Oracle mechanics

21.06.2015

Dynamic sampling (level=AUTO) в параллельных запросах с фиксированным планом выполнения

Filed under: Oracle,Plan Management — Игорь Усольцев @ 22:19
Tags: ,

При выполнении параллельного запроса наблюдалась неприятная картина ожиданий:

12.1.0.2.@ SQL> @ash_sqlmon2 8d49sjc17xwuc
 
LAST_PLSQL  SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                                                                   PX ASH_ROWS WAIT_PROFILE
----------- ------------- --------------- ---- -------------------------------------------------------------------------------- -- -------- ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Soft Parse  8d49sjc17xwuc       162625646    0 sql_plan_hash_value > 0; sql_exec_id is null                                     39    26689 library cache lock(19424); cursor: pin S wait on X(7223); kksfbc child completion(29); ON CPU(9); db file sequential read(3); db file scattered read(1)
Main Query  8d49sjc17xwuc       162625646    0   SELECT STATEMENT                                                                           
                                             1     PX COORDINATOR                                                                           
...
                                            38                                                           TABLE ACCESS FULL      19      339 db file scattered read(194); ON CPU(80); db file sequential read(64); latch: gcs resource hash(1)
                                            39                                                     TABLE ACCESS BY INDEX ROWID  19       96 ON CPU(90); db file sequential read(6)
                                            40                                                       INDEX RANGE SCAN           19      158 ON CPU(129); db file sequential read(29)
                                            41                                                   INDEX RANGE SCAN               19      834 db file sequential read(737); ON CPU(97)
                                            42                                                 TABLE ACCESS BY INDEX ROWID      19     5278 db file sequential read(4076); gc cr grant 2-way(597); ON CPU(378); gcs drm freeze in enter server mode(219); gc current block 2-way(5); latch: gcs resource hash(1); gc cr request(1); read by other session(1)
...
SQL Summary                             0    0 ASH fixed 1 execs from 41 sessions                                                     34181  ash rows were fixed from 29.05.2015 12:13:09 to 29.05.2015 12:30:48

— где наряду с «нормальными» ожиданиями по ходу выполнения (ID 38-42, например), преобладают типичные для стадии Soft Parse (sql_plan_hash_value > 0 AND sql_exec_id is null) ожидания library cache lock и cursor: pin S wait on X, вероятно, связанные с параллельным выполнением судя по кол-ву ожидающих PX-процессов (столбец PX)

Что можно проверить во-время (выполнения запроса) запущенным скриптом:

SQL> @kgllockpin
 
HANDLER          KGLLKTYPE  NAMESP          KGLOBTYD  KGLNAOWN  KGLNAOBJ          MODE_HELD  MODE_REQ   SECS_IN_WAIT EVENT                   SECONDS_IN_WAIT SID    SERIAL  SADDR            PROGRAM                 SQL_ID
---------------- ---------- --------------- --------- --------- ----------------- ---------- ---------- ------------ ----------------------- --------------- ------ ------- ---------------- ----------------------- -------------
000000289A1A6CD0 Lock       SQL AREA BUILD  CURSOR    $BUILD$   8691388b027ef34c  None       Share      25           library cache lock                   25 2953   15047   0000002C42402248 oracle@oebs.net (P00D)  8d49sjc17xwuc
...
000000289A1A6CD0 Lock       SQL AREA BUILD  CURSOR    $BUILD$   8691388b027ef34c  None       Share      25           library cache lock                   25 209    53713   0000002C220FCA50 oracle@oebs.net (P00G)  8d49sjc17xwuc
000000289A1A6CD0 Lock       SQL AREA BUILD  CURSOR    $BUILD$   8691388b027ef34c  Exclusive  None       0            db file sequential read               0 1611   3012    0000002BA22717A8 oracle@oebs.net (P004)  8d49sjc17xwuc

39 rows selected.

— из чего видно как PX-slave-ы числом около 40 достаточно долго ждут одного из своих товарищей на завершении SQL AREA BUILD, при этом блокирующий товарищ зачем-то занимается db file sequential read, что не всегда характерно для фазы Soft Parse)

Структура/зависимости блокировок для library cache lock хорошо видна из ASH:

SQL> @ash_sql_wait_tree "sql_id = '8d49sjc17xwuc' and event in ('library cache lock')"
 
LVL INST_ID BLOCKING_TREE  EVENT                   WAITS_COUNT EXECS_COUNT AVG_WAIT_TIME_MS EST_AVG_LATENCY_MS DATA_OBJECT                                   BLOCK_SID      SQL_ID        SQL_PLAN_LINE_ID SQL_PLAN_OPERATION
--- ------- -------------- ----------------------- ----------- ----------- ---------------- ------------------ --------------------------------------------- -------------- ------------- ---------------- ------------------
  1       1 (P...)         library cache lock            18820           0             1002              34852 ..                                            VALID i#1      8d49sjc17xwuc                0 SELECT STATEMENT  
  1       1 (P...)         library cache lock              604           0             1004              35529 SYS.WRH$_SQLSTAT.WRH$_SQLSTA_2598577434_85858 VALID i#1      8d49sjc17xwuc                0 SELECT STATEMENT  
  2       1   (P...)       On CPU / runqueue             36858           0                0           36858000 ..                                            NOT IN WAIT i# 8d49sjc17xwuc                                    
  2       1   (P...)       db file sequential read       16843           0               13                  1 ..                                            NO HOLDER i#   8d49sjc17xwuc                                    
  2       1   (P...)       db file scattered read         1804           0                3                  1 ..                                            NO HOLDER i#   8d49sjc17xwuc                                    
  2       1   (P...)       gc cr grant 2-way               837           0                0                  0 ..                                            UNKNOWN i#     8d49sjc17xwuc                                    
...

— откуда видно, что основными блокерами являются PX-процессы (P…), занимающиеся, предположительно, чтением буферных блоков (On CPU / runqueue), db file read и прочими чтениями, что может быть характерно, например, для Dynamic Sampling(*):

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('8d49sjc17xwuc', format => '+note'))

...

Note
-----
   - dynamic statistics used: dynamic sampling (level=AUTO) -- *
   - Degree of Parallelism is 20 because of hint
   - SQL patch "TASK-1711" used for this statement
   - SQL plan baseline SQL_PLAN_dnf8f9n4w4sx86f3363e5 used for this statement

— несколько неожиданным при этом выглядит факт применения dynamic sampling при живой (в смысле актуальной и применяемой) паре SQL patch и SQL plan baseline (!), последний из которых по замыслу должен по возможности точно фиксировать план выполнения и, в случае успешного применения, казалось бы, исключает необходимость всяких динамических модификаций

Другим любопытным наблюдением является сам факт генерации и последующего использования в одном параллельном выполнении по фиксированному SQL plan baseline 2-х дочерних курсоров (child cursors), хорошо заметное по отличию V$SQL.LAST_LOAD_TIME, например:

SQL> @shared_cu12 8d49sjc17xwuc
 
INST EXECS USERS_OPENING FIRST_LOAD_TIME      LAST_LOAD_TIME       PARSE_USER LAST_ACTIVE_TIME    ELA_PER_EXEC PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE OPTIMIZER_COST CHILD SHAREABLE  REOPT REOPT_HINTS ADAPT USE_FEEDBACK_STATS SQL_PLAN_DIRECTIVES REASON1              SQL_PLAN_BASELINE              SQL_PATCH
---- ----- ------------- -------------------- -------------------- ---------- ------------------- ------------ --------------- -------------------- -------------- ----- ---------- ----- ----------- ----- ------------------ ------------------- -------------------- ------------------------------ ---------
   1     0             0 2015-05-29/12:13:08  2015-05-29/12:24:50  APPS       29.05.2015 12:30:49  27627990042       162625646           1865638885         112014     1 Y          N               0       N                  valid:; used:                            SQL_PLAN_dnf8f9n4w4sx86f3363e5 TASK-1711
   1     1             0 2015-05-29/12:13:08  2015-05-29/12:13:30  APPS       29.05.2015 12:30:49     26644988       162625646           1865638885         112014     0 Y          Y               5       Y                  valid:; used:       Bind mismatch(17)  | SQL_PLAN_dnf8f9n4w4sx86f3363e5 TASK-1711

+ создание и использование реоптимизационных хинтов для плана, который нет возможности изменить, выглядит немного лишним:

SQL> select child_number, hint_text from V$SQL_REOPTIMIZATION_HINTS WHERE sql_id = '8d49sjc17xwuc';
 
CHILD_NUMBER HINT_TEXT
------------ --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
           0 OPT_ESTIMATE (@"SEL$D3FD61E8" JOIN ("AR_RECEIVABLE_APPLICATIONS"@"SEL$4" "AR_CASH_RECEIPTS"@"SEL$5" "RA_CUSTOMER_TRX"@"SEL$7" "RA_CUST_TRX_TYPES"@"SEL$6") ROWS=6883728.000000 )
           0 OPT_ESTIMATE (@"SEL$D3FD61E8" JOIN ("AR_CASH_RECEIPTS"@"SEL$5" "RA_CUSTOMER_TRX"@"SEL$7" "RA_CUST_TRX_TYPES"@"SEL$6") ROWS=6349281.000000 )
           0 OPT_ESTIMATE (@"SEL$D3FD61E8" JOIN ("RA_CUSTOMER_TRX"@"SEL$7" "RA_CUST_TRX_TYPES"@"SEL$6") ROWS=33659437.000000 )
           0 OPT_ESTIMATE (@"SEL$7" TABLE "RA_CUSTOMER_TRX"@"SEL$7" MIN=234872.000000 )
           0 OPT_ESTIMATE (@"SEL$6" TABLE "RA_CUST_TRX_TYPES"@"SEL$6" MIN=2.000000 )

