Oracle mechanics

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 -- фаза обычного выполнения НЕадаптивных планов


— необходимую оценку даёт вторая строка (*) ~ 12.2% DB Time, что достаточно много, интересно на что было потрачено это время:

SQL> select session_state, event, count(*)
  2    from gv$active_session_history
  3   where sql_opname = 'SELECT'
  4     and sql_plan_hash_value > 0
  5     and sql_exec_id is null
  6     and sql_adaptive_plan_resolved = 1
  7   group by session_state, event
  8   order by count(*) desc
  9  /
 
SESSION_STATE EVENT                      COUNT(*)
------------- ------------------------ ----------
WAITING       latch free                    13675 -- ***
ON CPU                                       9679 -- ожидаемо, см.предыдущий пост
WAITING       cursor: pin S wait on X        3708 -- ****
WAITING       db file sequential read         993 -- вероятно, отновится к Automatic Dynamic Sampling (ADS)
WAITING       library cache lock              980 -- ожидаемая конкуренция
WAITING       db file scattered read          368 -- вероятно, отновится к ADS
WAITING       library cache pin               270 -- ожидаемая конкуренция
...

(***) latch free в этом случае относился к неэффективному использованию Result Cache:

SQL> select event, p2, count(*)
  2    from gv$active_session_history
  3   where sql_opname = 'SELECT'
  4     and sql_plan_hash_value > 0
  5     and sql_exec_id is null
  6     and sql_adaptive_plan_resolved = 1
  7     and event = 'latch free'
  8   group by event, p2
  9   order by count(*) desc
 10  /
 
EVENT              P2   COUNT(*)
---------- ---------- ----------
latch free        559      13440
latch free        535          1
 
SQL> select * from v$latchname where latch# = 559;
 
    LATCH# NAME
---------- ---------------------------------------
       559 Result Cache: RC Latch

— как рез-т не совсем разумного применения pragma RESULT_CACHE в PL/SQL блоке, что наследуется всеми вызываемыми процедурами/запросами, и это удалось проверить/подтвердить в дальнейшем: после отключения RESULT_CACHE в проблемном PL/SQL блоке latch free изчез из картины:

SQL> select session_state, event, count(*)
  2    from gv$active_session_history
  3   where sql_opname = 'SELECT'
  4     and sql_plan_hash_value > 0
  5     and sql_exec_id is null
  6     and sql_adaptive_plan_resolved = 1
  7   group by session_state, event
  8   order by count(*) desc
  9  /
 
SESSION_STATE EVENT                                      COUNT(*)
------------- ---------------------------------------- ----------
ON CPU                                                      14173
WAITING       cursor: pin S wait on X                        1195 -- ****
WAITING       db file sequential read                        1124
WAITING       library cache lock                              522
WAITING       db file scattered read                          371
WAITING       library cache pin                               344
...

— т.е. проблема latch free не совсем относилась к 12c Adaptive, но с фазой Soft Parse вполне согласуется)

(****) характерное для Soft Parse ожидание cursor: pin S wait on X указывает, в основном (второй параметр скрипта «10» фильтрует/ограничивает вывод по кол-ву ожиданий/сторок ASH), на пару параллельных запросов со схожей симптоматикой:

SQL> @ash_sql_wait_tree "sql_opname = 'SELECT' and sql_plan_hash_value > 0 and sql_exec_id is null and sql_adaptive_plan_resolved = 1 and event = 'cursor: pin S wait on X'" 10
 
LVL BLOCKING_TREE  EVENT                    WAIT_CLASS  WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT BLOCK_SID       SQL_ID        SQL_PLAN_HASH_VALUE SQL_PLAN_OPERATION SQL_TEXT
--- -------------- ------------------------ ----------- ----------- ----------- ------ ---------- --------------- ------------- ------------------- ------------------ -------------------------
  1 (P...)         cursor: pin S wait on X  Concurrency        2125           0   1005         11 VALID i#2       4ghc76vf7qbjs          2096073692 SELECT STATEMENT   SELECT /*+ PARALLEL(8) */
  1 (P...)         cursor: pin S wait on X  Concurrency        1080           0   1004         16 VALID i#2       6ny7mc94ybyn8          1324809779 SELECT STATEMENT   SELECT /*+ PARALLEL(8) */
  2   (P...)       On CPU / runqueue                            910           0      0          1 NOT IN WAIT i#  4ghc76vf7qbjs           436554960                    SELECT /*+ PARALLEL(8) */
  2   (P...)       On CPU / runqueue                            873           0      0          1 NOT IN WAIT i#  4ghc76vf7qbjs          2096073692                    SELECT /*+ PARALLEL(8) */
  2   (P...)       On CPU / runqueue                            316           0      0          2 NOT IN WAIT i#  6ny7mc94ybyn8          2540110218                    SELECT /*+ PARALLEL(8) */
  2   (P...)       On CPU / runqueue                            252           0      0          1 NOT IN WAIT i#  6ny7mc94ybyn8                   0                    SELECT /*+ PARALLEL(8) */
  2   (P...)       On CPU / runqueue                            216           0      0          1 NOT IN WAIT i#  6ny7mc94ybyn8          1324809779                    SELECT /*+ PARALLEL(8) */
  2   (P...)       db file sequential read  User I/O            160           0     26          1 NO HOLDER i#    4ghc76vf7qbjs           436554960                    SELECT /*+ PARALLEL(8) */
  2   (P...)       db file sequential read  User I/O            126           0     75          1 NO HOLDER i#    4ghc76vf7qbjs          2096073692                    SELECT /*+ PARALLEL(8) */

На примере 1-го запроса:

SQL> @ash_sql_wait_tree "sql_id = '4ghc76vf7qbjs' and sql_plan_hash_value > 0 and sql_exec_id is null and event = 'cursor: pin S wait on X'" 0
 
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_PLAN_OPERATION SQL_TEXT
--- -------------- ------------------------ ----------- ----------- ----------- ------ ---------- --------------- -------------------------- -------------------------- ------------- ------------------- ------------------ -------------------------
  1 (P...)         cursor: pin S wait on X  Concurrency        2125           0   1005         11 VALID i#2       19-DEC-15 10.57.57.999 PM  19-DEC-15 11.01.41.524 PM  4ghc76vf7qbjs          2096073692 SELECT STATEMENT   SELECT /*+ PARALLEL(8) */
  2   (P...)       On CPU / runqueue                            910           0      0          1 NOT IN WAIT i#  19-DEC-15 10.57.57.999 PM  19-DEC-15 10.59.48.266 PM  4ghc76vf7qbjs           436554960                    SELECT /*+ PARALLEL(8) */
  2   (P...)       On CPU / runqueue                            873           0      0          1 NOT IN WAIT i#  19-DEC-15 10.59.50.266 PM  19-DEC-15 11.01.41.524 PM  4ghc76vf7qbjs          2096073692                    SELECT /*+ PARALLEL(8) */
  2   (P...)       db file sequential read  User I/O            160           0     26          1 NO HOLDER i#    19-DEC-15 10.58.59.146 PM  19-DEC-15 10.59.32.236 PM  4ghc76vf7qbjs           436554960                    SELECT /*+ PARALLEL(8) */
  2   (P...)       db file sequential read  User I/O            126           0     75          1 NO HOLDER i#    19-DEC-15 11.01.11.424 PM  19-DEC-15 11.01.25.504 PM  4ghc76vf7qbjs          2096073692                    SELECT /*+ PARALLEL(8) */
  2   (P...)       db file scattered read   User I/O             30           0      1          1 NO HOLDER i#    19-DEC-15 10.58.43.116 PM  19-DEC-15 10.59.47.256 PM  4ghc76vf7qbjs           436554960                    SELECT /*+ PARALLEL(8) */
  2   (P...)       direct path write temp   User I/O             10           0    113          1 UNKNOWN i#      19-DEC-15 10.59.37.246 PM  19-DEC-15 10.59.37.246 PM  4ghc76vf7qbjs           436554960                    SELECT /*+ PARALLEL(8) */
  2   (P...)       direct path write temp   User I/O              9           0    205          1 UNKNOWN i#      19-DEC-15 11.01.28.514 PM  19-DEC-15 11.01.28.514 PM  4ghc76vf7qbjs          2096073692                    SELECT /*+ PARALLEL(8) */
  2   (P...)       library cache pin        Concurrency           7           0      0          1 GLOBAL i#       19-DEC-15 10.59.49.266 PM  19-DEC-15 10.59.49.266 PM  4ghc76vf7qbjs          2096073692                    SELECT /*+ PARALLEL(8) */

— можно заметить следующее:
1) ожидания cursor: pin S wait on X длились достаточно долго в течение выполнения ~ 4 минут
2) ожидали PX процессы с PHV=2096073692, а в числе блокеров можно видеть как PX процесс с PHV=2096073692, так и с PHV=436554960, что похоже на адаптивное поведение — некие тесты/пробы различных планов
3) блокирующий PX процесс[ы], судя по присутствию I/O ожиданий, вероятно, выполнял ADS-запросы, что иллюстрирует проблему High Waits for ‘cursor: pin S wait on X’ due to Dynamic Sampling Against Parallel Queries (Doc ID 2006145.1)
4) блокировались PX процессы с уже сгенерированным/определившимся PHV=2096073692, что вероятно только при выборе 12c Adaptive Parallel Distribution Methods, имхо

Статистика курсоров во время выполнения показывает пару одновременно открытых курсоров с PHV=2096073692 с заметной долей конкурентных ожиданий (CONC_PER_EXEC, вероятно, cursor: pin S wait on X), однако, следов никаких адаптивных эффектов, кроме Automatic Dynamic Sampling может не наблюдаться во время выпонения запроса:

SQL> @shared_cu12_noxml 4ghc76vf7qbjs 0
 
EXECS USERS_OPENING LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC CONC_PER_EXEC CURSOR_STATUS  PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS REOPT REOPT_HINTS ADAPT SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON REASON#1              SQL_PLAN_BASELINE SQL_PATCH SQL_PROFILE IS_OBSOLETE
----- ------------- -------------------- ------------------- ------------ ------------ --------------- ------------- -------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----- --------- --------- -------- --- ---------- --------------------- ----------------- --------- ----------- -----------
    1             1 2015-12-19/22:55:37  19.12.2015 23:20:51    139538729     83542000              18        139775 INVALID_UNAUTH      2096073692           3606406536         309551     0 N          N          Y          N                  N                       21        0         11       8   hint       Bind UACs mismatch(0)                                         N
    0            16 2015-12-19/22:59:49  19.12.2015 23:20:59  12700827257   9196535000               0    3374666043 INVALID_UNAUTH      2096073692           3606406536         309488     2 N          N          Y          N                  N                       21        0         11                                                                                    N

, но проявиться уже после выпонения (USERS_OPENING=0) — см. USE_FEEDBACK_STATS=Y (V$SQL_SHARED_CURSOR.USE_FEEDBACK_STATS), REOPT=Y (V$SQL.IS_REOPTIMIZABLE) плюс кол-во REOPT_HINTS (из V$SQL_PLAN.OTHER_XML):

EXECS USERS_OPENING LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC CONC_PER_EXEC CURSOR_STATUS  PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS REOPT REOPT_HINTS ADAPT SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON REASON#1              SQL_PLAN_BASELINE SQL_PATCH SQL_PROFILE IS_OBSOLETE
----- ------------- -------------------- ------------------- ------------ ------------ --------------- ------------- -------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----- --------- --------- -------- --- ---------- --------------------- ----------------- --------- ----------- -----------
    1             0 2015-12-21/22:55:51  21.12.2015 23:24:23    120488053     73093000              17         76635 VALID               2096073692           3606406536         310918     0 N          N          Y          Y                  Y               8       21        0         11       8   hint       Bind UACs mismatch(0)                                         N
    0             0 2015-12-21/22:57:51  21.12.2015 23:24:23  12205200098  10290461000               0    1768198209 VALID               2096073692           3606406536         310897     1 N          N          Y          N                  N                       21        0         11                                                                                    N

, при этом DBMS_XPLAN.DISPLAY_CURSOR соответственно может не показывать адаптивных особенностей запроса:

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('4ghc76vf7qbjs'));

...
Note
-----
   - dynamic statistics used: dynamic sampling (level=AUTO) -- кроме ADS
   - Degree of Parallelism is 8 because of hint

Т.о. ввиду временных лагов заполнения V$SQL_SHARED_CURSOR / V$SQL / V$SQL_PLAN определение «адаптивности»/12c Adaptive выполняющегося плана может оказаться нетривиальной задачей, для которой кроме прямых признаков может подойти значение ASH.SQL_ADAPTIVE_PLAN_RESOLVED

ASH SQL мониторинг выполнения (в отличие от стандартного SQL Monitor) подтверждает использование 2-х планов в течение выполнения:

SQL> @ash_sqlmon2 4ghc76vf7qbjs
 
LAST_PLSQL  SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                                  PX   ASH_ROWS WAIT_PROFILE
----------- ------------- --------------- ---- --------------------------------------------- ---- ---------- -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Soft Parse  4ghc76vf7qbjs       436554960    0 sql_plan_hash_value > 0; sql_exec_id is null     0        111 ON CPU(91); db file sequential read(16); db file scattered read(3); direct path write temp(1)
Soft Parse  4ghc76vf7qbjs      2096073692    0 sql_plan_hash_value > 0; sql_exec_id is null    10       3611 cursor: pin S wait on X(2125); library cache lock(1233); ON CPU(173); db file sequential read(41); db file scattered read(21); db file parallel read(13); direct path write temp(3); library cache pin(1); kksfbc child completion(1)
Main Query  4ghc76vf7qbjs      2096073692    0   SELECT STATEMENT                               7          8 ON CPU(8)
                                             1     FILTER                                                    
                                             2       PX COORDINATOR                                          
                                             3         PX SEND QC (RANDOM)                                   
...
                                            64                   INDEX UNIQUE SCAN                           
                                            65                 TABLE ACCESS BY INDEX ROWID                   
SQL Summary                             0    0 ASH fixed 1 execs from 17 sessions                      13715  ash rows were fixed from 19.12.2015 22:55:38 to 19.12.2015 23:22:39

— план 436554960 используется только на этапе Soft Parse, при этом судя по WAIT_PROFILE кроме использования ЦПУ читает и пишет (временные) данные — т.е. реально работает

Если взглянуть на отличия планов PHV=2096073692 и PHV=436554960 запроса 4ghc76vf7qbjs в блоке SEL$AB668856:

SQL> @sql_plan_diff 4ghc76vf7qbjs 2096073692 4ghc76vf7qbjs 436554960 SEL$AB668856
 
-------------------------------
SQL Plans [by Query block] diff
-------------------------------
 
PLAN_HASH_VALUE QBLOCK_NAME     ID OPERATION                         QBLOCK_NAME   OBJECT_ALIAS              OBJECT           COST(IO)               TEMP TIME
--------------- ------------- ---- --------------------------------- ------------- ------------------------- ---------------- -------------- ------------ ----
AWR_2096073692  SEL$AB668856    10 VIEW                              SEL$AB668856  from$_subquery$_008@SEL$5                  286807(284005)                 6
                SEL$AB668856    11  FILTER                           SEL$AB668856                                             ()                          
                                12   HASH GROUP BY                                                                            286807(284005)   1097737000    6
                                13    PX RECEIVE                                                                              286807(284005)                 6
                                14     PX SEND HASH                                                          "SYS".":TQ20003" 286807(284005)                 6
                                15      HASH GROUP BY                                                                         286807(284005)   1097737000    6
                                16       NESTED LOOPS                                                                         275136(272529)                 6
                                17        HASH JOIN                                                                           274941(272529)                 6
                                18         JOIN FILTER CREATE                                                "SYS".":BF0000"  431(415)                       1
...
                                23         HASH JOIN                                                                          274266(272114)                 6
                                24          JOIN FILTER CREATE                                               "SYS".":BF0001"  77916(77591)                   2
                                25           PX RECEIVE                                                                       77916(77591)                   2
                                26            PX SEND HYBRID HASH                                            "SYS".":TQ20001" 77916(77591)                   2
                                27             STATISTICS COLLECTOR                                                           ()                          
                                28              PX BLOCK ITERATOR                                                             77916(77591)                   2
                SEL$AB668856    29               TABLE ACCESS FULL   SEL$AB668856  ORDERTZ@SEL$7             "UO"."ORDERTZ"   77916(77591)                   2
                                30          PX RECEIVE                                                                        196082(194523)                 4
                                31           PX SEND HYBRID HASH                                             "SYS".":TQ20002" 196082(194523)                 4
                                32            JOIN FILTER USE                                                "SYS".":BF0000"  196082(194523)                 4
                                33             JOIN FILTER USE                                               "SYS".":BF0001"  196082(194523)                 4
                                34              PX BLOCK ITERATOR                                                             196082(194523)                 4
                SEL$AB668856    35               TABLE ACCESS FULL   SEL$AB668856  CONSUMERZ@SEL$6           "UO"."CONSUMERZ" 196082(194523)                 4
...                        
--------------- -------------      --------------------------------- ------------- ------------------------- ----------------                             
AWR_436554960   SEL$AB668856    10 VIEW                              SEL$AB668856  from$_subquery$_008@SEL$5                  272306(269678)                 6
                SEL$AB668856    11  FILTER                           SEL$AB668856                                             ()                          
                                12   HASH GROUP BY                                                                            272306(269678)   1134826000    6
                                13    PX RECEIVE                                                                              272306(269678)                 6
                                14     PX SEND HASH                                                          "SYS".":TQ20002" 272306(269678)                 6
                                15      HASH GROUP BY                                                                         272306(269678)   1134826000    6
                                16       NESTED LOOPS                                                                         260260(257833)                 6
                                17        HASH JOIN                                                                           260058(257833)                 6
                                18         JOIN FILTER CREATE                                                "SYS".":BF0000"  430(414)                       1
...
                                23         HASH JOIN                                                                          259414(257419)                 6
                                24          PX RECEIVE                                                                        73536(73268)                   2
                                25           PX SEND BROADCAST                                               "SYS".":TQ20001" 73536(73268)                   2
                                26            PX BLOCK ITERATOR                                                               73536(73268)                   2
                SEL$AB668856    27             TABLE ACCESS FULL     SEL$AB668856  ORDERTZ@SEL$7             "UO"."ORDERTZ"   73536(73268)                   2
                                28          JOIN FILTER USE                                                  "SYS".":BF0000"  185636(184152)                 4
                                29           PX BLOCK ITERATOR                                                                185636(184152)                 4
                SEL$AB668856    30            TABLE ACCESS FULL      SEL$AB668856  CONSUMERZ@SEL$6           "UO"."CONSUMERZ" 185636(184152)                 4
...                        

 
------------------------------
SQL Plan "Notes" sections diff
------------------------------
 
PHV_2096073692                                                  PHV_436554960
--------------------------------------------------------------- ---------------------------------------------------------
                                                             
   sql_profile:                                                 sql_profile:
   sql_patch:                                                   sql_patch:
   baseline:                                                    baseline:
   outline:                                                     outline:
   dyn_sampling:    11                                          dyn_sampling:    11
   dop:                                                         dop:
   dop_reason:                                                  dop_reason:
   card_feedback:                                               card_feedback:
   perf_feedback:                                               perf_feedback:
   adaptive_plan:                                               adaptive_plan:
   spd_used:        0                                           spd_used:        0
   spd_valid:       18                                          spd_valid:       12
   gtt_sess_stat:                                               gtt_sess_stat:
   db_version:      12.1.0.2                                    db_version:      12.1.0.2
   plan_hash_full:  3606406536                                  plan_hash_full:  192865668
   plan_hash:       2096073692                                  plan_hash:       436554960
   plan_hash_2:     3606406536                                  plan_hash_2:     192865668
 
 
--------------------------------
SQL Plan "Outline" sections diff
--------------------------------
 
PHV_2096073692                                                  PHV_436554960
--------------------------------------------------------------- -------------------------------------------------------------------
PQ_DISTRIBUTE(@"SEL$AB668856" "CONSUMERZ"@"SEL$6" HASH HASH)
PX_JOIN_FILTER(@"SEL$AB668856" "CONSUMERZ"@"SEL$6")             
                                                                PQ_DISTRIBUTE(@"SEL$AB668856" "CONSUMERZ"@"SEL$6" BROADCAST NONE)

— можно видеть, что реально используемый при выполнении план PHV=2096073692 является адаптивным и после выбора 12c Adaptive Parallel Distribution Methods (см. операции PX SEND HYBRID HASH и STATISTICS COLLECTOR) использует/выбирает метод соединения PQ_DISTRIBUTE(HASH HASH) в противоположность потенциально возможному/применяемому в неадаптивном плане PHV=436554960 методу PQ_DISTRIBUTE(BROADCAST NONE)

И в процессе этого поиска оптимального метода непосредственно перед началом выполнения (sql_plan_hash_value > 0; sql_exec_id is null) используется краткосрочное тестовое(?) выполнение с планом PHV=436554960, что несколько отличается/разнообразит классическое описание Optimizer with Oracle Database 12c:

With the new adaptive distribution method, HYBRID HASH the optimizer can defer its distribution method decision until execution…

Итого, очищенным от случайностей запросом:

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             and not (session_state = 'WAITING' and event = 'latch free') -- исключение случайностей
 15           group by decode(nvl(sql_plan_hash_value, -1), -1, 'not yet', 0, '0', 'exists'),
 16                    nvl2(sql_exec_id, 'exists', 'not yet'),
 17                    session_state,
 18                    sql_adaptive_plan_resolved)
 19   group by plan_hash_value, sql_exec_id, adaptive_plan
 20   order by sum(ash_rows) desc
 21  /
 
PLAN_HASH_VALUE SQL_EXEC_ID ADAPTIVE_PLAN SUM(ASH_ROWS) DB_TIME_WASTE                    PerCent
--------------- ----------- ------------- ------------- -------------------------------- -------
exists          exists                  1        234439 ON CPU(181504);WAITING(52935)      90.41
exists          not yet                 1         16971 ON CPU(11916);WAITING(5055)         6.55 -- *
0               exists                  0          3605 WAITING(2089);ON CPU(1516)          1.39
0               not yet                 0          1937 ON CPU(1006);WAITING(931)           0.75
0               not yet                 1          1627 ON CPU(1479);WAITING(148)           0.63
exists          not yet                 0           714 WAITING(529);ON CPU(185)            0.28
0               exists                  1             2 ON CPU(2)                           0.00

можно оценить overhead типа Oracle 12c Adaptive Soft Parse в 6.5% (*), на другой системе ERP-типа аналогичная оценка даёт близкий рез-т (*):

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             and not (session_state = 'WAITING' and event = 'latch free') -- на всякий случай исключаю
 15           group by decode(nvl(sql_plan_hash_value, -1), -1, 'not yet', 0, '0', 'exists'),
 16                    nvl2(sql_exec_id, 'exists', 'not yet'),
 17                    session_state,
 18                    sql_adaptive_plan_resolved)
 19   group by plan_hash_value, sql_exec_id, adaptive_plan
 20   order by sum(ash_rows) desc
 21  /
 
PLAN_HASH_VALUE SQL_EXEC_ID ADAPTIVE_PLAN SUM(ASH_ROWS) DB_TIME_WASTE                    PerCent
--------------- ----------- ------------- ------------- -------------------------------- -------
exists          exists                  1        197445 ON CPU(143262);WAITING(54183)      80.17
0               exists                  0         27344 ON CPU(19423);WAITING(7921)        11.10 -- **
exists          not yet                 1         15413 ON CPU(13127);WAITING(2286)         6.26 -- *
0               not yet                 1          3311 ON CPU(3206);WAITING(105)           1.34
0               not yet                 0          1892 ON CPU(1455);WAITING(437)           0.77
exists          not yet                 0           884 WAITING(501);ON CPU(383)            0.36
0               exists                  1             3 ON CPU(3)                           0.00
exists          exists                  0             1 ON CPU(1)                           0.00

— но тут необычна велика доля неадаптивного выполнения с PLAN_HASH_VALUE=0 (**), что само по себе другая любопытная тема

В дополнение можно оценить долю Automatic Dynamic Sampling (ADS) запросов через V$SQLSTATS ибо запросы ADS в обзоры и таблицы ASH не попадают:(

SQL> select decode(substr(sql_text, 1, 19),'SELECT /* DS_SVC */','ADS_sql','Regular_sql') as SQL_TYPE,
  2         sum(elapsed_time) as "Elapsed_uS",
  3         to_char(RATIO_TO_REPORT(sum(elapsed_time)) OVER() * 100, '990.99') as "PerCent"
  4    from gv$sqlstats
  5   group by decode(substr(sql_text, 1, 19),'SELECT /* DS_SVC */','ADS_sql','Regular_sql')
  6  /
 
SQL_TYPE    Elapsed_uS PerCent
----------- ---------- -------
ADS_sql     3220029824    0.59 -- менее 1%
Regular_sql 5405965687   99.41

, что даёт для непрямых потерь на 12c Adaptive Soft Parse + ADS оценку в 6-7%, конечно же, без учёта прямых потерь от неоптимальных
адаптивных планов)

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

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

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