Oracle mechanics

30.11.2016

12c: Log File Sync, параметр _DB_MTTR_ADVICE и опасности увеличения кол-ва LGWR-workers

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

После switchover-а на аналогичное железо в разы выросло время ожидания log file sync:

12.1.0.2@ SQL> @ash_wait_tree "event = 'log file sync'" 0 "where inst_id = 1"
 
LVL BLOCKING_TREE         EVENT                         WAIT_CLASS WAITS_COUNT SESS_COUNT AVG_WA  EST_WAITS EST_AVG_LATENCY_MS
--- --------------------- ----------------------------- ---------- ----------- ---------- ------ ---------- ------------------
  1 (FOREGROUND)          log file sync                 Commit           37104       2019    395    1992400                 19 -- ну не 19 мс, конечно, но точно > 10 мс - недопустимо долго
  1 (J...)                log file sync                 Commit              37         35      0          0               1000
  2   (LGWR)              LGWR any worker group         Other            31107          1    518     134101                231 -- осн.блокер для log file sync
  2   (LGWR)              target log write size         Other             4053          1      7    1898397                  2
  2   (LGWR)              LGWR all worker groups        Other             1137          1    187      59184                 19
  2   (LGWR)              On CPU / runqueue                                 54          1      0          0               1000
  2   (LGWR)              enq: CF - contention          Other               19          1    316         60                317
  2   (LGWR)              control file sequential read  System I/O          12          1      1      10607                  1
  2   (LGWR)              control file parallel write   System I/O           7          1      1       6261                  1
  3     (LG..)            LGWR wait for redo copy       Other            25103          1    606      73038                340 -- осн.блокер для LGWR any worker group *
  3     (LG..)            log file parallel write       System I/O        6290          1    209     200335                 31
  3     (LG..)            LGWR worker group ordering    Other              406          1    223       2500                162
  4       (FOREGROUND)    On CPU / runqueue                              21073        354      0          0               1000
  4       (J...)          On CPU / runqueue                               3908         21      0          0               1000
  4       (LG..)          log file parallel write       System I/O         230          1    228       1014                227
  4       (LG..)          LGWR wait for redo copy       Other              176          1    198       1391                127
  4       (Q...)          On CPU / runqueue                                122          1      0          0               1000
  5         (FOREGROUND)  On CPU / runqueue                                176          4      0          0               1000

— при этом в качестве важного промежуточного блокера в вышеприведённой цепочке по частоте и продолжительности неожиданно проявилось LGWR wait for redo copy (*), что было отчётливо заметно в цепочке ожиданий, начиная с LGWR any worker group: (more…)

Реклама

29.11.2016

Наблюдение за Db File Scattered Read, SAMPLE операции планов выполнения и запросы с большим удельным Soft Parse

Разбираясь с использованием ожидания/активности db file scattered read при разных операциях планов выполнения, можно видеть:

12.1.0.2@ SQL> select sql_plan_operation, sql_plan_options, count(*)
  2    from gv$active_session_history
  3   where event = 'db file scattered read'
  4   group by sql_plan_operation, sql_plan_options
  5   order by count(*) desc
  6  /
 
SQL_PLAN_OPERATION  SQL_PLAN_OPTIONS                 COUNT(*)
------------------- ------------------------------ ----------
TABLE ACCESS        FULL                                 3220 -- ожидаемо большая доля FTS
                                                          901 -- scattered чтения без SQL_PLAN_OPERATION (*)
TABLE ACCESS        BY INDEX ROWID BATCHED                399 -- scattered read при INDEX BATCHED операциях
TABLE ACCESS        BY LOCAL INDEX ROWID BATCHED           57 -- // --
MAT_VIEW ACCESS     FULL                                   52
TABLE ACCESS        BY INDEX ROWID                         35 -- скорее всего также выполняется в режиме BATCHED
INDEX               FAST FULL SCAN                         23 -- ожидаемое многоблочное чтение
INDEX               SAMPLE FAST FULL SCAN                   5 -- SAMPLE операции (**)
INDEX               UNIQUE SCAN                             5
INDEX               RANGE SCAN                              3
TABLE ACCESS        SAMPLE                                  2 -- // -- (**)
MAT_VIEW ACCESS     SAMPLE                                  1 -- // -- (**)

(*) Scattered чтения без SQL_PLAN_OPERATION большей частью относятся к фазе Soft parse (***), определяемой здесь как промежуток, когда PLAN_HASH_VALUE уже сформирован (PHV exists), но выполнение запроса ещё не началось (SQL_EXEC_ID is null): (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…)

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…)

25.03.2016

12c: Automatic Dynamic Statistics в присутствии SPM Baseline

Восстановление default значения optimizer_dynamic_sampling = 2, последовавшее после обновления на 12c выявило краткосрочную проблему:

Top 5 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ -----------
DB CPU                                          53.2K              55.8         
db file sequential read          1,998,398      15.5K       7.74   16.2 User I/O
cursor: pin S wait on X             29,094      11.5K     396.15   12.1 Concurrency -- тут
db file parallel read               72,823       3284      45.09    3.4 User I/O
db file scattered read             164,408       2134      12.98    2.2 User I/O

