Oracle mechanics

19.08.2014

Большой план выполнения и трассировка рекурсивных запросов с помощью ASH

Filed under: Active Session History,memory management,Oracle,SQL Tuning — Игорь Усольцев @ 00:18
Tags: ,

Спустя час с небольшим после начала выполнения запроса была получена следующая ошибка*:

ORA-04030: выход за пределы памяти процесса при попытке выделить 4120 байт (kksfr: qkesSet,frame segment)

Из автоматически сгенерированного трейса инциндента можно получить много информации, включая, например, раскладку использованных процессом 10GB из 15GB PGA (!):

=======================================
PRIVATE MEMORY SUMMARY FOR THIS PROCESS
---------------------------------------
******************************************************
PRIVATE HEAP SUMMARY DUMP
10 GB total:
    10 GB commented, 1103 KB permanent
  1452 KB free (0 KB in empty extents),
    6596 MB,   1 heap:    "kxs-heap-c     "            72 KB free held
    3646 MB,   2 heaps:   "callheap       "            1127 KB free held

*** 2014-07-17 13:12:32.395
------------------------------------------------------
Summary of subheaps at depth 1
10 GB total:
  4175 MB commented, 1527 MB permanent
  4508 MB free (0 KB in empty extents),
    3613 MB,   1 heap:    "TCHK^6f1a0bb0  "
    1177 MB, 187983 chunks:  "qkkele                    " 794 MB free held
    1039 MB, 298563 chunks:  "subHeap:qkspmTransformPred" 987 MB free held
     812 MB, 198230 chunks:  "allocator state           " 800 MB free held
     676 MB, 187983 chunks:  "qkkkey                    " 663 MB free held
...

, но для начала, зная указанный в том же трейсе SID.SERIAL сессии и SQL_ID:

*** SESSION ID:(972.11477) 2014-07-17 13:12:25.342
...
----- Current SQL Statement for this session (sql_id=fq5vmt1rjn2xh) -----
insert into t_base_source
        select s.*, sysdate as insert_dt
          from v_base_source s

, полезно посмотреть в ASH чем занималась пользовательская сессия до падения:

11.2.0.3.@ SQL> select max(sample_time) - min(sample_time) as duration,
  2         sql_plan_hash_value,
  3         sql_exec_id,
  4         session_state,
  5         in_parse,
  6         in_hard_parse,
  7         max(pga_allocated)
  8    from dba_hist_active_sess_history
  9   where sql_id = 'fq5vmt1rjn2xh'
 10     and snap_id between 56284 and 56288
 11     and (session_id, session_serial#) in ((972, 11477))
 12   group by sql_plan_hash_value,
 13            sql_exec_id,
 14            session_state,
 15            in_parse,
 16            in_hard_parse
 17  /

DURATION                SQL_PLAN_HASH_VALUE SQL_EXEC_ID SESSION_STATE IN_PARSE IN_HARD_PARSE MAX(PGA_ALLOCATED)
----------------------- ------------------- ----------- ------------- -------- ------------- ------------------
+000000000 01:03:55.358                   0             ON CPU        Y        Y                     4271251456

— по IN_PARSE=Y и отсутствующим на протяжении всего времени «выполнения» SQL_PLAN_HASH_VALUE, SQL_EXEC_ID можно предположить, что с разбором запроса что-то не так)

И действительно, простой EXPLAIN select-части этого DML (что не имеет решающего значения для фазы HARD_PARSE) зависает на десятки минут:

SQL> explain plan for
        select
         s.*, sysdate as insert_dt
          from v_base_source s
^C

, в то время как та же операция с отключёнными трансформациями (см.Медленный разбор SQL запроса (long parse time): вариант №2):

SQL> explain plan for
  2          select--+ NO_QUERY_TRANSFORMATION
  3           s.*, sysdate as insert_dt
  4            from v_base_source s
  5  /

Explained.

Elapsed: 00:00:43.20

— за 40+ секунд, но отрабатывает

«Трассировка» по ASH выполнения последнего запроса скриптом ash_sqlmon показывает, что план содержит 10,000+ строк:

SQL> @ash_sqlmon dna60d4851gb4

        ID PLAN_OPERATION                                        OBJECT_NAME                 PX WAIT_PROFILE
---------- ----------------------------------------------------- --------------------------- -- ---------------------------------------------------------------------------------
         0   SELECT STATEMENT                                                                22 cursor: pin S wait on X(2215); library cache lock(1690); ON CPU(530); ON CPU(45);
         1     SORT AGGREGATE                                                                 0 ON CPU(1);
         2       TEMP TABLE TRANSFORMATION
         3         LOAD AS SELECT
         4           VIEW                                        V_BASE_2014_DATES
         5             FAST DUAL
         6         LOAD AS SELECT
...
     10006                                  VIEW
     10007                                    TABLE ACCESS FULL  SYS_TEMP_0FD9FC94D_EF6849C

, что объясняет и длительное время разбора, и объём требуемой при честном (с включённым QUERY_TRANSFORMATION) разборе памяти и, как следствие, возникновение ORA-4030

Скрипт ash_sqlmon был выполнен с указанием только SQL_ID в качестве аргумента, что позволило увидеть ожидания, зафиксированные до определения значения SQL_EXEC_ID в ASH: в частности, большое количество ожиданий cursor: pin S wait on X/library cache lock на 0-м шаге параллельного (столбец PX=22) выполнения указывает, что уже после небыстрого разбора SQL весьма значительное время тратится на конкуренцию между PX-процессами в попытках получить эксклюзивную блокировку на уже сгенерированный курсор в Shared Pool:

SQL> select sql_exec_id,
  2         decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue') as EVENT,
  3         wait_class,
  4         in_parse,
  5         in_hard_parse,
  6         in_sql_execution,
  7         count(*),
  8         count(distinct session_id),
  9         min(sample_time),
 10         max(sample_time)
 11    from v$active_session_history
 12   where sql_id = 'dna60d4851gb4'
 13   group by sql_exec_id,
 14            decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue'),
 15            wait_class,
 16            in_parse,
 17            in_hard_parse,
 18            in_sql_execution
 19   order by count(*) desc
 20  /

SQL_EXEC_ID EVENT                       WAIT_CLASS    IN_PARSE IN_HARD_PARSE IN_SQL_EXECUTION   COUNT(*) COUNT(DISTINCTSESSION_ID) MIN(SAMPLE_TIME)           MAX(SAMPLE_TIME)
----------- --------------------------- ------------- -------- ------------- ---------------- ---------- ------------------------- -------------------------- -------------------------
   33554432 On CPU / runqueue                         N        N             Y                      3921                        26 29-JUL-14 02.50.19.431 PM  29-JUL-14 04.22.59.200 PM
            cursor: pin S wait on X     Concurrency   Y        N             N                      2215                        23 29-JUL-14 02.50.31.441 PM  29-JUL-14 04.22.49.190 PM
   33554432 direct path read            User I/O      N        N             Y                      1886                         1 29-JUL-14 02.51.46.511 PM  29-JUL-14 04.23.05.210 PM
            library cache lock          Concurrency   Y        N             N                      1739                        17 29-JUL-14 02.53.32.640 PM  29-JUL-14 04.22.49.190 PM
            On CPU / runqueue                         Y        Y             N                       587                         9 29-JUL-14 02.49.29.351 PM  29-JUL-14 04.22.49.190 PM
...

— до начала выполнения соответствующего блока плана, судя по NULL-евому SQL_EXEC_ID во время этих ожиданий

Блокерами для этих ожиданий являются другие PX-процессы, обозначенные как (P…), что также хорошо наблюдается в ASH:

SQL> @ash_wait_tree "sql_id = 'dna60d4851gb4' and sql_exec_id is null"