— однако, поскольку автоматическая реоптимизация для запроса и системы не запрещены, формально придраться не к чему)

Можно потрейсить выполнение для поиска запросов вида SELECT /* OPT_DYN_SAMP */, но в этом случае ситуация достаточно прозрачна и остаётся лишь надёжно отключить фичу способом, упомянутом в 12c: Automatic Dynamic Statistics:

SQL> -- добавив в существующий SQL patch
SQL> @sqlpatch_hints TASK-1711
 
SQL_PATCH_HINTS
---------------
parallel(20)

SQL> -- рекомендованную подсказку
SQL> @sqlpatch+ 8d49sjc17xwuc "parallel(20) DYNAMIC_SAMPLING(0)" "TASK-1711"
 
PL/SQL procedure successfully completed
 
 
SQL_PATCH_HINTS
--------------------------------
parallel(20) DYNAMIC_SAMPLING(0)

и проверить результат последующего выполнения:

SQL> select decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue') as EVENT,
  2         sql_plan_hash_value,
  3         count(distinct sql_exec_id) as SQL_EXECS,
  4         count(distinct session_id) as PX,
  5         count(*)
  6    gv$active_session_history
  7   where sql_id = '8d49sjc17xwuc'
  8   group by decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue'),
  9            sql_plan_hash_value
 10   order by count(*) desc
 11  /
 
EVENT                   SQL_PLAN_HASH_VALUE  SQL_EXECS         PX   COUNT(*)
----------------------- ------------------- ---------- ---------- ----------
db file sequential read           162625646          1         20       4009
On CPU / runqueue                 162625646          1         40        662
db file scattered read            162625646          1         20        227
gc cr grant 2-way                 162625646          1         13         22
gc current block 2-way            162625646          1          9          9
oracle thread bootstrap           162625646          1          1          4
read by other session             162625646          1          1          2
db file parallel read             162625646          1          1          1

— ожидания, связанные с конкуренцией за объекты Shared Pool значительно сократились, и Automatic Dynamic Statistics, будем надеется, что надёжно, отключён:

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('8d49sjc17xwuc', format => '+note'))

...

Note
-----
   - Degree of Parallelism is 20 because of hint
   - SQL patch "TASK-1711" used for this statement
   - SQL plan baseline SQL_PLAN_dnf8f9n4w4sx86f3363e5 used for this statement

Бонусом — естественное (в 2+ раза) сокращение времени выполнения за счёт уменьшения ожиданий класса Concurrency (CCWAITS_PER_EXEC):

SQL> @dba_hist_sqlstat "sql_id = '8d49sjc17xwuc' and snap_id between 86116 and 86260 and executions_delta > 0"
 
INST BEGIN_SNAP_ID BEGIN_SNAP_TIME    EXECS ROWS_PROCESSED SQL_ID              PLAN       COST PARSE_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC IOWAITS_PER_EXEC CLWAITS_PER_EXEC_US CCWAITS_PER_EXEC PX_PER_EXEC
---- ------------- --------------- -------- -------------- ------------- ---------- ---------- -------------- ------------ ------------ ---------------- ------------------- ---------------- -----------
   1         86115 29.05 12:00            1              0 8d49sjc17xwuc  162625646     112014             58  27091992499   1234512000       4680819310           589829301      20805941762           0
   1         86119 29.05 14:00            1              1 8d49sjc17xwuc  162625646      70921             51   8583153466   1576969000       5346204511          1175456561        657544182          40
   1         86258 01.06 11:30            1              0 8d49sjc17xwuc  162625646      70921             48   7185053470   1644459000       4591570385           953827081        124361567          40
   2         86258 01.06 11:30            1              0 8d49sjc17xwuc  162625646      70921             44   5222753653   1120614000       4326370728            36587918         57503066          40
   1         86259 01.06 12:00            1              0 8d49sjc17xwuc  162625646      70921             41   2252797302    700757000       1652253010             8895520            10609          40
   2         86259 01.06 12:00            3              0 8d49sjc17xwuc  162625646      70921             41   1970229688    674323000       1374896458             7148855            54298          40

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

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

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