локализованную одним запросом:

12.1.0.2.@ SQL> @ash_sql_wait_tree "event = 'cursor: pin S wait on X'"
 
LVL BLOCKING_TREE  EVENT                    WAIT_CLASS   WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT BLOCK_SID  MIN_STIME                   MAX_STIME                   SQL_ID        SQL_PLAN_HASH_VALUE SQL_TEXT
--- -------------- ------------------------ ------------ ----------- ----------- ------ ---------- ---------- --------------------------- --------------------------- ------------- ------------------- -----------------------------------------------
  1 (USER)         cursor: pin S wait on X  Concurrency         9872           0    991        214 VALID i#1  03-MAR-16 03.00.13.029 PM   03-MAR-16 03.01.36.228 PM   5rrd8z9nt7t2j          1613548637 select 1 from dual where exists (select 1  from
  1 (USER)         cursor: pin S wait on X  Concurrency          474           0    986         17 VALID i#1  03-MAR-16 03.00.16.029 PM   03-MAR-16 03.01.31.218 PM   5rrd8z9nt7t2j           633295841 select 1 from dual where exists (select 1  from
...
  1 (USER)         cursor: pin S wait on X  Concurrency          135           0    988          4 VALID i#1  03-MAR-16 03.00.19.029 PM   03-MAR-16 03.01.29.218 PM   5rrd8z9nt7t2j          2447725225 select 1 from dual where exists (select 1  from
  1 (USER)         cursor: pin S wait on X  Concurrency          104           0    981          3 VALID i#1  03-MAR-16 03.00.14.029 PM   03-MAR-16 03.01.29.218 PM   5rrd8z9nt7t2j          3045292599 select 1 from dual where exists (select 1  from
...

с одним действующим PHV=1613548637 (и несколькими переходными «фантомными» не оставившими следов планами) в течение непродолжительной фазы hard [re-]parse последовавшей сразу после модификации параметра OPTIMIZER_DYNAMIC_SAMPLING. По природе ожидания конкуренция (WAIT_CLASS=»Concurrency») естественно наблюдалась между сессиями, ожидавшими окончания parse/разбора того же самого курсора (more…)

14.01.2016

12c: старая проблема High version count и параметр PARALLEL_INSTANCE_GROUP

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

С коллегой Сергеем Щукиным смотрели на проблему избыточной генерации трейсов типа Huge Trace Files Created Containing «—— Cursor Obsoletion Dump sql_id=%s ——» (Doc ID 1955319.1) — где в соотвествии с рекомендациями, установка параметра _kks_obsolete_dump_threshold = 0 помогла отключить/избавиться от трейсов

Но проблему High version count это не решило:

12.1.0.2@ SQL> select inst_id, sql_id, count(*)
  2    from gv$sql
  3   group by inst_id, sql_id
  4   having count(*) > 1000
  5   order by count(*) desc
  6  /
 
INST_ID SQL_ID          COUNT(*)
------- ------------- ----------
      1 7u1z273sfty8z      93057
      1 5cbp4s5jq04xg       7169
      2 gyvrs5a6pm7h7       1225

Топовые запросы имели схожую статистику курсоров: (more…)

13.01.2016

Oracle 12c Adaptive Soft Parse overhead

Логичным развитием темы предыдущей заметки будет оценка вклада типа Oracle 12c Adaptive Soft Parse overhead на систему в целом через подсчёт доли в общем DB Time (через кол-во ASH rows) «адаптивных» запросов в момент между генерацией плана и началом выполнения запроса (sql_plan_hash_value > 0 AND sql_exec_id is null)

Как-то так раскадка DB Time выглядит на примере системы (в бОльшей части OLTP типа) для sql типа SELECT:

SQL> select plan_hash_value,
  2         sql_exec_id,
  3         adaptive_plan,
  4         sum(ash_rows),
  5         listagg(session_state || '(' || ash_rows || ')', ';') within group(order by ash_rows desc) as DB_TIME_WASTE,
  6         to_char(RATIO_TO_REPORT(sum(ash_rows)) OVER() * 100,'990.99')                              as "PerCent"
  7    from (select decode(nvl(sql_plan_hash_value, -1), -1, 'not yet', 0, '0', 'exists')              as PLAN_HASH_VALUE,
  8                 nvl2(sql_exec_id, 'exists', 'not yet')                                             as SQL_EXEC_ID,
  9                 session_state,
 10                 sql_adaptive_plan_resolved                                                         as ADAPTIVE_PLAN,
 11                 count(*)                                                                           as ASH_ROWS
 12            from gv$active_session_history
 13           where sql_opname = 'SELECT'
 14           group by decode(nvl(sql_plan_hash_value, -1), -1, 'not yet', 0, '0', 'exists'),
 15                    nvl2(sql_exec_id, 'exists', 'not yet'),
 16                    session_state,
 17                    sql_adaptive_plan_resolved)
 18   group by plan_hash_value, sql_exec_id, adaptive_plan
 19   order by sum(ash_rows) desc
 20  /
 