LVL INST_ID BLOCKING_TREE    EVENT                     WAITS_COUNT SESS_COUNT AVG_WA  EST_WAITS EST_AVG_LATENCY_MS
--- ------- ---------------- ------------------------- ----------- ---------- ------ ---------- ------------------
  1       2 (P...)           cursor: pin S wait on X          2215         23    991         38               1000 -- таймаут ~ 1 секунды
  1       2 (P...)           library cache lock               1739         17    967         34               1000 -- --//--
  1       2 (P...)           On CPU / runqueue                 560         17      0          0               1000
  1       2 (USER)           On CPU / runqueue                  50          1      0          0               1000
  2       2   (P...)         On CPU / runqueue                3954          8      0          0               1000 -- блокеры

Для физического сокращения объёма запроса часть логики была перенесена в PL/SQL, что естественно эффективно сокращает объём работы оптимизатора (грубо отражаемом в сокращении кол-ва строк плана выполнения), но при этом возникает необходимость мониторинга/трассировки по данным ASH не только основного, но и рекурсивных SQL запросов, вызываемых из PL/SQL пакетов/функций (не уверен что это делает SQL_MONITOR — поправьте, если ошибаюсь), а пользоваться SQL trace для длинных запросов достаточно долго и не всегда удобно/доступно

Написал соответствующий скрипт ash_sqlmon2 со следующим выводом на примере небыстрого настраиваемого запроса:

SQL> --           SQL_ID        [PLAN_HASH] [SQL_EXEC_ID]
SQL> @ash_sqlmon2 6hk8wvqum2yvc	452895455	  16777216

LAST_PLSQL        SQL_ID          ID PLAN_OPERATION                                        ASH_ROWS WAIT_PROFILE
----------------- ------------- ---- ----------------------------------------------------- -------- -----------------------------------
Main Query        6hk8wvqum2yvc    0   SELECT STATEMENT                                           4 ON CPU(4)
                                   1     SORT AGGREGATE
                                   2       VIEW
                                   3         UNION-ALL
                                   4           VIEW
                                   5             TEMP TABLE TRANSFORMATION
                                   6               LOAD AS SELECT                                12 ON CPU(11); log file sync(1)
                                   7                 HASH JOIN                                    6 ON CPU(6)
                                   8                   VIEW
                                   9                     HASH JOIN                                2 ON CPU(2)
                                  10                       INDEX FAST FULL SCAN
                                  11                       INDEX FAST FULL SCAN                   1 ON CPU(1)
                                  12                   NESTED LOOPS
                                  13                     NESTED LOOPS
                                  14                       NESTED LOOPS
                                  15                         HASH JOIN                            4 ON CPU(3); direct path read temp(1)
                                 ...
                                 871                           UNION-ALL
                                 872                             FILTER
                                 873                               INDEX RANGE SCAN
                                 874                                 VIEW
                                 875                                   TABLE ACCESS FULL
                                 876                             FILTER
                                 877                               INDEX RANGE SCAN
PKG01.FUNCTION02  47r8gu53mp3c4    0   SELECT STATEMENT                                          85 ON CPU(85)
                                   1     COUNT STOPKEY                                           10 ON CPU(10)
                                   2       FILTER                                                29 ON CPU(29)
                                   3         FILTER                                               4 ON CPU(4)
                                   4           NESTED LOOPS OUTER                                 1 ON CPU(1)
                                   5             NESTED LOOPS OUTER                               2 ON CPU(2)
                                   6               HASH JOIN OUTER                              227 ON CPU(227)
                                   7                 TABLE ACCESS BY INDEX ROWID                 44 ON CPU(43); buffer busy waits(1)
                                   8                   INDEX SKIP SCAN                         1858 ON CPU(1858)
                                   9                 TABLE ACCESS FULL                          215 ON CPU(215)
                                  10               INDEX RANGE SCAN                              23 ON CPU(23)
                                  11             TABLE ACCESS CLUSTER                            12 ON CPU(12)
                                  12               INDEX UNIQUE SCAN                             10 ON CPU(10)
                                  13         SORT AGGREGATE                                      36 ON CPU(36)
                                  14           FILTER                                             2 ON CPU(2)
                                  15             NESTED LOOPS OUTER                               3 ON CPU(3)
                                  16               NESTED LOOPS OUTER                             6 ON CPU(6)
                                  17                 HASH JOIN OUTER                           1867 ON CPU(1867)
                                  18                   TABLE ACCESS BY INDEX ROWID               30 ON CPU(30)
                                  19                     INDEX SKIP SCAN                       1113 ON CPU(1113)
                                  20                   TABLE ACCESS FULL                        293 ON CPU(293)
                                  21                 INDEX RANGE SCAN                            39 ON CPU(39)
                                  22               TABLE ACCESS CLUSTER                          21 ON CPU(21)
                                  23                 INDEX UNIQUE SCAN                           13 ON CPU(13)

