ASH CPU trace

Запрос со ср.временем выполнения 3,7 мс периодически выполняется 22 секунды (*):

12.1.0.2@ SQL> @shared_cu12 4g02xxnvrk8j9 0

 EXECS LAST_LOAD_TIME      ROWS_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE CBO_MODE   OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  CF  REOPT REOPT_HINTS V$SQL.Adapt XML.Adapt SPD_Valid SPD_Used  DS_LEVEL DOP NOT_SHARED_BY  REASON                          SQL_PLAN_BASELINE SQL_PATCH              OUTLINE_CATEGORY SQL_PROFILE IS_OBSOLETE
------ ------------------- ------------- ------------ ------------ ------------- -------------- ------------ ------------- --------------- -------------------- ---------- -------------- ----- ---------- ---------- ---------- --- ----- ----------- ----------- --------- --------- --------- -------- --- -------------- ------------------------------- ----------------- ---------------------- ---------------- ----------- -----------
  9050 2019-06-05/10:12:04             1         3665         1076           291              0         2241            32       763530515            311975141 ALL_ROWS              429    53 N          N          Y              N                 N                                                      PURGED_CURSOR  Bind UACs mismatch(0)                             NO_ADAPT_4g02xxnvrk8j9                              N
                                                                                                                                                                                                                                                                                                                             Auto Reoptimization Mismatch(1)                                                                                            

1 rows selected
...

--------------------------------------------------------------
ASH TOP5 SQL_ID=4g02xxnvrk8j9 Executions by Elapsed Time
--------------------------------------------------------------

INST_ID SQL_ID        SQL_PLAN_HASH_VALUE SQL_FULL_PLAN_HASH_VALUE SQL_EXEC_ID   ASH_ROWS DURATIONs                 MIN_SAMPLE_TIME    MAX_SAMPLE_TIME
------- ------------- ------------------- ------------------------ ----------- ---------- ------------------------- ------------------ -----------------
      1 4g02xxnvrk8j9           763530515                311975141                     30 +000000000 12:26:39.998   04.06.19 20:54:28  05.06.19 09:21:08
      1 4g02xxnvrk8j9           763530515                311975141    18306846         22 +000000000 00:00:21.070   05.06.19 03:02:22  05.06.19 03:02:43 -- *
      1 4g02xxnvrk8j9                   0                311975141                      5 +000000000 08:07:56.983   05.06.19 00:03:32  05.06.19 08:11:29
      1 4g02xxnvrk8j9           763530515                311975141    18404662          3 +000000000 00:00:02.010   05.06.19 04:40:39  05.06.19 04:40:41
      1 4g02xxnvrk8j9           763530515                311975141    18506517          3 +000000000 00:00:02.010   05.06.19 06:36:50  05.06.19 06:36:52
...

— учитывая, что SQL Patch NO_ADAPT_4g02xxnvrk8j9 применяется как стандартное средство отключения адаптивных фич на уровне запроса и не способен повлиять на отдельное выполнение, остаётся вопрос, что же замедлило выполнение запроса SQL_EXEC_ID = 18306846 ?

TM — Library Cache Deadlock на этапе Parsing и Optimizer Finding

При выполнении ALTER TABLE DROP CONSTRAINT случился TM — library cache deadlock распределённого (RAC) вида, отразившийся в ASH следующим образом:

12.1.0.2@ SQL> @ash_sql_wait_tree "(session_id,session_serial#) in ((4460,16750)) and sample_time > trunc(sysdate,'hh24')" 0
 