PLAN_HASH_VALUE SQL_EXEC_ID ADAPTIVE_PLAN SUM(ASH_ROWS) DB_TIME_WASTE                 PerCent
--------------- ----------- ------------- ------------- ----------------------------- -------
exists          exists                  1        210576 ON CPU(173241);WAITING(37335)   85.23 -- фаза обычного выполнения, планы отмечены как адаптивные в 85% случаев
exists          not yet                 1         30274 WAITING(20739);ON CPU(9535)     12.25 -- (*) 12c Adaptive Soft Parse, то что подлежит оценке
0               exists                  0          2279 ON CPU(1254);WAITING(1025)       0.92 -- (**) строки нормального выполнения в ASH с PLAN_HASH_VALUE=0, особый случай
exists          not yet                 0          2161 WAITING(1939);ON CPU(222)        0.87 -- Soft Parse НЕадаптивных планов
0               not yet                 0          1415 ON CPU(986);WAITING(429)         0.57 -- Hard Parse НЕадаптивный
0               not yet                 1           366 ON CPU(283);WAITING(83)          0.15 -- Hard Parse адаптивный
0               exists                  1             1 ON CPU(1)                        0.00 -- (**) выполнение в ASH с PLAN_HASH_VALUE=0, особый случай
exists          exists                  0             1 ON CPU(1)                        0.00 -- фаза обычного выполнения НЕадаптивных планов

(more…)

08.11.2015

12c: hardcoded подсказка _fix_control и новая проблема High Version Count

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

Как бы продолжая тему багов/особенностей 12c, появился запрос с заметной долей Shared Pool Concurrency ожиданий в процессе выполнения с ASH мониторингом вида:

SQL> @ash_sqlmon2 45u45mpanbatr
 
LAST_PLSQL SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                                 PX   ASH_ROWS WAIT_PROFILE
---------- ------------- --------------- ---- ------------------------------------------------- ---------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Hard Parse 45u45mpanbatr               0    0 sql_plan_hash_value = 0                       385      48755 cursor: pin S wait on X(47474); library cache lock(653); ON CPU(318); cursor: mutex X(121); cursor: mutex S(120); kksfbc child completion(52); cursor: pin S(8); library cache: mutex X(7);
Soft Parse 45u45mpanbatr      2447725225    0 sql_plan_hash_value > 0; sql_exec_id is null  514      37420 cursor: pin S wait on X(36708); library cache lock(454); cursor: mutex X(88); cursor: mutex S(77); ON CPU(44); kksfbc child completion(32); library cache: mutex X(11); SQL*Net message from dblink(3);
Soft Parse 45u45mpanbatr      2907472699    0 sql_plan_hash_value > 0; sql_exec_id is null  601     113412 cursor: pin S wait on X(107536); ON CPU(3566); library cache lock(1607); cursor: mutex X(286); cursor: mutex S(255); kksfbc child completion(88); PX Deq: Signal ACK EXT(26); library cache: mutex X(24);
...

— на этапах Hard/Soft Parse, доля которых для запроса составляла ~ 2/3 общего времени выполнения: (more…)

30.09.2015

Об использовании Parallel Statement Queuing в процессе Complete Non-Atomic mview refresh

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

При выполнении DBMS_MVIEW.REFRESH(…, ‘C’, ATOMIC_REFRESH=>FALSE) можно видеть ожидание pipe get, что ожидаемо и описано в Complete Refresh Of Materialized View Hangs On Pipe Get (Doc ID 1193294.1), где, среди прочих «смелых» решений|solutions (удалять индексы перед обновлением, запретить job-ы на системном уровне, не использовать NONATOMIC REFRESH), рекомендуют использовать dbms_jobs вместо dbms_scheduler с помощью специального замысловатого event:)

$ oerr ora 10992
10992, 00000, "event to enable dbms_job instead of dbms_scheduler"
// *Cause:
// *Action:   enables dbms_job instead of dbms_scheduler
// *Comment:  set this event only under the supervision of Oracle Development
// LEVEL        ACTION
//---------------------------------------------------------------------------
//  0x0001      enable dbms_job instead of dbms_scheduler for MV refresh

Т.е. штатно DBMS_MVIEW.REFRESH после собственно обновления (TRUNCATE+INSERT /*+ APPEND*/) запускает одновременно несколько DBMS_SCHEDULER заданий с процедурами типа: (more…)

17.05.2015

12c: конкуренция при компиляции курсоров

Filed under: Диагностика системы (instance),Oracle,shared pool — Игорь Усольцев @ 20:12
Tags: ,

После обновления бд до версии 12.1.0.2 столкнулись с проблемой блокировок курсоров, сопровождавшей замедлившийся процесс разбора (parse) некоторых запросов, и материально выраженой большим кол-вом/долей ожиданий cursor: pin S wait on X и library cache lock в ASH/AWR:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ --------
cursor: pin S wait on X                941      60,9K   64747.53   50.3 Concurrency
DB CPU                                          42,5K              35.1         
library cache lock                  20,478     6681,6     326.28    5.5 Concurrency

Наблюдение в режиме реального времени позволило достаточно быстро и пОлно диагностировать и разрешить проблему, начиная с топа запросов по ожиданиям: (more…)

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

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