LAST_PLSQL        SQL_ID          ID PLAN_OPERATION                                        ASH_ROWS WAIT_PROFILE
----------------- ------------- ---- ----------------------------------------------------- -------- -----------------------------------
PKG01.FUNCTION02  6dsmmx2w1yfmx    0   SELECT STATEMENT                                           2 ON CPU(2)
                                   1     FILTER
                                   2       NESTED LOOPS OUTER
                                   3         NESTED LOOPS OUTER
                                   4           HASH JOIN OUTER                                   20 ON CPU(20)
                                   5             TABLE ACCESS BY INDEX ROWID
                                   6               INDEX SKIP SCAN                                8 ON CPU(8)
                                   7             TABLE ACCESS FULL                                2 ON CPU(2)
                                   8           INDEX RANGE SCAN                                   1 ON CPU(1)
                                   9         TABLE ACCESS CLUSTER
                                  10           INDEX UNIQUE SCAN
PKG01.FUNCTION02  6kbunt1umh0bx    0   SELECT STATEMENT                                          74 ON CPU(74)
                                   1     SORT AGGREGATE                                          13 ON CPU(13)
                                   2       NESTED LOOPS OUTER                                     2 ON CPU(2)
                                   3         NESTED LOOPS OUTER                                   1 ON CPU(1)
                                   4           NESTED LOOPS OUTER
                                   5             NESTED LOOPS OUTER
                                   6               NESTED LOOPS                                   1 ON CPU(1)
                                   7                 NESTED LOOPS
                                   8                   NESTED LOOPS                               3 ON CPU(3)
                                   9                     NESTED LOOPS                             4 ON CPU(4)
                                  10                       TABLE ACCESS BY INDEX ROWID            9 ON CPU(9)
                                  11                         INDEX UNIQUE SCAN                   11 ON CPU(11)
                                  12                       INDEX FULL SCAN                       44 ON CPU(44)
                                  13                     INDEX RANGE SCAN                       674 ON CPU(674)
                                  14                   TABLE ACCESS CLUSTER                      39 ON CPU(39)
                                  15                     INDEX UNIQUE SCAN                       24 ON CPU(24)
                                  16                 TABLE ACCESS BY INDEX ROWID
                                  17                   INDEX RANGE SCAN
                                  18               INDEX RANGE SCAN
                                  19             TABLE ACCESS CLUSTER
                                  20               INDEX UNIQUE SCAN
                                  21           TABLE ACCESS CLUSTER
                                  22             INDEX UNIQUE SCAN
                                  23         INDEX RANGE SCAN
PL/SQL                             0 SCOTT PKG01.FUNCTION02                                      65 ON CPU(65)

— где в первом столбце для основного запроса с планом о 877 строках указано Main Query, для рекурсивных — название пакета и процедуры/функции (PKG01.FUNCTION02), а последней строкой выводятся ожидания «чистого» PL/SQL выполнения, не привязанного к конкретному SQL_ID

В первом столбце LAST_PLSQL кроме названия используемой PL/SQL конструкции отражаются недавние/текущие выполняемые операции значками >>> для наглядности (как в SQL_MONITOR), например, вывод скрипта для простого, выполняемого в н.м. запроса:

SQL> @ash_sqlmon2 40wnpfbaguvyx "" 16777248

