Oracle mechanics

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

SQL> select in_parse,
  2         in_hard_parse,
  3         nvl2(sql_plan_hash_value, 'PHV exists', 'Hard parse') as plan_hash_value,
  4         nvl2(sql_exec_id, 'In Exec', 'Soft parse')                 as sql_exec_id,
  5         sql_plan_operation,
  6         sql_plan_options,
  7         count(*)
  8    from gv$active_session_history
  9   where event = 'db file scattered read'
 10   group by in_parse,
 11            in_hard_parse,
 12            nvl2(sql_plan_hash_value, 'PHV exists', 'Hard parse'),
 13            nvl2(sql_exec_id, 'In Exec', 'Soft parse'),
 14            sql_plan_operation,
 15            sql_plan_options
 16   order by count(*) desc
 17  /
 
IN_PARSE IN_HARD_PARSE PLAN_HASH_VALUE SQL_EXEC_ID SQL_PLAN_OPERATION  SQL_PLAN_OPTIONS                 COUNT(*)
-------- ------------- --------------- ----------- ------------------- ------------------------------ ----------
N        N             PHV exists      In Exec     TABLE ACCESS        FULL                                 3219
Y        Y             PHV exists      Soft parse                                                            874 -- (***)
N        N             PHV exists      In Exec     TABLE ACCESS        BY INDEX ROWID BATCHED                399
N        N             PHV exists      In Exec     TABLE ACCESS        BY LOCAL INDEX ROWID BATCHED           56
N        N             PHV exists      In Exec     MAT_VIEW ACCESS     FULL                                   52
N        N             PHV exists      In Exec     TABLE ACCESS        BY INDEX ROWID                         35
N        N             PHV exists      In Exec                                                                26
N        N             PHV exists      In Exec     INDEX               FAST FULL SCAN                         22
Y        Y             PHV exists      In Exec     INDEX               SAMPLE FAST FULL SCAN                   5
N        N             PHV exists      In Exec     INDEX               UNIQUE SCAN                             5
N        N             PHV exists      In Exec     INDEX               RANGE SCAN                              3
Y        Y             PHV exists      In Exec     TABLE ACCESS        SAMPLE                                  2
Y        Y             PHV exists      In Exec     TABLE ACCESS        FULL                                    1
Y        Y             PHV exists      Soft parse  TABLE ACCESS        BY LOCAL INDEX ROWID BATCHED            1
Y        Y             PHV exists      In Exec     MAT_VIEW ACCESS     SAMPLE                                  1
N        N             PHV exists      Soft parse                                                              1
Y        Y             PHV exists      In Exec     INDEX               FAST FULL SCAN                          1

(**) SAMPLE операции заслуживают отдельного внимания, в особенности когда встречаются не в запросах Adaptive Dynamic Sampling (ADS) типа SELECT /* DS_SVC */:

SQL> select sql_adaptive_plan_resolved,
  2         sql_plan_hash_value,
  3         sql_id,
  4         substr(sql_text, 1, 100) as SQL_TEXT,
  5         count(*)
  6    from gv$active_session_history
  7    left join gv$sqlarea
  8   using (inst_id, sql_id)
  9   where SQL_PLAN_OPTIONS like 'SAMPLE%'
 10     and nvl(sql_text, 'unknown') not like 'SELECT /* DS_SVC */%'
 11   group by sql_adaptive_plan_resolved,
 12            sql_plan_hash_value,
 13            sql_id,
 14            substr(sql_text, 1, 100)
 15  having count(*) > 5
 16   order by count(*) desc
 17  /
 
SQL_ADAPTIVE_PLAN_RESOLVED SQL_PLAN_HASH_VALUE SQL_ID        SQL_TEXT                                    COUNT(*)
-------------------------- ------------------- ------------- ----------------------------------------- ----------
                         1          1217131701 duwnj7x2rabfu SELECT invoice.id AS invoice_id, invoice.         14
                         1          4034620363 ctbk9nadpwpk8          SELECT sum(CASE            WHEN           6
                         1          1310796708 3hfrbuk9wnyw7 SELECT act_infernal.id AS act_infernal_id          6

— из чего можно предположить, что использование SAMPLE операций характерно для адаптивных планов выполнения (****) и по SQL_ID и PHV запроса, наиболее часто использующего SAMPLE операции при сформированном плане, внимательно промониторить статистику множественных выполнений SQL_ID=duwnj7x2rabfu и PHV=1217131701:

SQL> @ash_sqlmon2 duwnj7x2rabfu 1217131701
 
LAST_PLSQL   SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                                        QBLOCK_NAME    COST  ASH_ROWS WAIT_PROFILE
------------ ------------- --------------- ---- ----------------------------------------------------- ------------- ----- --------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Soft Parse   duwnj7x2rabfu      1217131701    0 sql_plan_hash_value > 0; sql_exec_id is null                                   1515 ON CPU(1034); cursor: pin S wait on X(250); library cache pin(84); library cache lock(69); db file scattered read(36); db file sequential read(29); gc buffer busy acquire(4); gc current block 2-way(3)
                                                                                                                                    ; gc cr block busy(2); library cache: mutex X(2); KJC: Wait for msg sends to complete(1); gc cr block 2-way(1)
 
Soft Parse   duwnj7x2rabfu      1217131701    2 sql_plan_hash_value > 0; sql_exec_id is null                                      9 ON CPU(9)
Soft Parse   duwnj7x2rabfu      1217131701    3 sql_plan_hash_value > 0; sql_exec_id is null                                     11 ON CPU(11)
Soft Parse   duwnj7x2rabfu      1217131701   10 sql_plan_hash_value > 0; sql_exec_id is null                                      1 gc buffer busy acquire(1)
Main Query   duwnj7x2rabfu      1217131701    0   SELECT STATEMENT                                                   3611         8 ON CPU(8)
                                              1     NESTED LOOPS                                      SEL$2C0D7645   3611           
                                              2       NESTED LOOPS                                                   3611           
                                              3         NESTED LOOPS                                                 3610           
                                              4           HASH JOIN ANTI                                             3607         4 ON CPU(4)
                                              5             TABLE ACCESS BY INDEX ROWID BATCHED       SEL$2C0D7645     23        33 ON CPU(14); db file parallel read(13); db file sequential read(5); gc cr block busy(1)
                                              6               INDEX RANGE SCAN                        SEL$2C0D7645      4        26 db file sequential read(22); gc cr block busy(3); ON CPU(1)
                                              7             VIEW                                      SEL$BF82FE11   3584           
                                              8               FILTER                                  SEL$BF82FE11                1 ON CPU(1)
                                              9                 HASH GROUP BY                                        3584        17 ON CPU(17)
                                             10                   NESTED LOOPS                                       3583           
                                             11                     NESTED LOOPS                                     3583           
                                             12                       NESTED LOOPS                                   1928           
>>>                                          13                         TABLE ACCESS FULL             SEL$BF82FE11    273        43 ON CPU(43)
                                             14                         TABLE ACCESS BY INDEX ROWID   SEL$BF82FE11      1        32 ON CPU(32)
                                             15                           INDEX UNIQUE SCAN           SEL$BF82FE11      0        53 ON CPU(53)
                                             16                       INDEX UNIQUE SCAN               SEL$BF82FE11      0        45 ON CPU(45)
                                             17                     TABLE ACCESS BY INDEX ROWID       SEL$BF82FE11      1        27 ON CPU(27)
                                             18           PARTITION LIST ALL                                            3           
                                             19             TABLE ACCESS BY LOCAL INDEX ROWID BATCHED SEL$2C0D7645      3         7 db file sequential read(4); db file parallel read(3)
                                             20               INDEX RANGE SCAN                        SEL$2C0D7645      0        20 db file sequential read(14); ON CPU(3); gc current block 2-way(1); gc cr block 2-way(1); gc cr block busy(1)
                                             21         INDEX UNIQUE SCAN                             SEL$2C0D7645      0         3 db file parallel read(1); ON CPU(1); db file sequential read(1)
                                             22       TABLE ACCESS BY INDEX ROWID                     SEL$2C0D7645      1         3 ON CPU(3)
Recurs.waits                             0    0 sql_id is null and plsql[_entry]_object_id is null                                8 ON CPU(7); log file sync(1)
SQL Summary                              0    0 ASH fixed 321 execs from 648 sessions                                          1858  ash rows were fixed from 28.11.2016 14:33:27 to 28.11.2016 18:47:06

SAMPLE операции в плане выполнения запроса естественно отсутствуют, они используют db file scattered read(36); db file sequential read(29);… на этапе Soft Parse до начала выполнения — первые 4 строки вывода

Кроме того, из мониторинга видно, что этап Soft Parse «занимает» 1515+9+11+1 из 1858 ash rows, приходящихся на этот запрос в ASH — т.е. налицо явная проблема с Soft Parse, что выражается в кол-ве дочерних курсоров:

SQL> select count(*) from gv$sql where sql_id = 'duwnj7x2rabfu';
 
  COUNT(*)
----------
       608

Простая сумма/группировка курсоров скриптом SHARED_CU12S_NOXML.SQL показывет, что основной причиной генерации курсоров (часто с повторяющимся PHV=1217131701) является Bind mismatch(33) (aka Bind Aware Cursor Sharing — один из классических примеров High Version Count):

SQL> @shared_cu12s_noxml duwnj7x2rabfu
 
INST_ID PLAN_HASH_VALUE OPTIMIZER_MODE LAST_ACTIVE_TIME    BIND_SENSE BIND_AWARE FEEDBACK_STATS OPT_STATS REOPT ADAPT ADAPT BIND_EQ_FAIL REASON#1                        FIX_CONTROL#1 CURSOR_COUNT  PHV_COUNT FPHV_COUNT   EXECS SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE
------- --------------- -------------- ------------------- ---------- ---------- -------------- --------- ----- ----- ----- ------------ ------------------------------- ------------- ------------ ---------- ---------- ------- ----------------- --------- ---------------- -----------
      2      1217131701 ALL_ROWS       28.11.2016 18:49:04 Y          Y          N              N         N           N     Y            Bind mismatch(33)                                      327          1          1    7973
      1      1665129135 ALL_ROWS       28.11.2016 18:49:05 Y          Y          N              N         N           N     Y            Bind mismatch(33)                                       82          1          1    8189
      2       868370966 ALL_ROWS       28.11.2016 18:49:04 Y          Y          N              N         N           N     Y            Bind mismatch(33)                                       78          1          1     781
      1      1217131701 ALL_ROWS       28.11.2016 18:39:42 Y          Y          N              N         N           N     Y            Bind mismatch(33)                                       65          1          1    1450
      1       868370966 ALL_ROWS       28.11.2016 17:31:29 Y          Y          N              N         N           N     Y            Bind mismatch(33)                                       10          1          1     140
      2      1217131701 ALL_ROWS       28.11.2016 17:16:02 Y          Y          Y              N         Y           N     Y            Bind mismatch(33)                                        8          1          1       8
      2      1217131701 ALL_ROWS       28.11.2016 17:15:28 Y          Y          Y              N         Y           N     Y            Optimizer mismatch(13)                                   7          1          1      12
      2      1217131701 ALL_ROWS       28.11.2016 18:13:29 N          Y          N              N         N           N     Y            Bind mismatch(33)                                        5          1          1      20
      1      1217131701 ALL_ROWS       28.11.2016 18:32:19 N          Y          N              N         N           N     Y            Bind mismatch(33)                                        3          1          1     180
      1      1217131701 ALL_ROWS       28.11.2016 14:38:12 Y          Y          Y              N         Y           N     Y            Optimizer mismatch(13)                                   3          1          1       5
      2      1526528793 ALL_ROWS       28.11.2016 18:49:04 Y          Y          N              N         N           N     Y            Bind mismatch(33)                                        2          1          1     890
      1      3635730922 ALL_ROWS       28.11.2016 18:49:05 Y          Y          N              N         N           N     Y            Bind mismatch(33)                                        2          1          1     394
      2      1217131701 ALL_ROWS       28.11.2016 11:03:50 N          N          Y              N         Y           N     N            Auto Reoptimization Mismatch(1)                          1          1          1  757095
      2      1217131701 ALL_ROWS       28.11.2016 17:06:14 N          Y          Y              N         Y           N     Y            Bind mismatch(33)                                        1          1          1     196
      2      1217131701 ALL_ROWS       28.11.2016 02:16:24 Y          N          Y              N         Y           N     N            Auto Reoptimization Mismatch(1)                          1          1          1       1
      2      1217131701 ALL_ROWS       28.11.2016 16:06:00 Y          Y          N              N         N           N     N            Bind mismatch(33)                                        1          1          1       4
      2      1217131701 ALL_ROWS       28.11.2016 16:05:59 Y          Y          Y              N         Y           N     N            Bind mismatch(33)                                        1          1          1   16331
      2      1148897207 ALL_ROWS       28.11.2016 17:34:12 Y          Y          N              N         N           N     N            Bind mismatch(35)                                        1          1          1     939
      2       937984306 ALL_ROWS       28.11.2016 16:55:46 Y          Y          Y              N         Y           N     Y            Optimizer mismatch(13)                                   1          1          1       1
      1      3635730922 ALL_ROWS       28.11.2016 18:37:14 N          Y          N              N         N           N     Y            Bind mismatch(33)                                        1          1          1    1424
      1      1665129135 ALL_ROWS       28.11.2016 18:27:04 N          Y          N              N         N           N     Y            Bind mismatch(33)                                        1          1          1     155
      1      1526528793 ALL_ROWS       28.11.2016 14:35:31 Y          Y          Y              N         Y           N     Y            Optimizer mismatch(13)                                   1          1          1       2
      1      1526528793 ALL_ROWS       28.11.2016 17:06:07 Y          N          Y              N         Y           N     N            Auto Reoptimization Mismatch(1)                          1          1          1       1
      1      1217131701 ALL_ROWS       28.11.2016 14:35:26 Y          Y          N              N         N           N     N            Bind mismatch(33)                                        1          1          1       4
      1      1217131701 ALL_ROWS       28.11.2016 14:35:25 Y          N          N              Y         N           N     N            Bind mismatch(25)                                        1          1          1       2
      1      1217131701 ALL_ROWS       28.11.2016 17:06:05 N          N          Y              N         Y           N     N            Auto Reoptimization Mismatch(1)                          1          1          1   13410
      1       937984306 ALL_ROWS       28.11.2016 14:38:16 Y          Y          Y              N         Y           N     Y            Optimizer mismatch(13)                                   1          1          1       5
      2      3625987712 ALL_ROWS       28.11.2016 16:55:55 Y          Y          Y              N         Y           N     Y            Optimizer mismatch(13)                                   1          1          1       3
      1       868370966 ALL_ROWS       28.11.2016 17:06:11 Y          N          Y              N         Y           N     N            Auto Reoptimization Mismatch(1)                          1          1          1       1
      1       868370966 ALL_ROWS       28.11.2016 17:09:36 Y          Y          N              N         N           N     N            Bind mismatch(33)                                        1          1          1      71
 
30 rows selected

— а вот адаптивные планы выполнения не используются вовсе — т.е. значение V$ACTIVE_SESSION_HISTORY.SQL_ADAPTIVE_PLAN_RESOLVED из предыдущего скрипта (****), к сожалению, не может быть надёжным источником)

Фраза ASH fixed 321 execs from 648 sessions из вывода SHARED_CU12_NOXML.SQL при некоторой кажущейся нелогичности просто говорит о больших затратах на Parsing:

SQL> select count(distinct session_id || ' ' || session_serial#) as distinct_sids,
  2         count(distinct sql_exec_id) as distinct_execs,
  3         count(*)
  4    from gv$active_session_history
  5   where sql_id = 'duwnj7x2rabfu'
  6  /
 
DISTINCT_SIDS DISTINCT_EXECS   COUNT(*)
------------- -------------- ----------
         1446            961       4188

— во время которого в ASH «отмечается» больше сессий, чем при собственно выполнениях

Таким образом, наблюдение за db file scattered read и SAMPLE операциями в не-ADS запросах может быть полезно в идентификации запросов с проблемами в части Soft Parse

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

Комментариев нет.

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 такие блоггеры, как: