Oracle mechanics

09.03.2018

log file sequential read

Filed under: Active Session History,AWR,Oracle — Игорь Усольцев @ 12:14
Tags:

Всплеск нагрузки на IO подсистему:

сопровождался, по нашим с Дмитрием Якубеней наблюдениям, дисбалансом в отчёте AWR — совершенно незначительные цифры пользовательской нагрузки (*):

Load Profile                    Per Second   Per Transaction  Per Exec  Per Call
~~~~~~~~~~~~~~~            ---------------   --------------- --------- ---------
             DB Time(s):              73.0               0.0      0.01      0.00
              DB CPU(s):              10.5               0.0      0.00      0.00
      Background CPU(s):               0.9               0.0      0.00      0.00
      Redo size (bytes):       6,734,104.6           3,153.3
  Logical read (blocks):       2,698,366.4           1,263.6
          Block changes:          41,001.2              19.2
 Physical read (blocks):          11,301.7               5.3
Physical write (blocks):           3,319.9               1.6
       Read IO requests:           4,417.3               2.1
      Write IO requests:             721.0               0.3
           Read IO (MB):              44.2               0.0                      -- *
          Write IO (MB):              13.0               0.0                      -- *
...

никак не коррелировали с Total (MB) нагрузкой AWR IO Profile (**): (more…)

Реклама

24.08.2016

12c, адаптивный LGWR: ожидания log file sync и target log write size

Из более-менее традиционной картинки ожиданий log file sync:

12.1.0.2@ SQL> @ash_wait_tree "event = 'log file sync' and inst_id = 1"
 
LVL INST_ID BLOCKING_TREE     WAIT_CLASS  EVENT                         WAITS_COUNT SESS_COUNT AVG_WA
--- ------- ----------------- ----------- ----------------------------- ----------- ---------- ------
  1       1 (FOREGROUND)      Commit      log file sync                       10992       6879    130 -- польз.процессы
  1       1 (J...)            Commit      log file sync                          13         13      0 -- и Job-ы ожидают LGWR
  2       1   (LGWR)          Other       LGWR any worker group                4675          1    190 -- , висящий, восновном,
  2       1   (LGWR)          Other       target log write size                3880          1      4 -- на этих 3-х ожиданиях
  2       1   (LGWR)          Other       LGWR all worker groups                691          1    265 -- и облокируемый
  2       1   (LGWR)                      On CPU / runqueue                      61          1      0
...
  3       1     (LG..)        System I/O  log file parallel write              5064          1    217 -- LGWR-worker-ами (LG..)
  3       1     (LG..)        Other       LGWR worker group ordering            129          1    223
  3       1     (FOREGROUND)              On CPU / runqueue                       2          1      0
  4       1       (LG..)      System I/O  log file parallel write               129          1    347

— можно предположить, что для уменьшения log file sync достаточно сократить время/кол-во блокирующих ожиданий LGWR any worker group/LGWR all worker groups и target log write size, распределённых в этом случае приблизительно поровну

И если первая группа ожиданий очевидно «упирается» в кол-во/скорость работы LGWR-worker-ов, обозначенных как (LG..): (more…)

06.05.2016

Кластерные ожидания внутри одного инстанса RAC и количество LMS-процессов

Filed under: Active Session History,Oracle,RAC,SGA — Игорь Усольцев @ 12:48
Tags:

Краткосрочный всплеск ожиданий типа Cluster:

Top 5 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ --------
gc buffer busy acquire           1,157,219      59.3K      51.23   42.6 Cluster  
gc cr grant 2-way                2,838,562      24.8K       8.72   17.8 Cluster 
gc current grant busy              382,881      11.5K      30.05    8.3 Cluster 
DB CPU                                          10.6K               7.6         
gc current grant 2-way             141,095     8458.2      59.95    6.1 Cluster

был вызван сформирован* в бОльшей части двумя SQL с типом команд SELECT (без FOR UPDATE), выполнявшимися на 2-м инстансе: (more…)

27.04.2016

Скрипт для асинхронных блокировок/блокеров из [истории] ASH

Filed under: Active Session History,Диагностика системы (instance),Oracle,Scripts — Игорь Усольцев @ 16:04
Tags: ,

Для ответа на вопрос типа «Кто кого блокировал 21 апреля в период между 03:00 и 03:30 ?» можно посмотреть в соответствующий AWR и определить:

1) собственно факт вероятного наличия проблемы:

              Snap Id      Snap Time      Sessions Curs/Sess Instances
            --------- ------------------- -------- --------- ---------
Begin Snap:    325799 21-Apr-16 03:00:50       672       2.9         2
  End Snap:    325800 21-Apr-16 03:30:06       613       2.9         2
   Elapsed:               29.28 (mins)
   DB Time:            2,157.33 (mins) -- тут

2) проблемное ENQUEUE ожидание:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ --------
DB CPU                                          50.8K              39.2         
enq: TX - row lock contention          907      26.2K   28850.95   20.2 Applicat -- вероятно, тут
latch: cache buffers chains      1,063,115     7905.4       7.44    6.1 Concurre
enq: UL - contention                38,803     4835.8     124.63    3.7 Applicat
db file sequential read          2,587,974     2225.1       0.86    1.7 User I/O

3) страждущий запрос(ы) по наименованию ожидания: (more…)

18.04.2016

ASH_SQLMON12S.SQL: блочный мониторинг длинных планов выполнения

Filed under: Active Session History,Oracle,Scripts — Игорь Усольцев @ 23:48
Tags: ,

Причины длительного выполнения запросов с обширным планом бывает непросто увидеть/определить как в связи объёмом, так и в связи с ненадёжностью / периодическим прерыванием функционирования DBMS_SQLTUNE.REPORT_SQL_MONITOR сообщениями типа:

Global Information
------------------------------
 Status                                 :  DONE (ERROR)

— для всё ещё продолжающих выполняться запросов

Идея скрипта проста — сгруппировать ASH строки по имени Query Block определённого плана выполнения, например так: (more…)

04.04.2016

12c: 2 x FULL_PLAN_HASH_VALUE для одного плана выполнения / PLAN_HASH_VALUE и скрипт ASH_SQLMON12.SQL

Filed under: Active Session History,Oracle — Игорь Усольцев @ 23:34
Tags: ,

При интенсивном выполнении (конец месяца, подсчёт итогов,..) запроса типа SELECT наблюдал картину:

SQL> @shared_cu12_noxml 35hnzb2q6xrkc
 
  EXECS LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CLU_PER_EXEC CURSOR_STATUS PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS REOPT REOPT_HINTS ADAPT SPD_Valid SPD_Used  DS_LEVEL BIND_EQ_FAILURE REASON#1          SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE IS_OBSOLETE
------- -------------------- ------------------- ------------ ------------ ------------- -------------- ------------ ------------ ------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----- --------- --------- -------- --------------- ----------------- ----------------- --------- ---------------- ----------- -----------
   1015 2016-04-01/10:10:12  01.04.2016 10:16:44       470644        74060         24316            462       303651       107095 VALID               434062702           3150513221         194928     3 Y          Y          N          N                  N                 Y     5         2         2        Y               Bind mismatch(33)                                                          N
    384 2016-04-01/10:16:47  01.04.2016 10:19:05       482506        66008         20388            401       309564       118371 VALID               434062702           3150513221          11350     5 Y          N          N          N                  N                 Y     5         2         2        N               Bind mismatch(25)                                                          N
    481 2016-04-01/10:19:05  01.04.2016 10:23:02       440066        44582         13717            295       214687       188648 VALID               434062702           3150513221             72     6 Y          Y          N          N                  N                 Y     5         2         2        N               Bind mismatch(33)                                                          N
    538 2016-04-01/10:22:06  01.04.2016 10:27:07       622140        69344         24159            422       305390       258859 VALID               434062702           3150513221         315650     7 Y          Y          N          N                  N                 Y     6         1         2        Y               Bind mismatch(33)                                                          N
   2426 2016-04-01/10:27:04  01.04.2016 10:35:02       324502        49090         15276            266       209320        73840 VALID               434062702           3150513221            345     8 Y          Y          N          N                  N                 Y     5         2         2        Y               Bind mismatch(33)                                                          N
  18369 2016-04-01/10:34:44  01.04.2016 10:54:36       212043        24282          6648            142       121101        69878 VALID               434062702           3150513221          11390     2 Y          Y          N          N                  N                 Y     5         2         2        Y               Bind mismatch(33)                                                          N
  11009 2016-04-01/10:54:26  01.04.2016 11:00:00       103472        16452          4501             87        70872        18074 VALID               434062702           3150513221          42424     9 Y          Y          N          N                  N                 Y     5         2         2        Y               Bind mismatch(33)                                                          N
  15439 2016-04-01/10:59:58  01.04.2016 11:07:58       157499        16593          4644             78       127386        14786 VALID               434062702           1196564125         385981    10 Y          Y          N          N                  N                       5         2         2        Y               Bind mismatch(33)                                                          N
 148072 2016-04-01/11:07:57  01.04.2016 12:01:52        53123         9772          2884             50        41752         2766 VALID               434062702           3150513221           8859    11 Y          Y          Y          N                  N                 Y     5         2         2        Y                                                                                          N
 
10 rows selected
 