LAST_PLSQL   SQL_ID         ID PLAN_OPERATION                                   PX   ASH_ROWS WAIT_PROFILE
------------ ------------- --- ------------------------------------------------ -- ---------- -------------------------------------------------------------------------------------------------------------------------------------------------------------------
Main Query   40wnpfbaguvyx   0   INSERT STATEMENT                                0          1 ON CPU(1)
                             1     LOAD TABLE CONVENTIONAL
                             2       PX COORDINATOR
                             3         PX SEND QC (RANDOM)
                             4           VIEW
>>>                          5             WINDOW SORT                           0       1336 direct path write temp(1146); ON CPU(190)
                             6               PX RECEIVE
                             7                 PX SEND HASH
                             8                   VIEW                            0          7 ON CPU(7)
>                            9                     UNION-ALL                     0         31 ON CPU(31)
                            10                       FILTER
                            11                         PX BLOCK ITERATOR
>>>                         12                           MAT_VIEW ACCESS FULL    0       2480 db file scattered read(2134); db file sequential read(145); db flash cache single block physical read(107); ON CPU(76); db flash cache multiblock physical read(18)
                            13                       FILTER
                            14                         PX BLOCK ITERATOR
                            15                           MAT_VIEW ACCESS FULL

— значком >>> указывает операции, наблюдавшиеся в течение последних 10 секунд, >> — в течение последних 30 секунд, а > — в течение последней минуты (интервалы настраиваются)

Или для параллельно выполненного запроса:

SQL> @ash_sqlmon2 40wnpfbaguvyx 1704676952 16777244

LAST_PLSQL  SQL_ID          ID PLAN_OPERATION                                                    PX   ASH_ROWS WAIT_PROFILE
----------- ------------- ---- ---------------------------------------------------------------- --- ---------- -----------------------------------------------------------------------------------------------------------------------
Main Query  40wnpfbaguvyx    0   INSERT STATEMENT                                                 0          1 ON CPU(1)
                             1     LOAD TABLE CONVENTIONAL                                        0         60 ON CPU(58); log file switch (private strand flush incomplete)(1); log file switch completion(1)
                             2       PX COORDINATOR                                               0          2 ON CPU(2)
                             3         PX SEND QC (RANDOM)
                             4           VIEW                                                    11         90 ON CPU(90)
                             5             WINDOW SORT                                           11      18486 direct path read temp(11108); direct path write temp(6182); ON CPU(1196)
                             6               PX RECEIVE                                          10         60 ON CPU(60)
                             7                 PX SEND HASH                                      11        101 ON CPU(100); PX qref latch(1)
                             8                   VIEW                                             8         17 ON CPU(17)
                             9                     UNION-ALL                                      9         30 ON CPU(30)
                            10                       FILTER
                            11                         PX PARTITION RANGE ALL
                            12                           MAT_VIEW ACCESS BY LOCAL INDEX ROWID    11       7507 db file sequential read(4882); db flash cache single block physical read(2326); ON CPU(173); read by other session(126)
                            13                             BITMAP CONVERSION TO ROWIDS            2          4 ON CPU(4)
                            14                               BITMAP INDEX FULL SCAN               6         14 db file sequential read(13); db flash cache single block physical read(1)
                            15                       FILTER
                            16                         PX BLOCK ITERATOR
                            17                           MAT_VIEW ACCESS FULL

— в столбце PX указывается кол-во параллельных процессов, оставивших в ASH следы при выполнении операции. Естественно обращать внимание на этот столбец только при мониторинге одиночного выполнения запроса, т.е. с указанием конкретного SQL_EXEC_ID при запуске скрипта

Дополнения:

*) При беглом поиске по Металинку можно видеть относительно несвежий баг, в котором при попытке построить план выполнения для extremely complex view получают ошибку:

ORA-4031: unable to allocate 4104 bytes of shared memory ("shared pool","explain plan for ...","kksfr: qkesSet","frame segment")

