Скачок 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 — т.е. формально запрос в процессе исполнения
Добавить комментарий