LVL INST_ID BLOCKING_TREE   EVENT                 WAIT_CLASS   DATA_OBJECT_P1RAW  IN_PARSE SQL_CHILD_NUMBER WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT BLOCK_SID  MIN_STIME                  MAX_STIME                  SQL_ID        SQL_PLAN_HASH_VALUE SQL_EXEC_ID SQL_TEXT
--- ------- --------------- --------------------- ------------ ------------------ -------- ---------------- ----------- ----------- ------ ---------- ---------- -------------------------- -------------------------- ------------- ------------------- ----------- ----------------------------------------------------------------------------------------------------
  1       1 (USER)          enq: TM - contention  Application  MY.PAYMENT_Z.      N                       0          11           1      0          1 GLOBAL i#  26-JUN-17 04.06.39.431 PM  26-JUN-17 04.06.49.451 PM  7kpzqksdg4wu8                   0           1 
  1       1 (USER)          enq: TM - contention  Application  MY.PAYMENT_Z.      N                       0           2           1      0          1 VALID i#2  26-JUN-17 04.06.50.451 PM  26-JUN-17 04.06.51.451 PM  7kpzqksdg4wu8                   0           1 
  1       1 (USER)          library cache pin     Concurrency  000000261138EA48   Y                       0           1           0      1          1 GLOBAL i#  26-JUN-17 04.06.37.431 PM  26-JUN-17 04.06.37.431 PM  73f85gf8qvb34          2024994732           0 select NULL AS TABLE_CAT, OWNER AS TABLE_SCHEM, 'NO' as IS_AUTOINCREMENT, cc.COMMENTS AS REMARKS,OWN
  1       1 (USER)          library cache pin     Concurrency  000000274A98AEE0   Y                       0           1           0      0          1 GLOBAL i#  26-JUN-17 04.06.36.431 PM  26-JUN-17 04.06.36.431 PM  6196bjzyj6dv7          2050374072           0 SELECT null as TABLE_CAT, a.OWNER as TABLE_SCHEM, a.TABLE_NAME as TABLE_NAME, a.TEMPORARY as TEMPORA
  2       2   (USER)        library cache lock    Concurrency  00000027E6E364A8   Y                      -1           4           0   6807          1 VALID i#1  26-JUN-17 04.06.50.574 PM  26-JUN-17 04.06.51.574 PM  0w12fswfwtrdv          3054558131           0 UPDATE payment_z SET ...
  2       2   (USER)        library cache lock    Concurrency  00000027E6E364A8   Y                      -1           1           0      0          1 GLOBAL i#  26-JUN-17 04.06.49.564 PM  26-JUN-17 04.06.49.564 PM  0w12fswfwtrdv          3054558131           0 UPDATE payment_z SET ...
  3       1     (USER)      enq: TM - contention  Application  MY.PAYMENT_Z.      N                       0           4           1      0          1 VALID i#2  26-JUN-17 04.06.50.451 PM  26-JUN-17 04.06.51.451 PM  7kpzqksdg4wu8                   0           1 
  3       1     (USER)      enq: TM - contention  Application  MY.PAYMENT_Z.      N                       0           2           1      0          1 GLOBAL i#  26-JUN-17 04.06.49.451 PM  26-JUN-17 04.06.49.451 PM  7kpzqksdg4wu8                   0           1 
  4       2       (USER)    library cache lock    Concurrency  00000027E6E364A8   Y                      -1           4           0   6807          1 VALID i#1  26-JUN-17 04.06.50.574 PM  26-JUN-17 04.06.51.574 PM  0w12fswfwtrdv          3054558131           0 UPDATE payment_z SET ...
  4       2       (USER)    library cache lock    Concurrency  00000027E6E364A8   Y                      -1           2           0      0          1 GLOBAL i#  26-JUN-17 04.06.49.564 PM  26-JUN-17 04.06.49.564 PM  0w12fswfwtrdv          3054558131           0 UPDATE payment_z SET ...
  5       1         (USER)  enq: TM - contention  Application  MY.PAYMENT_Z.      N                       0           2           1      0          1 GLOBAL i#  26-JUN-17 04.06.49.451 PM  26-JUN-17 04.06.49.451 PM  7kpzqksdg4wu8                   0           1 
 
11 rows selected

где:

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

После 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:

Синтаксическая ошибка в запросе, приводящая к бесконечному parsing-у

Наблюдали с коллегами запрос, часами не выходящий из фазы Hard Parse:

SQL> @ash_sqlmon2 81vm5p8sr91zr
 
LAST_PLSQL                SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                    COST ASH_ROWS WAIT_PROFILE
------------------------- ------------- --------------- ---- --------------------------------- ---- -------- --------------------------------------------------------------------
Hard Parse                81vm5p8sr91zr               0    0 sql_plan_hash_value = 0                   32514 ON CPU(32514)
Main Query w/o saved plan 81vm5p8sr91zr               0                                                      
SQL Summary                                           0    0 ASH fixed 0 execs from 1 sessions         32514  ash rows were fixed from 01.06.2016 03:26:52 to 01.06.2016 12:29:00

— и так не сформировавшему за 8 часов плана выполнения!

Оказалось, что поведение запроса поменялось после незначительных изменений в тексте запроса (что ожидаемо и неудивительно), запрос «плотно висел» ON CPU, oradebug dump errorstack 3 стабильно указывал:

Join Predicate Push-Down, допускающий картезианское произведение

SQL трейс уровня 8+ («с ожиданиями») выявил медленный запрос, частовыполняемый при элементарных бизнес операциях:

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.17       0.18          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1     47.84      50.76        180     270283         34           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3     48.02      50.94        180     270283         34           0

Статистика выполнения из того же трейса показывает, что при построении плана запроса не срабатывает ожидаемая операция Join Predicate Push-Down (JPPD), приводя к TABLE ACCESS FULL по хорошо индексированной таблице T2:

Library cache lock deadlock

Недавно наблюдали в некотором роде замечательный интересный описанием процесса параллельного разбора Bug 14356507 — Deadlock between partition maintenance and parallel query operations [ID 14356507.8]:

Library cache lock deadlock can occur between parallel query and a DDL (Eg: partition maintenance operations) on the same objects.
When a parallel query is hard parsed, first QC hard parses the query and then all the slaves. When a partition maintenance operation (DDL) comes in between the hard parses of QC and Slaves.
…
The QC holds the library cache lock in shared mode when the query is being hard parsed by the slaves. The exclusive mode requests from the session performing the DDL operation will block the parallel query getting the same lock in shared mode. At the same time, the exclusive request will not be served as the QC is holding the lock in shared mode and waiting for the slaves to complete the parsing.

This fix removes this limitation and the  slaves should get the lock in EXPRESS mode when the QC holds the same lock.

— сложный разбор (hard parse) параллельного запроса состоит из нескоскольких частей: вначале Query Coordinator, затем разбор выполняют PX Slaves. Deadlock возникает, когда на реально нагруженной OLTP системе сторонний запрос попытается получить блокировку Lock между этими событиями

В нашем случае deadlock проявлялся при одновременном параллельном DDL на партиции индекса:

alter index t1_idx rebuild partition SYS_P18934 online parallel 5

и случайно попавшим DML удаления строк из той же таблицы

delete from t1 where dt between :dt1 and :dt2

Влияние параметра optimizer_index_cost_adj на оптимизатор версии 11.1

Традиционно начинаю с неэффективно работающего запроса:

11.1.0.7.@ SQL> Select
Distinct ("EXP")
  From "SOME_PARTITIONED_TABLE"
 Where "PATH__LVL" < 10
   And ("PATH" In (Chr(9) || 'R' || Chr(9),
                   Chr(9) || 'R' || Chr(9) || 'v11' || Chr(9)))
/

------------------------------------------------------------+-----------------------------------+---------------+
| Id  | Operation              | Name                       | Rows  | Bytes | Cost  | Time      | Pstart| Pstop |
------------------------------------------------------------+-----------------------------------+---------------+
| 0   | SELECT STATEMENT       |                            |       |       |  6723 |           |       |       |
| 1   |  RESULT CACHE          | 9qyjpzzpk6tyu0r3wpj8un8pbd |       |       |       |           |       |       |
| 2   |   HASH UNIQUE          |                            |    21 |  1155 |  6723 |  00:02:35 |       |       |
| 3   |    PARTITION RANGE ALL |                            |    59 |  3245 |  6722 |  00:02:35 | 1     | 5     |
| 4   |     INDEX FULL SCAN    | MULTIFIELDS_INDX           |    59 |  3245 |  6722 |  00:02:35 | 1     | 5     |
------------------------------------------------------------+-----------------------------------+---------------+
Predicate Information:
----------------------
4 - access("PATH__LVL"<10)
4 - filter((INTERNAL_FUNCTION("PATH") AND "PATH__LVL"<10))

