Oracle mechanics

28.10.2015

12c: адаптивная оптимизация и CBO

Filed under: CBO,Oracle — Игорь Усольцев @ 00:20
Tags: ,

С удивлением надлюдал поведение стандартного запроса приложения 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

4 комментария »

  1. 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 | Ответить

  2. Здравствуйте, скажите пожалуйста, перешли на 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 | Ответить


RSS feed for comments on this post. TrackBack URI

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

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

Логотип WordPress.com

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

Фотография Twitter

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

Фотография Facebook

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

Google+ photo

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

Connecting to %s

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

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