— и хотя в отличие от описанного случая ORA-4031 сигнализирует не о проблемах с местом в PGA (ORA-4030), а о трудностях при размещении крупного курсора в SGA, интересно полное совпадение аргументов при аналогичных проблемах — Bug 7443808 : VIEW THAT WORKS ON V92080 RAISES ORA-04031 ON 10.2.0.4 UNLESS SGA IN INCREASED

**) Вывод explain plan рассчитан разработчиками на 4-х значный номер операции ID, что косвенно указывает на нежелательность extremely длинных планов, как мне кажется). На примере первого попавшегося длинного плана:

SQL> SELECT * FROM TABLE(dbms_xplan.display_awr('8mpjnk85dbnu4'));

---------------------------------------------------------------------------------
| Id  | Operation                | Name | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------
|   0 | INSERT STATEMENT         |      |       |       | 20004 (100)|          |
|   1 |  LOAD TABLE CONVENTIONAL |      |       |       |            |          |
|   2 |   VIEW                   |      | 10000 |    27M| 20004   (1)| 00:03:41 |
|   3 |    UNION-ALL             |      |       |       |            |          |
...
|9997 |     FAST DUAL            |      |     1 |       |     2   (0)| 00:00:01 |
|9998 |     FAST DUAL            |      |     1 |       |     2   (0)| 00:00:01 |
|9999 |     FAST DUAL            |      |     1 |       |     2   (0)| 00:00:01 |
|1000 |     FAST DUAL            |      |     1 |       |     2   (0)| 00:00:01 |
|1000 |     FAST DUAL            |      |     1 |       |     2   (0)| 00:00:01 |
|1000 |     FAST DUAL            |      |     1 |       |     2   (0)| 00:00:01 |
|1000 |     FAST DUAL            |      |     1 |       |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------------

***) По ходу оптимизации описанного проблемного запроса, при многократных, порою длительных выполнениях было вполне естественно иногда получать:

ORA-08103: object no longer exists

— с прерыванием выполнения по ошибке — просто запрос использует переодически перезаполняемые ( через TRUNCATE/INSERT) таблички, т.е. это была нормальная, ожидаемая в случае затянувшегося выполнения ошибка

Однако в некоторых случаях выполнение запроса не прерывалось (что хорошо), а alert.log при этом сигнализировал о проблемах следующими 2-мя типами сообщений:

ORA-12842: Cursor invalidated during parallel execution
...
ORA-14403: cursor invalidation detected after getting DML partition lock

с незаметным на уровне клиента рестартом выполнения запроса(!):

SQL> select sql_id, sql_exec_id, min(sample_time), max(sample_time)
  2    from dba_hist_active_sess_history
  3   where snap_id = 56743
  4     and (session_id, session_serial#) in ((516, 43817))
  5   group by sql_id, sql_exec_id
  6   order by min(sample_time)
  7  /

SQL_ID        SQL_EXEC_ID MIN(SAMPLE_TIME)            MAX(SAMPLE_TIME)
------------- ----------- --------------------------- -------------------------
gcuk9sx3xtny3    16777216 05-AUG-14 01.26.15.781 PM   05-AUG-14 01.45.17.470 PM -- прервано по ORA-14403
gcuk9sx3xtny3    16777217 05-AUG-14 01.45.47.510 PM   05-AUG-14 01.59.58.837 PM -- автоматически запущено через 40 мс

Появление последнего сообщения ORA-14403 было достаточно неожиданным, поскольку никаких операций (и объектов) с партициями в запросе не присутствовало:

SQL> select * from dba_hist_sql_plan where sql_id = 'gcuk9sx3xtny3' and operation like '%PARTITION%';

no rows selected

Системы в появлении той или иной ошибки пока не заметил

1 комментарий »

  1. Спасибо за скрипт и инетерсный ресерч!

    комментарий от Евгений — 12.09.2014 @ 21:08 | Ответить


RSS feed for comments on this post. TrackBack URI

Добавить комментарий

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход / Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход / Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход / Изменить )

Google+ photo

Для комментария используется ваша учётная запись Google+. Выход / Изменить )

Connecting to %s

Блог на WordPress.com.

%d такие блоггеры, как: