Oracle mechanics

15.06.2018

Oracle 12c: Optimizer Adaptive Features как генератор планов выполнения и сокращение mutex-ожиданий cursor: pin S

Filed under: Oracle,SQL Tuning — Игорь Усольцев @ 18:06
Tags: , ,

Скачок Load Average на обеих нодах:


high_LA_06062018.png

был спровоцирован частым выполнением запроса со стабильным, но не очень удачным планом 4125831042:

12.1.0.2@ SQL> @dba_hist_sqlstat "sql_id = '9z9wnsytk5m4b' and snap_id between 139091 and 139096 and executions_delta > 0"
 
INST BEGIN_SNAP_ID BEGIN_SNAP_TIME EXECS ROWS_PROCESSED SQL_ID              PLAN  COST ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC DISK_READS_PER_EXEC ROWS_PER_EXEC IOWAITS_PER_EXEC CLWAITS_PER_EXEC_US CCWAITS_PER_EXEC PLSQL_PER_EXEC
---- ------------- --------------- ----- -------------- ------------- ---------- ----- ------------ ------------ ------------- ------------------- ------------- ---------------- ------------------- ---------------- --------------
   1        139089 06.06 16:30         3              3 9z9wnsytk5m4b 4125831042  2966     36271943     36091101       3503111                  31             1            16899                2923                0        6792158
   1        139092 06.06 18:00       352            233 9z9wnsytk5m4b 4125831042  2966    159940974     55761382       2930457                  33             1           282948              142977         29794101       22437928
   2        139092 06.06 18:00       572            501 9z9wnsytk5m4b 4125831042  2966     61244614     31192562        317288                  55             1           401033              175832              438       55229013
   1        139093 06.06 18:30       581            579 9z9wnsytk5m4b 4125831042  2966    347472896    125918636             0                  40             1           355404              253346         62755340       50646945
   2        139093 06.06 18:30      1290           1305 9z9wnsytk5m4b 4125831042  2966    104476648     54168738        512261                  36             1           288617              160452              295       92433937
   1        139094 06.06 19:00       465            495 9z9wnsytk5m4b 4125831042  2966    430096809    158365446             0                  36             1           306187              310770         79839833       61356321
   2        139094 06.06 19:00      1285           1250 9z9wnsytk5m4b 4125831042  2966    100680227     51474082        500784                  33             1           249754              122598              309       90848706
   1        139095 06.06 19:30       528            517 9z9wnsytk5m4b 4125831042  2966    367288335    145858178       7650387                  21             1           175260              249648         65556602       57209250
   2        139095 06.06 19:30      1219           1235 9z9wnsytk5m4b 4125831042  2966    125583050     61912918        580701                  21             1           174633              153186              676      107770099
   1        139096 06.06 20:00       237            322 9z9wnsytk5m4b 4125831042  2966    485030687    256840531             0                  27             1           162455              266074         74233385       75603767
   2        139096 06.06 20:00       466            540 9z9wnsytk5m4b 4125831042  2966    164813126    104059324       1299009                  27             1           168473              156789              449      146630964

, причём относительно высокая доля ожиданий класса Concurrency — колонка CCWAITS_PER_EXEC (соответствующая DBA_HIST_SQLSTAT.CCWAIT_DELTA/EXECUTIONS_DELTA) относилась к рекурсивным (*) / вызываемым из используемой в запросе PL/SQL функции запросам(**), на что косвенно указывает высокая доля PLSQL_PER_EXEC (DBA_HIST_SQLSTAT.PLSEXEC_TIME_DELTA/EXECUTIONS_DELTA):

SQL> select inst_id, sql_id, session_state, event, wait_class, count(*)
  2    from gv$active_session_history
  3   where sql_id = '9z9wnsytk5m4b'
  4      or top_level_sql_id = '9z9wnsytk5m4b' -- *
  5   group by inst_id, sql_id, session_state, event, wait_class
  6  having count(*) > 3000
  7   order by count(*) desc
  8  /
 
INST_ID SQL_ID        SESSION_STATE EVENT                WAIT_CLASS     COUNT(*)
------- ------------- ------------- -------------------- ------------ ----------
      2 9z9wnsytk5m4b ON CPU                                              202661
      1 9z9wnsytk5m4b ON CPU                                               56654
      1 6gqwu2btky0za ON CPU                                               38373
      2 9z9wnsytk5m4b WAITING       resmgr:cpu quantum   Scheduler         33119
      1               ON CPU                                               14662
      2 9z9wnsytk5m4b WAITING       latch free           Other             14598
      1 b9tuqaas6xbh8 ON CPU                                               13048
      1 6gqwu2btky0za WAITING       cursor: pin S        Concurrency       12001 -- **
      1               WAITING       cursor: pin S        Concurrency       10825 -- **
      1 6f8nnh3kc2syp ON CPU                                               10806
      1 007zsgnrtb0c8 ON CPU                                                9169
      1 9z9wnsytk5m4b WAITING       resmgr:cpu quantum   Scheduler          8678
      1 7qwsx7rw0s3a5 ON CPU                                                8321
      1               WAITING       resmgr:cpu quantum   Scheduler          7966
      1 6gqwu2btky0za WAITING       resmgr:cpu quantum   Scheduler          7117
      1 ctdcj8mghk5c9 ON CPU                                                4828
      1 90znmngwuvu4w ON CPU                                                4794
      1 5b6q12n5gr1d3 ON CPU                                                4774
      1 6xzrrmb9f81x7 ON CPU                                                4764
      1 6f8nnh3kc2syp WAITING       cursor: pin S        Concurrency        3841 -- **
      1 b9tuqaas6xbh8 WAITING       cursor: pin S        Concurrency        3355 -- **

, в то время как во время выполнения основного запроса ожиданий класса Concurrency замечено не было:

SQL> select session_state, event, wait_class, count(*)
  2    from gv$active_session_history
  3   where inst_id = 1
  4     and sql_id = '9z9wnsytk5m4b'
  5   group by session_state, event, wait_class
  6   order by count(*) desc
  7  /
 
SESSION_STATE EVENT                     WAIT_CLASS    COUNT(*)
------------- ------------------------- ----------- ----------
ON CPU                                                   56654
WAITING       resmgr:cpu quantum        Scheduler         8678
WAITING       gc current block 2-way    Cluster            125
WAITING       db file sequential read   User I/O           100
WAITING       gc cr grant 2-way         Cluster             16
WAITING       gc cr block busy          Cluster              1
 
6 rows selected

Для решения проблемы неэффективности плана, поискав в DBA_HIST_SQL_PLAN, обнаружил ещё один Plan Hash Value 2532323071, отличавшийся от проблемного лишь одним используемым индексом:

SQL> @sql_plan_diff_outl_v2 9z9wnsytk5m4b 2532323071 9z9wnsytk5m4b 4125831042
--------------------------------
SQL Plan "Outline" sections diff
--------------------------------
 
PHV_2532323071
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
INDEX_RS_ASC(@"SEL$8E13D68A" "R"@"SEL$4" ("XXAR_REC_BALANCES_MONTH"."CODE_COMBINATION_ID" "XXAR_REC_BALANCES_MONTH"."END_DATE" "XXAR_REC_BALANCES_MONTH"."ORG_ID"))
----------------------------------------------------------------------------------------------------
PHV_4125831042
----------------------------------------------------------------------------------------------------
INDEX_RS_ASC(@"SEL$8E13D68A" "R"@"SEL$4" ("XXAR_REC_BALANCES_MONTH"."BILL_TRX_NUMBER" "XXAR_REC_BALANCES_MONTH"."CODE_COMBINATION_ID" "XXAR_REC_BALANCES_MONTH"."END_DATE"))
 
10 rows selected

