С удивлением надлюдал поведение стандартного запроса приложения OEBS в условиях напряжённой адаптивной оптимизации (optimizer_features_enable = 12.1.0.2 and optimizer_adaptive_features=TRUE):
SQL> @shared_cu12_noxml fwpd5tbgffy68 INST EXECS USERS_OPENING LAST_LOAD_TIME PARSE_USER LAST_ACTIVE_TIME ELA_PER_EXEC CURSOR_STATUS PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE USE_FEEDBACK_STATS REOPT REOPT_HINTS ADAPT SPD_Valid SPD_Used DS_LEVEL BIND_EQ_FAILURE REASON#1 REASON#2 ---- ----- ------------- -------------------- ---------- ------------------- ------------ -------------- --------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----- --------- --------- -------- ---------------- ------------------------------- ------------------------------- 1 11 0 2015-10-23/01:05:07 APPS 23.10.2015 01:06:02 1810503 VALID 2124898932 1103 0 N N N Y Y 6 Y 37 8 2 N Auto Reoptimization Mismatch(1) 1 11 0 2015-10-23/01:06:09 APPS 23.10.2015 01:07:01 978098 VALID 1544287943 3063 1 N N N Y Y 9 Y 37 8 2 N Auto Reoptimization Mismatch(1) 1 1 0 2015-10-23/01:44:48 APPS 23.10.2015 01:44:58 10736147 VALID 3906421685 6915 2 N N N Y Y 15 Y 35 9 2 N Auto Reoptimization Mismatch(1) 1 1 0 2015-10-23/01:44:59 APPS 23.10.2015 01:45:06 7286152 VALID 1726949873 5111 3 N N N Y Y 17 Y 35 9 2 N Auto Reoptimization Mismatch(1) 1 1 0 2015-10-23/02:02:06 APPS 23.10.2015 02:02:12 7083138 VALID 773547478 9513 4 N N N Y Y 31 Y 36 9 2 N Auto Reoptimization Mismatch(1) 1 1 0 2015-10-23/02:02:13 APPS 23.10.2015 02:02:16 2993535 VALID 1066558335 3952 5 N N Y Y Y 15 Y 39 6 2 N 2 63 1 2015-10-22/00:49:53 APPS 22.10.2015 00:52:15 949616 INVALID_UNAUTH 1963710993 938052128 4 N N N Y Y 31 Y 42 2 2 N Auto Reoptimization Mismatch(1) Auto Reoptimization Mismatch(1) 2 1 0 2015-10-23/01:12:00 APPS 23.10.2015 01:12:01 1184060 VALID 840067654 235 5 N N N Y Y 11 Y 40 5 2 N Auto Reoptimization Mismatch(1) Auto Reoptimization Mismatch(1) 2 10 0 2015-10-23/01:20:05 APPS 23.10.2015 01:36:53 3232426 VALID 1064056405 2226 7 N N Y N N Y 40 5 2 N Auto Reoptimization Mismatch(1) Auto Reoptimization Mismatch(1) 2 4 1 2015-10-22/00:52:41 APPS 23.10.2015 13:05:46 32593707246 INVALID_UNAUTH 1663364961 1373425052843 6 N N N Y Y 45 Y 41 3 2 N Auto Reoptimization Mismatch(1) Auto Reoptimization Mismatch(1)
— запрос по V$SQL_SHARED_CURSOR / V$SQL показывает набор динамично генерируемых планов с незначительными колебаниями ср.времени выполнения ELA_PER_EXEC, кроме последней строки: CHILD=6 на 2-м инстансе выполняется с PLAN_HASH_VALUE=1663364961 стоимостью 1373425052843 (что несколько превышает обычную) достаточно длительное время 32,593,707,246 ns = 32,593 секунд при ср.времени выполнения не более 10 секунд
Причиной, очевидно, являются адаптивные эксперименты Oracle, в частности, в этом случае под влиянием 45 реоптимизационных хинтов (REOPT_HINTS) и 3 из 41 доступных SQL Plan Directives (SPD_Valid / SPD_Used) был выбран не очень удачный план с использованием старого доброго MERGE JOIN CARTESIAN по безопасному однострочному, как предполагалось, источнику данных:
SQL Monitoring Report Global Information ------------------------------ Status : EXECUTING Instance ID : 2 Session : APPS (773:23770) SQL ID : fwpd5tbgffy68 SQL Execution ID : 33554966 Execution Started : 10/22/2015 09:08:28 First Refresh Time : 10/22/2015 09:08:34 Last Refresh Time : 10/23/2015 13:26:51 Duration : 101904s Module/Action : e:AR:bes:oracle.apps.xla.accounting.extract/AR Service : oebs Program : STANDART@appl2.oebs.net (TNS V1-V3) PLSQL Entry Ids (Object/Subprogram) : 1679535,5 PLSQL Current Ids (Object/Subprogram) : 2447424,2 Binds -- ***** ======================================================================================================================== | Name | Position | Type | Value | ======================================================================================================================== | :B5 | 1 | NUMBER | 243970149 | | :B4 | 2 | NUMBER | 243972101 | | :B3 | 3 | DATE | 01/01/1805 00:00:00 | | :B2 | 4 | DATE | 10/21/2015 00:00:00 | | :B1 | 5 | VARCHAR2(32) | RECEIPT | ======================================================================================================================== Global Stats ============================================================================== | Elapsed | Cpu | IO | Cluster | Other | Buffer | Read | Read | | Time(s) | Time(s) | Waits(s) | Waits(s) | Waits(s) | Gets | Reqs | Bytes | ============================================================================== | 101906 | 101610 | 0.04 | 0.00 | 296 | 4M | 74 | 592KB | -- **** ============================================================================== SQL Plan Monitoring Details (Plan Hash Value=1663364961) ============================================================================================================================================================================== | Id | Operation | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Mem | Activity | Activity Detail | | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | | (%) | (# samples) | ============================================================================================================================================================================== | 0 | SELECT STATEMENT | | | | | 1 | | | | | | | | 1 | FILTER | | | | | 1 | | | | | | | | 2 | NESTED LOOPS OUTER | 1186 | 1T | | | 1 | | | | | | | ... | 182 |/***/ NESTED LOOPS | 12P | 3823 | 101881 | +6 | 1 | 52M | | | | 4.04 | Cpu (1241) | | -> 183 |/**/ MERGE JOIN CARTESIAN | 1 | 3820 | 101908 | +6 | 1 | 4G | | | | | | | -> 184 | HASH JOIN | 1 | 829 | 101908 | +6 | 1 | 7M | | | 3M | 0.01 | Cpu (4) | | 185 | NESTED LOOPS | 1 | 829 | | | 1 | | | | | | | | 186 | STATISTICS COLLECTOR | | | 1 | +6 | 1 | 0 | | | | | | | 187 | TABLE ACCESS BY INDEX ROWID BATCHED | 1 | 827 | 1 | +6 | 1 | 10016 | | | | | | | 188 | INDEX FULL SCAN | 10M | 26 | 1 | +6 | 1 | 231K | | | | | | | 189 | TABLE ACCESS BY INDEX ROWID BATCHED | 1 | 2 | | | | | | | | | | | 190 | INDEX RANGE SCAN | 1 | 1 | | | | | | | | | | | 191 | TABLE ACCESS BY INDEX ROWID BATCHED | 1 | 2 | 101880 | +6 | 1 | 1867 | 30 | 240KB | | | | | -> 192 | INDEX RANGE SCAN | 1 | 1 | 101908 | +6 | 1 | 1867 | 6 | 49152 | | | | | 193 | BUFFER SORT | 19030 | 3818 | 101899 | +6 | 7M | 4G | | | 2M | 16.11 | Cpu (4949) | | 194 | TABLE ACCESS BY INDEX ROWID BATCHED | 19030 | 2991 | 1 | +6 | 1 | 40523 | | | | | | | 195 | INDEX RANGE SCAN | 19030 | 87 | 1 | +6 | 1 | 40523 | | | | | | | 196 |/***/ INDEX UNIQUE SCAN | 1 | 2 | 101900 | +6 | 4G | 52M | | | | 79.83 | Cpu (24526) | | 197 | TABLE ACCESS BY INDEX ROWID | 18447P | 3 | 101868 | +6 | 52M | 1295 | 13 | 104KB | | 0.01 | Cpu (3) | ... ==============================================================================================================================================================================
— который неожиданно вернул 4G строк(/**/) и последующий NESTED LOOPS (/***/) успешно двигался по направлению to infinity and beyond
Тут, кроме нестыковок времени и статистики выполнения, в частности, указано всего 4M Buffer Gets (****) при очевидно куда большем потреблении этого ресурса, обращает внимание тот факт, что уже после всех адаптивных оптимизаций и реоптимизаций, CBO выполнил свой расчёт и как мог предупредил о предстоящей работе цифрами Rows (Estim): 12P и 18447P, а также итоговой оценкой стоимости > 1T
Можно предположить, что 12c Adaptive Features в связке с SQL Plan Management (SPM) представляют собой в определённом смысле альтернативный CBO механизм оптимизации , а CBO постепенно уходит со сцены, как это произошло в своё время с RBO. Т.е. адаптивные указания / директивы оказываются приоритетнее Cost-Based расчётов
Несколько замечаний по рассмотренному запросу:
1) как можно заметить из рез-тов первого скрипта запрос не разу не определяется ни как BIND_SENSE, ни как BIND_AWARE, несмотря на использование связанных переменных в запросе (*****), что вместе с другими признаками, в принципе, может намекать на неуспех/неперспективность технологии Adaptive Cursor Sharing (?)
2) там же видно, что после генерации неудачного child курсора №6 в 2015-10-22/00:52:41 на том же 2-м инстансе были сформированы вполне удачные CHILD 5 и 7 с нормальной стоимостью и секундным временем выполнения, что внушает сдержанную веру в идеи реоптимизации, сравнение деталей неудачного плана PHV=1663364961 и следующего адаптивного PHV=1064056405:
SQL> @sql_plan_diff_notes fwpd5tbgffy68 1663364961 fwpd5tbgffy68 1064056405
------------------------------
SQL Plan "Notes" sections diff
------------------------------
PHV_1663364961 PHV_1064056405
------------------------------- ------------------------------
sql_profile: sql_profile:
sql_patch: sql_patch:
baseline: baseline:
outline: outline:
dyn_sampling: 2 dyn_sampling: 2
dop: dop:
dop_reason: dop_reason:
card_feedback: yes card_feedback: yes
perf_feedback: perf_feedback:
adaptive_plan: yes adaptive_plan: yes
spd_used: 3 spd_used: 5
spd_valid: 41 spd_valid: 40
gtt_sess_stat: gtt_sess_stat:
db_version: 12.1.0.2 db_version: 12.1.0.2
plan_hash_full: 3818626266 plan_hash_full: 2707264861
plan_hash: 1663364961 plan_hash: 1064056405
plan_hash_2: 1522739251 plan_hash_2: 2765309730
Далее предположив, что картезиаский джойн всему виной (не в смысле скорости самой операции, а в плане низкой предсказуемости рез-тов) и отключив опцию на уровне запроса:
SQL> @sqlpatch+
&SQL_ID: fwpd5tbgffy68
&SQL_PATCH_TEXT: opt_param(''_optimizer_mjc_enabled'' ''false'')
&SQL_PATCH_NAME: APPSUP-225460
PL/SQL procedure successfully completed
SQL_ID NAME CATEGORY CREATED STATUS FMATCH
------------- ------------------------------ ------------------------------ --------------------- -------- ------
fwpd5tbgffy68 APPSUP-225460 DEFAULT 23.10.2015 13:39:02 ENABLED NO
SQL_PATCH_HINTS
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
opt_param('_optimizer_mjc_enabled' 'false')
SQL> @spm_check4sql_id fwpd5tbgffy68
SIGNATURE SPM_TYPE SQL_HANDLE PATCH_NAME ORIGIN VERSION LAST_MODIFIED ENABLED ACCEPTED FIXED REPRODUCED AUTOPURGE
--------------------- --------- -------------------- ------------- -------------- ---------- ------------------- ------- -------- ----- ---------- ---------
2315302924519493549 SQL Patch SQL_20219bbe2b684fad APPSUP-225460 MANUAL-SQLTUNE 12.1.0.2.0 23.10.2015 13:39:02 YES NO NO YES NO
можно видеть, что предположение работает в части улучшения времени выполнения:
SQL> @shared_cu12_noxml fwpd5tbgffy68 INST EXECS USERS_OPENING FIRST_LOAD_TIME LAST_LOAD_TIME PARSE_USER LAST_ACTIVE_TIME ELA_PER_EXEC CURSOR_STATUS PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE USE_FEEDBACK_STATS REOPT REOPT_HINTS ADAPT SPD_Valid SPD_Used DS_LEVEL REASON#1 SQL_PATCH ---- ----- ------------- -------------------- -------------------- ---------- ------------------- ------------ ------------- --------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----- --------- --------- -------- --------------------------------- ------------- 2 1 0 2015-10-16/00:48:46 2015-10-23/01:12:00 APPS 23.10.2015 01:12:01 1184060 VALID 840067654 235 5 N N N Y Y 11 Y 40 5 2 Auto Reoptimization Mismatch(1) 2 10 0 2015-10-16/00:48:46 2015-10-23/01:20:05 APPS 23.10.2015 01:36:53 3232426 VALID 1064056405 2226 7 N N Y N N Y 40 5 2 SQL Tune Base Object Different(3) 2 41 0 2015-10-16/00:48:46 2015-10-23/15:31:13 APPS 23.10.2015 15:33:20 1219371 VALID 1702667717 255 0 N N N Y Y 11 Y 43 2 2 Auto Reoptimization Mismatch(1) APPSUP-225460 2 21 0 2015-10-16/00:48:46 2015-10-23/15:31:30 APPS 23.10.2015 15:34:10 2952382 VALID 260608790 1,044923697162 1 N N N Y Y 26 Y 43 2 2 Auto Reoptimization Mismatch(1) APPSUP-225460 2 20 0 2015-10-16/00:48:46 2015-10-23/15:33:09 APPS 23.10.2015 15:34:42 799230 VALID 2490206822 8125206759 2 N N N Y Y 36 Y 41 3 2 Auto Reoptimization Mismatch(1) APPSUP-225460 2 21 0 2015-10-16/00:48:46 2015-10-23/15:33:51 APPS 23.10.2015 15:36:04 789979 VALID 3688023206 33599945 3 N N N Y Y 39 Y 41 3 2 Auto Reoptimization Mismatch(1) APPSUP-225460 2 21 0 2015-10-16/00:48:46 2015-10-23/15:34:38 APPS 23.10.2015 15:37:02 852862 VALID 735600476 32083069 4 N N Y Y Y 41 Y 41 3 2 Auto Reoptimization Mismatch(1) APPSUP-225460
— но не в части стоимости! Child 1 со ср.временем выполнения ~3 секунд (2,952,382 мкс) имеет выдающуюся стоимость:
SQL> SELECT * FROM TABLE(dbms_xplan.display_awr('fwpd5tbgffy68',260608790));
SQL_ID fwpd5tbgffy68
--------------------
Plan hash value: 260608790
----------------------------------------------------------------------------------------------------------
| Id | Operation | Rows | Bytes |TempSpc| Cost (%CPU)| Time |
----------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 71P(100)| |
| 1 | FILTER | | | | | |
| 2 | HASH JOIN OUTER | 3082 | 4322K| | 71P(100)|999:59:59 |
| 3 | HASH JOIN | 4 | 5468 | | 71P(100)|999:59:59 |
...
----------------------------------------------------------------------------------------------------------
Note
-----
- dynamic statistics used: dynamic sampling (level=2)
- statistics feedback used for this statement
- this is an adaptive plan
- 2 Sql Plan Directives used for this statement
— Cost ~ 71P в истории (для актуального курсора из Shared Pool dbms_xplan.display_cursor показывал 105P) со временем выполнения 999:59:59, что можно рассматривать как лишнее подтверждение неточности расчётов CBO для определённого типа запросов при имеющейся статистике, даже несмотря и применение адаптивного Dynamic Sampling странного уровня 2
Execllent blogs on 12c….thanks a lot for sharing
I see that you are using using some excellent sql scripts like shared_cu12_noxml. If you don’t mind can you please share those scripts.
— Yasser
комментарий от Yasser — 08.12.2015 @ 09:26
Thanks, Yasser
Of course, all my scripts are available by this periodically updated link
комментарий от Игорь Усольцев — 08.12.2015 @ 10:15
Здравствуйте, скажите пожалуйста, перешли на 12-ый оракл и испытали резкое проседание в производительности. Грешу на адаптивную оптимизацию. OPTIMIZER_ADAPTIVE_REPORTING_ONLY = TRUE не помог. optimizer_features_enable = 12.1.0.2 и optimizer_adaptive_features=TRUE Куда можно покопать? Куда взглянуть. На 11-ом было все отлично.
комментарий от Дмитрий — 26.02.2016 @ 12:26
Дмитрий, посмотрите в конце Oracle 12c Adaptive Soft Parse overhead есть пара запросов для оценки влияния адаптивных эффектов и Automatic Dynamic Sampling (ADS) 12c(последнее вероятнее)
OPTIMIZER_ADAPTIVE_REPORTING_ONLY отключает только использование адаптивных планов выполнения, оставляя в игре Statistics Feedback/Re-optimization и SQL Plan Directives/ADS, имхо, использование этих всех фич можно отключать/регулировать по-отдельности — 12c: управление адаптивными фичами
комментарий от Игорь Усольцев — 26.02.2016 @ 13:38