--------------------------------------------------------------
SQL_ID=35hnzb2q6xrkc Shared Pool statistics by PLAN_HASH_VALUE
--------------------------------------------------------------
 
  EXECS ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC CLU_PER_EXEC FETCH_PER_EXEC ROWS_PER_EXEC PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE AVG_CBO_COST     CHILDS BIND_SENSE BIND_AWARE REOPT ADAPT SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE
------- ------------ ------------ ------------- -------------- ------------ ------------- ------------ -------------- ------------- --------------- -------------------- ------------ ---------- ---------- ---------- ----- ----- ----------------- --------- ---------------- -----------
  15439       157499        16593          4644             78       127386            16        14786              1             1       434062702           1196564125       385981          1 Y          Y          N     N                                                  
 182294        81718        12905          3774             69        56993            32        13470              1             1       434062702           3150513221        73127          8 Y          Y          N     Y

— любопытную прежде всего тем, что по причине BIND_AWARE / Bind mismatch(33) Oracle периодически перегенерировал один и тот же курсор с неизменным рез-татом в виде плана PLAN_HASH_VALUE = 434062702, но с использованием разных FULL_PLAN_HASH_VALUE — см. CHILD 9-11, например (more…)

15.07.2015

12c: Сравнение планов выполнения и выявление соответствий в паре PLAN_HASH_VALUE >-< FULL_PLAN_HASH_VALUE

Filed under: Active Session History,CBO,Oracle — Игорь Усольцев @ 00:44
Tags: ,

Для одного из запросов внезапно сработал Statistics Feedback, что в V$SQL отразилось следующим образом:

EXEC LOAD_TIME   OPENING LAST_ACTIVE_TIME ELA_PER_EXEC PLAN_HASH_VALUE    COST CHILD BIND_SENSITIVE BIND_AWARE SHARABLE FEEDBACK_STATISTIC    ROWS PARSE_CALLS
---- ----------- ------- ---------------- ------------ --------------- ------- ----- -------------- ---------- -------- ------------------ ------- -----------
   1 29.06 12:07       0      29.06 12:45   1912450710      2108937779  396162     0 N              N          N        Y                  1106472           1
   1 29.06 15:17       1      30.06 15:07  85765923098      3773907172 5597267     1 N              N          Y        N                        0           1

— т.е. 29.06 в 12:45 запрос выполнялся с нормальным планом 2108937779, а при следующем выполнении в 30.06 в 15:07 под действием FEEDBACK_STATISTIC=Y с новым планом 3773907172 наблюдается затянувшееся выполнение, что в принципе не является чем-то необычным, любопытно что в AWR таблице DBA_HIST_SQLSTAT оба выполнения записаны с одним планом 2108937779, что, мягко говоря, не способствует правильной диагностике (первая строка SNAP_ID=87604 соотв.1-му, последующие — 2-му выполнению):

12.1.0.2.@ SQL> @dba_hist_sqlstat "sql_id = '38dyq2ab12nju' and snap_id >= 87605"
 
INST BEGIN_SNAP_ID BEGIN_SNAP_TIME    EXECS ROWS_PROCESSED SQL_ID              PLAN       COST PARSE_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC DISK_READS_PER_EXEC READ_MB_PER_EXEC READS_PER_EXEC WRITES_MB_PER_EXEC WRITES_PER_EXEC DIRECT_WRITES_PER_EXEC ROWS_PER_EXEC FETCHES_PER_EXEC IOWAITS_PER_EXEC CLWAITS_PER_EXEC_US
---- ------------- --------------- -------- -------------- ------------- ---------- ---------- -------------- ------------ ------------ ------------- ------------------- ---------------- -------------- ------------------ --------------- ---------------------- ------------- ---------------- ---------------- -------------------
   2         87604 29.06 12:30            0              0 38dyq2ab12nju 2108937779     396162              0    553193496    117012000      10507935             1083047             8461         954997                910            7763                 116445       1106472           158068        462927031             3887793
   2         87609 29.06 15:00            0              0 38dyq2ab12nju 2108937779     396162              0            0            0             0                   0                0              0                  0               0                      0             0                0                0                   0
   2         87610 29.06 15:30            0              0 38dyq2ab12nju 2108937779     396162              0            0            0             0                   0                0              0                  0               0                      0             0                0                0                   0
...
   2         87655 30.06 14:00            0              0 38dyq2ab12nju 2108937779     396162              0            0            0             0                   0                0              0                  0               0                      0             0                0                0                   0
   2         87656 30.06 14:30            0              0 38dyq2ab12nju 2108937779     396162              0            0            0             0                   0                0              0                  0               0                      0             0                0                0                   0

(more…)

25.03.2015

12c: ASH.SQL_PLAN_HASH_VALUE и адаптивные эффекты

Filed under: Active Session History,Oracle — Игорь Усольцев @ 00:15
Tags: ,

В Active Session History (ASH) версии 11g содержалось относительно небольшое кол-во записей с PLAN_HASH_VALUE = 0 о запросах в стадии выполнения (IN_SQL_EXECUTION = ‘Y’):

11.2@ SQL> select decode(sql_plan_hash_value, 0, '0', '>0') as sql_plan_hash_value,
  2         case when sql_plan_line_id is null then 'NULL' else '>= 0' end as SQL_PLAN_LINE_ID,
  3        count(*)
  4   from v$active_session_history
  5  where IN_PARSE         = 'N'
  6    and IN_HARD_PARSE    = 'N'
  7    and IN_SQL_EXECUTION = 'Y'
  8  group by decode(sql_plan_hash_value, 0, '0', '>0'),
  9           case when sql_plan_line_id is null then 'NULL' else '>= 0' end
 10  order by count(*)
 11  /
 
SQL_PLAN_HASH_VALUE SQL_PLAN_LINE_ID   COUNT(*)
------------------- ---------------- ----------
>0                  NULL                   1120
0                   NULL                   1903 -- немного, SQL_PLAN_LINE_ID is NULL - "служебные записи"
>0                  >= 0                 141186

, и, в основном, это ожидаемые куски PL/SQL кода или какие-то специальные случаи типа ожиданий по db link, etc…

В Oracle 12c кол-во таких записей может внезапно/периодически увеличиться:

12.1@ SQL> select decode(sql_plan_hash_value, 0, '0', '>0') as sql_plan_hash_value,
  2         count(*)
  3    from v$active_session_history
  4   where IN_PARSE         = 'N'
  5     and IN_HARD_PARSE    = 'N'
  6     and IN_SQL_EXECUTION = 'Y'
  7   group by decode(sql_plan_hash_value, 0, '0', '>0')
  8   order by count(*)
  9  /
 
SQL_PLAN_HASH_VALUE   COUNT(*)
------------------- ----------
0                        33215
>0                      163247

(more…)

10.10.2014

Планы выполнения запросов на RO Standby

Filed under: Active Session History,Oracle — Игорь Усольцев @ 02:42
Tags: ,

Хорошо известно, что перераспределение запросной активности на Standby db, открытую в режиме READ ONLY — чистое благо, по крайней мере покуда «всё идёт по плану»

Диагностика возникающих при этом проблем типа периодического замедления выполнения конкретных запросов, на ro-standby имеет особенности и может быть любопытна

Например, была получена достоверная информация, что запрос, посылаемый через dblink на standby:

SQL> @inst
 
INST_ID INSTANCE_NAME HOST_NAME VERSION    PLATFORM_NAME    DATABASE_STATUS DATABASE_ROLE    STATUS   OPEN_MODE
------- ------------- --------- ---------- ---------------- --------------- ---------------- -------- ---------
1*      myinst        myhost    11.2.0.3.0 Linux x86 64-bit ACTIVE          PHYSICAL STANDBY OPEN     READ ONLY

периодически вместо секунд выполняется десятки минут, что очевидно заслуживает пристального внимания (more…)

19.09.2014

ASH-трассировка PL/SQL

Filed under: Active Session History,Диагностика системы (instance),Oracle — Игорь Усольцев @ 00:13
Tags: ,

К примеру, в AWR-отчёте бд ERP-системы на первом месте видно продолжающееся/неоконченное выполнение процедуры, лидирующей по использованному DB Time с большим отрывом от ближайшего преследователя — 72% против 18%:

SQL ordered by Elapsed Time           DB/Inst: OEBS/OEBS1  Snaps: 73249-73250

        Elapsed                  Elapsed Time
        Time (s)    Executions  per Exec (s)  %Total   %CPU    %IO    SQL Id
---------------- -------------- ------------- ------ ------ ------ -------------
        36,572.3              0           N/A   72.5   45.7   41.0 5t39uchjqpyfm
Module: XLAACCUP
BEGIN xla_accounting_pkg.unit_processor_batch(:errbuf,:rc,:A0,:A1,:A2,:A3,:A4,:A

         9,246.2             15        616.41   18.3   29.4   65.5 0vjcg5zp30z2x

Для быстрой оценки такого рода проблем написал скрипт ash_plsqlmon_hist.sql, который по истории ASH вначале показывает суммарный вклад запросов и PL/SQL блоков по частоте попадания в историю ASH (ASH_ROWS), кол-во зафиксированных неповторяющихся выполнений (EXECS), затем — мин/мах время наблюдения(с соответствующими названиями столбцов) и общий профиль ожиданий (WAIT_PROFILE) примерно так:
(more…)

Следующая страница →

Создайте бесплатный сайт или блог на WordPress.com.