, что, судя по DBA_HIST_SQLSTAT, мало влияло на время выполнения запроса(

Optimizer Adaptive Features на уровне системы были отключены, что блокировало эволюционную генерацию дополнительных планов:

SQL> @shared_cu12 9z9wnsytk5m4b 0
 
INST  EXECS LAST_LOAD_TIME       ROWS_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC CLU_PER_EXEC PLSQL_PER_EXEC CURSOR_STATUS PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  CF  REOPT REOPT_HINTS V$SQL.Adapt XML.Adapt SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON NOT_SHARED_BY         REASON                                SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE
---- ------ -------------------- ------------- ------------ ------------ ------------- -------------- ------------ ------------- ------------ -------------- ------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- --- ----- ----------- ----------- --------- --------- --------- -------- --- ---------- --------------------- ------------------------------------- ----------------- --------- ---------------- -----------
   1   2179 2018-06-06/15:30:57              1    375113276    162477598       1397489             37       267878      62686295       246943       56538499 VALID              4125831042           4083637131           2966     0 N          N          Y              N                 N                                                                                       Rolling Invalidate Window Exceeded(3)                                                         
                                                                                                                                                                                                                                                                                                                                                                                    Rolling Invalidate Window Exceeded(3)                                                         
                                                                                                                                                                                                                                                                                                                                                                                    Rolling Invalidate Window Exceeded(2)                                                         
                                                                                                                                                                                                                                                                                                                                                                                    Rolling Invalidate Window Exceeded(3)                                                         
   2   4844 2018-06-06/15:42:58              1    109586768     57702970        604127             33       250834           426       149786       96726754 VALID              4125831042           4083637131           2966     0 N          N          Y              N                 N                                                                                       Rolling Invalidate Window Exceeded(3)                                                         
                                                                                                                                                                                                                                                                                                                                                                                    Rolling Invalidate Window Exceeded(3)                                                         
                                                                                                                                                                                                                                                                                                                                                                                    Rolling Invalidate Window Exceeded(3)                                                         
   1     15 2018-06-07/09:27:39              1     41704166     41398307       3155081             22        16148           227        33092        7885463 VALID              4125831042           4083637131           2975     1 N          N          Y              N                 N                                                                 ROLL_INVALID_MISMATCH Rolling Invalidate Window Exceeded(3)                                                         
                                                                                                                                                                                                                                                                                                                                                                                    Rolling Invalidate Window Exceeded(2)                                                         
                                                                                                                                                                                                                                                                                                                                                                                    Rolling Invalidate Window Exceeded(3)                                                         
   2     20 2018-06-07/09:37:41              1      4861761      4673936        336849             96        57424             0        30934        3337694 VALID              4125831042           4083637131           2975     1 N          N          Y              N                 N                                                                 ROLL_INVALID_MISMATCH                                                                                               
 
--------------------------------------------------------------
SQL_ID=9z9wnsytk5m4b Shared Pool statistics by PLAN_HASH_VALUE
--------------------------------------------------------------
 
INST  EXECS LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC CLU_PER_EXEC PLSQL_PER_EXEC FETCH_PER_EXEC ROWS_PER_EXEC PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE AVG_CBO_COST     CHILDS BIND_SENSE BIND_AWARE REOPT ADAPT SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE
---- ------ -------------------- ------------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- ------------ -------------- -------------- ------------- --------------- -------------------- ------------ ---------- ---------- ---------- ----- ----- ----------------- --------- ---------------- -----------
   1   2194 2018-06-07/09:27:39                         372833815    161649799               1       1409505             37       266157      62257721       245481       56205866              1             1      4125831042           4083637131         2971          2 N          N          N     N
   2   4864 2018-06-07/09:37:41                         109156155     57484923               1        603028             33       250039           424       149298       96342752              1             1      4125831042           4083637131         2971          2 N          N          N     N
...

, а для применения доступных в этой ситуации технологий Adaptive Cursor Sharing / Cardinality Feedback версии 11g запрос не подходил по причине того, что кол-во связанных переменных в запросе / binds count = 14 что в точности совпадает с ограничением технологии ACS — магия?) — т.о. среди причин генерации новых курсоров заметны лишь унылые ROLL_INVALID_MISMATCH / Rolling Invalidate Window Exceeded (

Как вариант решения проблемы генерации разнообразия планов, в качестве триггера, были включены Optimizer Adaptive Features на уровне запроса:

SQL> @sqlpatch+
&SQL_ID: 9z9wnsytk5m4b
&SQL_PATCH_TEXT: opt_param(''optimizer_adaptive_features' 'true'')
&SQL_PATCH_NAME: 2gen_plans_adapt_f
 
PL/SQL procedure successfully completed
 
SQL_ID        NAME                           CATEGORY                       CREATED               STATUS   FMATCH
------------- ------------------------------ ------------------------------ --------------------- -------- ------
9z9wnsytk5m4b 2gen_plans_adapt_f             DEFAULT                        07.06.2018 15:54:55   ENABLED  NO
 
SQL_PATCH_HINTS
-----------------------------------------------------------------------------------------------------------------
opt_param('optimizer_adaptive_features' 'true')

, что по прошествии пары дней (благодаря USE_FEEDBACK_STATS и использованию Adaptive Plan-ов — колонка ADAPT) привело к следующим разнообразным рез-там:

SQL> @shared_cu12s 9z9wnsytk5m4b 0
 
INST_ID PLAN_HASH_VALUE EXECS ROWS_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXECUIO_PER_EXEC CONC_PER_EXECPLSQL_PER_EXEC OPTIMIZER_MODE LAST_ACTIVE_TIME    AVG_CBO_COST BIND_SENSE BIND_AWARE REOPT ADAPT NOT_SHARED_BY          REASON                                CURSOR_COUNT FPHV_COUNT  SQL_PATCH         
------- --------------- ----- ------------- ------------ ------------ ------------------------- --------------------------- -------------- ------------------- ------------ ---------- ---------- ----- ----- ---------------------- ------------------------------------- ------------ ----------  ------------------
      1      4125831042  2179             1    375113276    162477598       1397489      267878      62686295      56538499 ALL_ROWS       06.06.2018 15:30:57         2966 N          N          N     N                            SQL Tune Base Object Different(3)                1          1                    
                                                                                                                                                                                                                                     Rolling Invalidate Window Exceeded(3)                                            
 
      2      4125831042  4844             1    109586768     57702970        604127      250834           426      96726754 ALL_ROWS       06.06.2018 15:42:58         2966 N          N          N     N                            SQL Tune Base Object Different(3)                1          1                    
                                                                                                                                                                                                                                     Rolling Invalidate Window Exceeded(3)                                            
 
      1      4125831042    63             1    134657582    133733052      10840820       71961         81555      25300163 ALL_ROWS       07.06.2018 09:27:39         2975 N          N          N     N     ROLL_INVALID_MISMATCH  SQL Tune Base Object Different(3)                1          1                    
                                                                                                                                                                                                                                     Rolling Invalidate Window Exceeded(3)                                            
 
      2      4125831042    51             1      8528597      8184022        547019       69999           195       6050161 ALL_ROWS       07.06.2018 09:37:41         2975 N          N          N     N     ROLL_INVALID_MISMATCH  SQL Tune Base Object Different(3)                1          1                    
      2      2475345058     1             1      1417836      1242962        150501        3539             0        921797 ALL_ROWS       07.06.2018 15:56:25         2975 N          N          Y     Y     STB_OBJECT_MISMATCH    Auto Reoptimization Mismatch(1)                  1          1  2gen_plans_adapt_f
                                                                                                                                                                                                              USE_FEEDBACK_STATS                                                                                      
 
      2       131630208     1             1    122706390    119440056        264481        2839           289     110590259 ALL_ROWS       07.06.2018 16:05:56         7127 N          N          Y     N     USE_FEEDBACK_STATS     Auto Reoptimization Mismatch(1)                  1          1  2gen_plans_adapt_f
...
      2       526250104     1             1     18408236     16639201       1109515     1685829           636          1901 ALL_ROWS       09.06.2018 09:45:27         5180 N          N          Y     N     USE_FEEDBACK_STATS     Auto Reoptimization Mismatch(1)                  1          1  2gen_plans_adapt_f
      1      2985564690     5             1   9608364916   9476678996     733276651       79625      48069920    1810551381 ALL_ROWS       09.06.2018 09:47:27         4641 N          N          Y     N     USE_FEEDBACK_STATS     Auto Reoptimization Mismatch(1)                  1          1  2gen_plans_adapt_f
      2       336359141  1142             1       475090       435531         48913       24166             2        172202 ALL_ROWS       09.06.2018 09:49:28         3019 N          N          N     Y                                                                             1          1  2gen_plans_adapt_f
      1      3737918819   195             1     78803715     53263778       3411217      111665       9996503      13000052 ALL_ROWS       09.06.2018 10:03:00         6124 N          N          N     N                            Rolling Invalidate Window Exceeded(2)            1          1  2gen_plans_adapt_f
                                                                                                                                                                                                                                     Rolling Invalidate Window Exceeded(3)                                            
 
      1      4125831042     1             1      1480320      1459401        109541        2928             0        246223 ALL_ROWS       09.06.2018 14:52:59         3016 N          N          Y     Y     ROLL_INVALID_MISMATCH  Auto Reoptimization Mismatch(1)                  1          1  2gen_plans_adapt_f
                                                                                                                                                                                                              USE_FEEDBACK_STATS                                                                                      
 
      1       336359141     1             1        17098        11720          1323         644          4539           464 ALL_ROWS       09.06.2018 15:27:36         3019 N          N          Y     Y     ROLL_INVALID_MISMATCH  Auto Reoptimization Mismatch(1)                  1          1  2gen_plans_adapt_f
                                                                                                                                                                                                              USE_FEEDBACK_STATS                                                                                      
 
      1      4159039855     1             1       153239       144037         11750        2820          6431           613 ALL_ROWS       09.06.2018 15:39:08         3019 N          N          Y     Y     ROLL_INVALID_MISMATCH  Auto Reoptimization Mismatch(1)                  1          1  2gen_plans_adapt_f
                                                                                                                                                                                                              USE_FEEDBACK_STATS                                                                                      
 
43 rows selected
 
--------------------------------------------------------------
SQL_ID=9z9wnsytk5m4b Shared Pool statistics by PLAN_HASH_VALUE
--------------------------------------------------------------
 
INST        EXECS LAST_LOAD_TIME       ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC PLSQL_PER_EXEC ROWS_PER_EXEC PLAN_HASH_VALUE AVG_CBO_COST     CHILDS BIND_SENSE BIND_AWARE REOPT ADAPT SQL_PATCH         
---- ------------ -------------------- ------------ ------------ ------------- -------------- ------------ ------------- -------------- ------------- --------------- ------------ ---------- ---------- ---------- ----- ----- ------------------
   1         2242 2018-06-07/09:27:39     368356492    161669878       1662846             38       262373      60927107       55660704             1      4125831042         2971          2 N          N          N     N                       
   2         4895 2018-06-07/09:37:41     108533864     57187042        603532             34       248950           423       95782013             1      4125831042         2971          2 N          N          N     N                       
   2            1 2018-06-07/16:05:56     122706390    119440056        264481              5         2839           289      110590259             1       131630208         7127          1 N          N          Y     N     2gen_plans_adapt_f
   2            1 2018-06-07/16:39:10      12230860     12197294       1190100              0           81             0           2365             1      1034327791         7737          1 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-07/16:41:32        963802       949471         65938              0          136             0         654267             1      3533562600         8963          1 N          N          Y     N     2gen_plans_adapt_f
   2            1 2018-06-07/16:45:33     265639128    252456892         51926             13         7335             0      248644216             1      3928935937        10618          1 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-08/09:44:09      16488349     16184763         93851            275       258453             0       14510804             1      2989434425         4458          1 N          N          Y     Y     2gen_plans_adapt_f
   1            1 2018-06-08/09:49:10      33492384     33382279       3129242              4         2342         46412        6261508             1      1517253540         4777          1 N          N          Y     N     2gen_plans_adapt_f
   1            1 2018-06-08/10:04:13      34796844     34487354       3127291              3         1664         40116        6456222             1      1733478395         4805          1 N          N          Y     N     2gen_plans_adapt_f
   1            1 2018-06-08/10:05:43     132326585    131871107      12479977              8         4051        290799       24046465             1      2511506931         5178          1 N          N          Y     N     2gen_plans_adapt_f
   2            1 2018-06-08/10:12:44       4721459      4557851       1134328            141       100943           494          45845             1      1402816095         4970          1 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-08/10:49:52        176677       173325         12870              4         2119             0          46417             1      1847683437         8196          1 N          N          Y     N     2gen_plans_adapt_f
   2            1 2018-06-08/10:51:21        884861       718266         32390             53       149886             0         471466             1      1714672604         9011          1 N          N          Y     N     2gen_plans_adapt_f
   2            3 2018-06-08/14:27:38       1147128      1026708         89098             17        12160             0         627955             1      2475345058         2981          3 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-08/14:33:07        741191       715779         42931             15         8442             0         446671             1      3255123387         4289          1 N          N          Y     Y     2gen_plans_adapt_f
   2            2 2018-06-08/14:39:39   10104168885   7896598993      15720402            483       277859         49623     9318640550             1      2989434425         4548          1 N          N          Y     N     2gen_plans_adapt_f
   1            1 2018-06-08/14:46:10       1097349      1025475        221676             48        55281             0           8452             1      2592771521         4873          1 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-08/14:54:12       2370803      2119504         19638              2         1004             0        2063621             1      4070462107         4594          1 N          N          Y     N     2gen_plans_adapt_f
   1            1 2018-06-08/14:55:12       8289652      8191895        564114              8         6394         46826        1520787             1      1423139203         5774          1 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-08/14:57:12        533722       512493         85927             11         6203             0           7318             1      1058400361         4688          1 N          N          Y     Y     2gen_plans_adapt_f
   1            1 2018-06-08/21:56:12        485794       475724         42799              1          536          4222          70687             1       337880747         3043          1 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-08/21:58:14        590769       355882         12629              2         1419             0          21259             1      4125831042         2984          1 N          N          Y     Y     2gen_plans_adapt_f
   1            1 2018-06-08/22:03:13        661491       603995         42793              0          465          7987          81836             1      1470612792         3047          1 N          N          Y     Y     2gen_plans_adapt_f
   1            1 2018-06-08/22:04:43        539721       532838         42781              0            0          4991          75300             1       337880747         3449          1 N          N          Y     Y     2gen_plans_adapt_f
   1            3 2018-06-09/09:13:54       9667676      9337766        745334           3375       274962             0        1712766             1      2475345058         2995          3 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-09/09:16:23         82006        74737         25742              1          574          3622            477             1      4159039855         3019          1 N          N          Y     Y     2gen_plans_adapt_f
   1            1 2018-06-09/09:35:56      34410703     34120046       3132720            271       179899          5370        6379190             1      3211425168         4494          1 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-09/09:40:57        883793       769852         41308             66       100917           461         502749             1      3737918819         3245          1 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-09/09:44:27       1705170      1616296         93952             47        73882             0        1142241             1      3023061585         3337          1 N          N          Y     Y     2gen_plans_adapt_f
   2            1 2018-06-09/09:45:27      18408236     16639201       1109515           2501      1685829           636           1901             1       526250104         5180          1 N          N          Y     N     2gen_plans_adapt_f
   1            5 2018-06-09/09:47:27    9608364916   9476678996     733276651            130        79625      48069920     1810551381             1      2985564690         4641          1 N          N          Y     N     2gen_plans_adapt_f
   2         1146 2018-06-09/09:49:28        474786       435202         48911             35        24100             2         171894             1       336359141         3037          5 N          N          Y     Y     2gen_plans_adapt_f -- ****
   1          195 2018-06-09/10:03:00      78803715     53263778       3411217             36       111665       9996503       13000052             1      3737918819         6124          1 N          N          N     N     2gen_plans_adapt_f
   1            2 2018-06-09/14:52:59       1255248      1176152         76726              5        12958             0         165591             1      4125831042         3000          2 N          N          Y     Y     2gen_plans_adapt_f
   1            5 2018-06-09/15:27:36        220473       190601         34975             30        20538           908          57855             1       336359141         3045          5 N          N          Y     Y     2gen_plans_adapt_f
   1            2 2018-06-09/15:39:08        131949       123833         11693              3         1901          6176            405             1      4159039855         3003          2 N          N          Y     Y     2gen_plans_adapt_f
...
--------------------------------------------------------------
ASH TOP15 SQL_ID=9z9wnsytk5m4b Executions by Elapsed Time
--------------------------------------------------------------
 
INST_ID SQL_ID        SQL_PLAN_HASH_VALUE SQL_EXEC_ID   CHILD_ID   ASH_ROWS DURATIONs                 MIN_SAMPLE_TIME           MAX_SAMPLE_TIME
------- ------------- ------------------- ----------- ---------- ---------- ------------------------- ------------------------- -------------------------
      1 9z9wnsytk5m4b          2985564690    16779865         21       2666 +000000000 02:30:01       09-JUN-18 12.42.16.174 PM 09-JUN-18 03.12.17.852 PM -- ***
      1 9z9wnsytk5m4b          2985564690    16779864         21       1972 +000000000 01:54:33       09-JUN-18 12.42.16.174 PM 09-JUN-18 02.36.50.114 PM -- ***
      1 9z9wnsytk5m4b                   0    16779865         21        152 +000000000 02:28:38       09-JUN-18 12.42.40.214 PM 09-JUN-18 03.11.18.722 PM
      1 9z9wnsytk5m4b          2985564690    16779863         21         89 +000000000 00:05:18       09-JUN-18 12.42.16.174 PM 09-JUN-18 12.47.34.825 PM
      1 9z9wnsytk5m4b          3737918819    16780055         22         58 +000000000 00:02:58       09-JUN-18 01.08.40.472 PM 09-JUN-18 01.11.38.870 PM
      1 9z9wnsytk5m4b          3737918819    16780043         22         57 +000000000 00:02:37       09-JUN-18 12.42.18.194 PM 09-JUN-18 12.44.55.516 PM
      1 9z9wnsytk5m4b          3737918819    16780049         22         46 +000000000 00:02:48       09-JUN-18 12.55.37.814 PM 09-JUN-18 12.58.26.166 PM
      1 9z9wnsytk5m4b          3737918819    16780045         22         41 +000000000 00:02:03       09-JUN-18 12.49.36.083 PM 09-JUN-18 12.51.39.340 PM
      1 9z9wnsytk5m4b                   0    16779864         21         37 +000000000 01:51:58       09-JUN-18 12.44.39.466 PM 09-JUN-18 02.36.38.064 PM
      1 9z9wnsytk5m4b          3737918819    16780044         22         33 +000000000 00:02:02       09-JUN-18 12.47.05.775 PM 09-JUN-18 12.49.08.043 PM
      1 9z9wnsytk5m4b          3737918819    16780046         22         28 +000000000 00:01:30       09-JUN-18 12.49.38.083 PM 09-JUN-18 12.51.08.290 PM
      1 9z9wnsytk5m4b          3737918819    16780047         22         27 +000000000 00:01:45       09-JUN-18 12.53.08.541 PM 09-JUN-18 12.54.53.754 PM
      1 9z9wnsytk5m4b          3737918819    16780057         22         25 +000000000 00:01:12       09-JUN-18 01.18.41.739 PM 09-JUN-18 01.19.53.919 PM
      1 9z9wnsytk5m4b          3737918819    16780054         22         25 +000000000 00:01:24       09-JUN-18 01.07.40.331 PM 09-JUN-18 01.09.04.572 PM
      1 9z9wnsytk5m4b          3737918819    16780058         22         16 +000000000 00:01:03       09-JUN-18 01.21.45.133 PM 09-JUN-18 01.22.48.299 PM
 
15 rows selected

— планов появилось множество, они разные — есть из чего выбрать, не все «адаптивнопорождённые» планы удачны, например, PLAN_HASH_VALUE = 2985564690 (***) — очевидно неудачный(

Однако благодаря набранной статистике выполнения, среди прочих можно заметить и очевидно привлекательные планы типа PLAN_HASH_VALUE = 336359141 (****), который и можно будет «зафиксировать»:

SQL> @sql_profile_from_sql  9z9wnsytk5m4b 336359141 9z9wnsytk5m4b_336359141 9z9wnsytk5m4b_336359141
 
PL/SQL procedure successfully completed
 
HINT
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
ALL_ROWS
...
OPTIMIZER_FEATURES_ENABLE('12.1.0.2')
...
USE_NL(@"SEL$158D96DD" "TRX"@"SEL$2")
USE_NL(@"SEL$158D96DD" "X"@"SEL$2")
 
83 rows selected

, удалив за ненадобностью SQL Patch, включавший Adaptive Features:

SQL> @sqlpatch- "2gen_plans_adapt_f"  9z9wnsytk5m4b
 
PL/SQL procedure successfully completed
 
SPM Elements (SQL Profile, or SQL Plan Baseline, or SQL Patch) List for SQL_ID = 9z9wnsytk5m4b
 
SPM_TYPE          SQL_HANDLE                     PATCH_NAME                     ORIGIN         VERSION    CREATED             LAST_MODIFIED       LAST_EXECUTED       LAST_VERIFIED       ENABLED ACCEPTED FIXED REPRODUCED AUTOPURGE SPM_SIGNATURE         SQL_EXACT_SIGNATURE   SQL_FORCE_SIGNATURE
----------------- ------------------------------ ------------------------------ -------------- ---------- ------------------- ------------------- ------------------- ------------------- ------- -------- ----- ---------- --------- --------------------- --------------------- ---------------------
SQL Profile       SQL_9d0ffdcbe0996b40           9z9wnsytk5m4b_336359141        MANUAL-LOAD    12.1.0.2.0 13.06.2018 19:06:27 13.06.2018 19:06:27                                         YES     NO       NO    YES        NO         11317543440693685056  11317543440693685056  11317543440693685056

, что даёт следующую динамику:

SQL> @dba_hist_sqlstat "sql_id = '9z9wnsytk5m4b' and snap_id >= 139220 and executions_delta > 0"
 
INST BEGIN_SNAP_ID BEGIN_SNAP_TIME EXECS ROWS_PROCESSED SQL_ID              PLAN       COST ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC ROWS_PER_EXEC IOWAITS_PER_EXEC CLWAITS_PER_EXEC_US CCWAITS_PER_EXEC PLSQL_PER_EXEC
---- ------------- --------------- ----- -------------- ------------- ---------- ---------- ------------ ------------ ------------- ------------- ---------------- ------------------- ---------------- --------------
   1        139219 09.06 09:30         1              1 9z9wnsytk5m4b 3211425168       4494     34410703     34120046       3132720             1           179899               22666             5370        6379190
   1        139219 09.06 09:30         5              0 9z9wnsytk5m4b 2985564690       4641    417847816    413877718      32357122             0            31718               97169          1796050       78025804
   1        139220 09.06 10:00       130             54 9z9wnsytk5m4b 3737918819       6124     33952328     17791268       1024579             0            66942               37909          5980696        5444773
   2        139220 09.06 10:00       369            364 9z9wnsytk5m4b  336359141       3019       426917       393319         40983             1            21521                3488                4         156583 -- генерация удачного PHV 336359141
   1        139221 09.06 10:30        22            105 9z9wnsytk5m4b 3737918819       6124    414282145    285988648      17706706             5           520008              375642         52343481       67710430
   2        139221 09.06 10:30       725            727 9z9wnsytk5m4b  336359141       3019       466882       425497         45161             1            24140                3489                0         172717 -- под действием Adaptive Features
   1        139222 09.06 11:00         4              4 9z9wnsytk5m4b 3737918819       6124     12771290     12532255        974488             1             9610                3557            64329        2368348
...
   1        139423 13.06 15:30         1              0 9z9wnsytk5m4b 1430526634      10933    983100144    974497031      72566162             0             2065               17117          3854921      184811766 -- ещё один неудачный PHV 1430526634
   1        139424 13.06 16:00         5              0 9z9wnsytk5m4b 1430526634      10933   1147247431   1132245001      83980790             0               24                2034          6870673      213625348 -- , сгенерированный by Adaptive Features
   1        139425 13.06 16:30         1              2 9z9wnsytk5m4b 1430526634      10933   8269959737   8133378349     600954972             2             3736                4713         66089949     1540462355
   1        139426 13.06 17:00         1              0 9z9wnsytk5m4b 1430526634      10933   8439556473   8297901517     616774120             0              558                2876         70600110     1568134964
   1        139427 13.06 17:30         3              3 9z9wnsytk5m4b 1430526634      10933   3020530885   2966773648     208497086             1           207935                4837         21953709      564389575
   1        139428 13.06 18:00         4              1 9z9wnsytk5m4b 1430526634      10933   2881474540   2843123904     210558786             0              589                1600         16229560      534547180
   1        139429 13.06 18:30         3              1 9z9wnsytk5m4b 1430526634      10933   5678633254   5580705111             0             0              741                8534         56045033     1046379983
   1        139430 13.06 19:00         1              1 9z9wnsytk5m4b  336359141       3023       207080       183717         14957             1             7262               15582                0           9540 -- момент фиксации успешного PHV 336359141 +
   1        139431 13.06 19:30         1              1 9z9wnsytk5m4b  336359141       3023      2977552      2604652        610186             1           344563               73777                0         603014
   1        139432 13.06 20:00         1              1 9z9wnsytk5m4b  336359141       3023       715215       502662         13309             1            12128              356509                0           1453
   1        139439 13.06 23:30         1              1 9z9wnsytk5m4b  336359141       3023       166782       156382         13271             1             6574                2113              918           1282
   1        139453 14.06 06:30         1              1 9z9wnsytk5m4b  336359141       3032      3854971      2773642        461772             1           999806              137303                0         798624
   1        139454 14.06 07:00         3              3 9z9wnsytk5m4b  336359141       3032       124553        53737          7961             1            12821               60651                0          14422
   1        139455 14.06 07:30         2              2 9z9wnsytk5m4b  336359141       3032      1127350       993617        195095             1            53705              147946                0         278067
   1        139456 14.06 08:00         3              3 9z9wnsytk5m4b  336359141       3032      1846876      1743440        330524             1            69125                8292                0         555227
   1        139457 14.06 08:30         3              3 9z9wnsytk5m4b  336359141       3032       525548       487335         88979             1            32659                4170                0         168651
   1        139459 14.06 09:30         4              4 9z9wnsytk5m4b  336359141       3032       545255       517211         95515             1            26115                3576                0         132745
 
65 rows selected

— после фиксации успешного сгенерированного PHV=336359141 (+), кроме общего уменьшения среднего времени выполнения запроса (ELA_PER_EXEC), можно видеть значительное уменьшение и времени PL/SQL (PLSQL_PER_EXEC) и практического обнуления доли ожиданий класса Concurrency (CCWAITS_PER_EXEC) во времени выполнения запроса, что хорошо иллюстрируется сравнением зафиксированного PHV=336359141 с прежним медленным PHV=4125831042:

SQL> @sql_plan_diff_outl_v2 9z9wnsytk5m4b 336359141 9z9wnsytk5m4b 4125831042
--------------------------------
SQL Plan "Outline" sections diff
--------------------------------
 
PHV_336359141
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
FULL(@"SEL$158D96DD" "LGR"@"SEL$13")
FULL(@"SEL$158D96DD" "LS"@"SEL$9")
INDEX(@"SEL$158D96DD" "GC"@"SEL$5" ("GL_CODE_COMBINATIONS"."SEGMENT2"))
LEADING(@"SEL$158D96DD" "O"@"SEL$10" "HR_ALL_ORGANIZATION_UNITS_TL"@"SEL$12" "O3"@"SEL$10" "O2"@"SEL$10" "FND_LOOKUP_VALUES"@"SEL$8" "GC"@"SEL$5" "LS"@"SEL$9" "LGR"@"SEL$13" "C"@"SEL$2" "TRX"@"SEL$2" "X"@"SEL$2" "OKE"@"SEL$2")
NLJ_BATCHING(@"SEL$158D96DD" "GC"@"SEL$5")
SWAP_JOIN_INPUTS(@"SEL$158D96DD" "LS"@"SEL$9")
USE_HASH(@"SEL$158D96DD" "LGR"@"SEL$13")
USE_HASH(@"SEL$158D96DD" "LS"@"SEL$9")
USE_MERGE_CARTESIAN(@"SEL$158D96DD" "C"@"SEL$2")
----------------------------------------------------------------------------------------------------
PHV_4125831042
----------------------------------------------------------------------------------------------------
BATCH_TABLE_ACCESS_BY_ROWID(@"SEL$158D96DD" "GC"@"SEL$5")
INDEX(@"SEL$158D96DD" "LS"@"SEL$9" ("GL_LEDGER_NORM_SEG_VALS"."LEDGER_ID" "GL_LEDGER_NORM_SEG_VALS"."SEGMENT_TYPE_CODE" "GL_LEDGER_NORM_SEG_VALS"."SEGMENT_VALUE" "GL_LEDGER_NORM_SEG_VALS"."START_DATE" "GL_LEDGER_NORM_SEG_VALS"."END_DATE" "GL_LEDGER_NORM_SEG_VALS"."STATUS_CODE"))
INDEX_RS_ASC(@"SEL$158D96DD" "GC"@"SEL$5" ("GL_CODE_COMBINATIONS"."SEGMENT2"))
INDEX_RS_ASC(@"SEL$158D96DD" "LGR"@"SEL$13" ("GL_LEDGERS"."LEDGER_ID"))
LEADING(@"SEL$158D96DD" "O"@"SEL$10" "HR_ALL_ORGANIZATION_UNITS_TL"@"SEL$12" "C"@"SEL$2" "TRX"@"SEL$2" "O3"@"SEL$10" "O2"@"SEL$10" "OKE"@"SEL$2" "FND_LOOKUP_VALUES"@"SEL$8" "GC"@"SEL$5" "X"@"SEL$2" "LGR"@"SEL$13" "LS"@"SEL$9")
NLJ_BATCHING(@"SEL$158D96DD" "LS"@"SEL$9")
USE_NL(@"SEL$158D96DD" "C"@"SEL$2")
USE_NL(@"SEL$158D96DD" "LGR"@"SEL$13")
USE_NL(@"SEL$158D96DD" "LS"@"SEL$9")
 
26 rows selected

— из которого заметно, что медленный PHV=4125831042, в основном, использовал индексный доступ, провоцируя обработку большего кол-ва строк и более частое выполнение PL/SQL функции, в то время как быстрый план PHV_336359141 настроен на FULL SCAN / HASH JOIN

P.S. Ожидания cursor: pin S

The reason for the wait is that in order to acquire the mutex in S mode (or release it) the session has to increment (or decrement) the mutex reference count and this requires an exclusive atomic update to the mutex structure itself. If there are concurrent sessions trying to make such an update to the mutex then only one session can actually increment (or decrement) the reference count at a time. A wait on «cursor: pin S» thus occurs if a session cannot make that atomic change immediately due to other concurrent requests

имеют класс Concurrency, в описанном случае наблюдались по причине неэффективного плана / избыточного кол-ва выполнений рекурсивных запросов и возникали формально на этапе Soft Parse — до начала выполнения — SQL_EXEC_ID [nvl2(sql_exec_id,1,0)] = 0 и до определения плана выполнения — SQL_PLAN_HASH_VALUE = 0, однако имея либо уже выбранный SQL_CHILD_NUMBER (т.е. конкурировали за определённый дочерний курсор), либо ещё не определённый/не указанный в ASH номер дочернего курсора SQL_CHILD_NUMBER = -1 (*****) — что может относиться и к Hard Parse:

SQL> @ash_sql_wait_tree "top_level_sql_id = '9z9wnsytk5m4b' and event = 'cursor: pin S'" 100
 
LVL INST_ID BLOCKING_TREE EVENT              WAIT_CLASS   IN_PARSE IN_HARD_PARSE IN_SQL_EXECUTION IN_PLSQL_EXECUTION SQL_EXEC_ID WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT BLOCK_SID       SQL_ID        SQL_PLAN_HASH_VALUE TOP_LEVEL_SQL_ID SQL_CHILD_NUMBER
--- ------- ------------- ------------------ ------------ -------- ------------- ---------------- ------------------ ----------- ----------- ----------- ------ ---------- --------------- ------------- ------------------- ---------------- ----------------
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0       10289           0     19        614 NO HOLDER i#    6gqwu2btky0za                   0 9z9wnsytk5m4b                  58
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        9541           0     19        605 NO HOLDER i#                                    0 9z9wnsytk5m4b                  -1 -- *****
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        3285           0     19        521 NO HOLDER i#    6f8nnh3kc2syp                   0 9z9wnsytk5m4b                  56
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        3027           0     21        506 NO HOLDER i#    b9tuqaas6xbh8                   0 9z9wnsytk5m4b                  66
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        1774           0     20        448 NO HOLDER i#    007zsgnrtb0c8                   0 9z9wnsytk5m4b                  64
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        1712           0     17        430 VALID i#1       6gqwu2btky0za                   0 9z9wnsytk5m4b                  58
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        1585           0     18        420 NO HOLDER i#    ctdcj8mghk5c9                   0 9z9wnsytk5m4b                  58
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        1511           0     20        402 NO HOLDER i#    90znmngwuvu4w                   0 9z9wnsytk5m4b                  59
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        1478           0     21        404 NO HOLDER i#    6xzrrmb9f81x7                   0 9z9wnsytk5m4b                  76
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        1335           0     18        393 NO HOLDER i#    5b6q12n5gr1d3                   0 9z9wnsytk5m4b                  78
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        1324           0     18        381 NO HOLDER i#    7qwsx7rw0s3a5                   0 9z9wnsytk5m4b                 112
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0        1283           0     17        394 VALID i#1                                       0 9z9wnsytk5m4b                  -1
  1       1 (USER)        cursor: pin S      Concurrency  N        N             Y                N                            0         556           0     11        246 VALID i#1       6f8nnh3kc2syp                   0 9z9wnsytk5m4b                  56
  2       1   (USER)      On CPU / runqueue               N        N             Y                N                            0         836           0      0        158 NOT IN WAIT i#                                  0 9z9wnsytk5m4b                  -1
  2       1   (USER)      On CPU / runqueue               N        N             Y                Y                            1         674         250      0        250 NOT IN WAIT i#  9z9wnsytk5m4b          4125831042 9z9wnsytk5m4b                   0
  2       1   (USER)      On CPU / runqueue               N        N             Y                N                            1         580         409      0        229 NOT IN WAIT i#  6gqwu2btky0za           285861321 9z9wnsytk5m4b                  58
  2       1   (USER)      On CPU / runqueue               N        N             Y                N                            1         216         114      0        114 NOT IN WAIT i#  9z9wnsytk5m4b          4125831042 9z9wnsytk5m4b                   0
  2       1   (USER)      On CPU / runqueue               N        N             Y                N                            1         188         142      0        107 NOT IN WAIT i#  b9tuqaas6xbh8          1319308958 9z9wnsytk5m4b                  66
  2       1   (USER)      On CPU / runqueue               N        N             Y                N                            1         186         140      0         99 NOT IN WAIT i#  6f8nnh3kc2syp          2755394754 9z9wnsytk5m4b                  56
  2       1   (USER)      On CPU / runqueue               N        N             Y                N                            1         135         117      0         87 NOT IN WAIT i#  007zsgnrtb0c8           624732679 9z9wnsytk5m4b                  64
  2       1   (USER)      On CPU / runqueue               N        N             Y                N                            1         132         107      0         87 NOT IN WAIT i#  7qwsx7rw0s3a5           624732679 9z9wnsytk5m4b                 112
 
21 rows selected

— при этом ASH показывает IN_PARSE = N / IN_HARD_PARSE = N / IN_SQL_EXECUTION = Y — т.е. формально запрос в процессе исполнения

Реклама

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

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

RSS feed for comments on this post. TrackBack URI

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

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

Логотип WordPress.com

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

Google+ photo

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

Фотография Twitter

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

Фотография Facebook

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

Connecting to %s

Создайте бесплатный сайт или блог на WordPress.com.

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