Строка RESULT CACHE в плане значения не имеет и определяется установленным в системе параметром:

SQL> show parameter result_cache_mode

NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
result_cache_mode                    string      FORCE

Показательно, хотя и не очень важно в этом случае, что тот же запрос с одним условием выполняется по тому же «плохому» плану:

Операции LOAD TABLE CONVENTIONAL / LOAD AS SELECT: direct-path и другие способы вставки в 11.2

Попробовал оценить насколько|почему хорошо работает direct-path insert (операция LOAD AS SELECT в плане выполнения), а поскольку нет смысла описывать эту операцию отдельно от традиционной (conventional) вставки — сделал несколько простых тестов различных вариантов вставки массивов строк в DML типа INSERT…SELECT…:

• традиционная непараллельная вставка — conventional insert
• традиционная параллельная — conventional parallel insert
• прямая непараллельная — direct-path serial insert
• прямая непараллельная вставка с параллельным выполнением запроса — direct-path serial insert + parallel SELECT execution
• прямая параллельная — direct-path parallel insert

Попутно выяснилась интересная техническая особенность выполнения прямых вставок, судя по которой разработчики Oracle намеренно отдали предпочтение последнему варианту — direct-path parallel insert, и проверил влияние параметра _direct_path_insert_features на режим прямой вставки в версии 11.2

Тестовая схема:

Сложный запрос, использование Baseline и Bind-Aware Cursor Sharing

Планы выполнения любых запросов, например, сложно-составных «матрёшечного» типа, т.е. содержащих множественно-вложенные view, могут и часто должны существенно меняться после обновления 10.2 -> 11.2, что естественно и «баян». Интересно попробовать определить причины и исключить изменения в худшую сторону

Далее приводится интересный на мой взгляд случай диагностики таких изменений без использования трассировки оптимизатора, пример модификации плана проблемного  с использованием рекомендуемой Oracle технологии SQL Plan Management (SPM), и решение практических проблем, возникающих при использовании SPM baseline под влиянием другой передовой технологии Oracle 11g Bind-Aware Cursor Sharing (BASC)

Итак, «всё пропало — запрос медленно работает» => запрос, раньше выполнявшийся за секунды, запущен час назад и продолжает выполняеться :(

Поскольку запрос всё ещё выполняется, можно включить обычный SQL trace:

Параметр CHILD NUMBER в процедуре DBMS_SQLDIAG.DUMP_TRACE

В Oracle 11.2 появилась возможность получать трейс CBO без необходимости заново выполнять запрос с установленным 10053 event при условии наличия соответствующего курсора в shared pool — факт извесный и добротно описанный в блоге Greg Rahn. Creating Optimizer Trace Files, где указывается, что при вызове процедуры DBMS_SQLDIAG.DUMP_TRACE Oracle выполняет новый разбор нового курсора с добавленным к оригинальному запросу комментарием типа /* SQL Analyze(12,0) */ и, следовательно, с  новым SQL_ID:

При этом совершенно непонятна роль параметра CHILD NUMBER:

--     dump_trace - Dump Optimizer Trace
--
-- DESCRIPTION:
--     This procedure dumps the optimizer or compiler trace for a give SQL
--     statement identified by a SQL ID and an optional child number.
--
-- PARAMETERS:
--     p_sql_id          (IN)  -  identifier of the statement in the cursor
--                                cache
--     p_child_number    (IN)  -  child number

И, соответственно, не вполне ясно можно ли с помощью процедуры сгенерировать трейсы с различными планами выполнения, которые могут присутствовать в shared pool для разных дочерних курсоров?