Oracle mechanics

18.04.2016

ASH_SQLMON12S.SQL: блочный мониторинг длинных планов выполнения

Filed under: Active Session History,Oracle,Scripts — Игорь Усольцев @ 23:48
Tags: ,

Причины длительного выполнения запросов с обширным планом бывает непросто увидеть/определить как в связи объёмом, так и в связи с ненадёжностью / периодическим прерыванием функционирования DBMS_SQLTUNE.REPORT_SQL_MONITOR сообщениями типа:

Global Information
------------------------------
 Status                                 :  DONE (ERROR)

— для всё ещё продолжающих выполняться запросов

Идея скрипта проста — сгруппировать ASH строки по имени Query Block определённого плана выполнения, например так:

SQL> @ash_sqlmon12s 5ksw42mvwfr78 2751485074
 
LAST_PLSQL           ID    DISP  PLAN_OPERATION                                          QBLOCK_NAME   OBJECT_NAME                    CARDINALITY      BYTES       COST TEMP_SPACE  PX  ASH_ROWS MIN_SAMPLE_TIME     MAX_SAMPLE_TIME     WAIT_PROFILE 
-------------------- ----- ----- ------------------------------------------------------- ------------- ------------------------------ ----------- ---------- ---------- ---------- --- --------- ------------------- ------------------- -------------
Main Query               0    0    INSERT STATEMENT                                                                                                             2707375                                                                               
                         1    1      TEMP TABLE TRANSFORMATION                                                                                                                                                                                        
...
                       609  609              UNION-ALL                                   SET$8                                                                                                                                                        
                       610  610                COUNT STOPKEY                             SEL$092A3AC1                                                                                                                                                 
                       611  611                  MAT_VIEW ACCESS BY INDEX ROWID BATCHED  SEL$092A3AC1  FACTS_INTERNAL                           1         26          1              7     68101 11.04.2016 17:41:36 11.04.2016 20:53:26 ON CPU(68101)
                       612  612                    INDEX RANGE SCAN                      SEL$092A3AC1  DT_INDEX_FACTS                           1                     1              7     23776 11.04.2016 17:41:36 11.04.2016 20:53:26 ON CPU(23776)
                       613  613                      VIEW                                SEL$46BA7E08                                           1          6          2                                                                               
                       614  614                        TABLE ACCESS FULL                 SEL$46BA7E08  SYS_TEMP_0FDA00BE8_88879527              1         18          2                                                                               
...
                      1011 1011                              INDEX UNIQUE SCAN           SEL$91766163  MV_ANY_DELICIOUS_DISCOUNT_MPK2           1                     1                                                                               
Main SQL Stats                   ASH fixed 1 execs from 8 sessions                                                                                                                         91928 11.04.2016 17:41:36 11.04.2016 20:53:26
Stats by QBlock Name     0 1000                                                                                                                                                      2         7 11.04.2016 17:45:41 11.04.2016 20:23:19
Stats by QBlock Name   619  670                                                          SEL$E7587437                                                                                1         3 11.04.2016 17:50:00 11.04.2016 20:10:58
Stats by QBlock Name   633  668                                                          SEL$6CBAC421                                                                                7        41 11.04.2016 17:41:54 11.04.2016 20:51:19
Stats by QBlock Name   610  612                                                          SEL$092A3AC1                                                                                7     91877 11.04.2016 17:41:36 11.04.2016 20:53:26

— судя по статистике строки Main SQL Stats запрос выполняемся 3+ часа, при этом сгруппированная по блокам статистика выполнения Stats by QBlock Name очевидно указывает на блок SEL$092A3AC1, в котором и сосредоточена основная часть ASH активности

Теперь, зная QBlock Name и имея в активе SQL_ID и PLAN_HASH_VALUE быстрого выполнения запроса того же типа (SQL_ID запросов отличаются по причине добавления в запрос элемента случайности для стимулирования hard parse для каждого исполнении — что само по себе может быть неплохим методом CBO оптимизации редковыполняемых запросов) можно попробовать оценить отличия хорошего и плохого планов скриптом SQL_PLAN_DIFF.SQL для конкретного блока:

SQL> --             v медленный запрос       v быстрый запрос        v QBlock Name
SQL> @sql_plan_diff 5ksw42mvwfr78 2751485074 bbbnn8r2dq41w 723482314 SEL$092A3AC1
 
-------------------------------
SQL Plans [by Query block] diff
-------------------------------
 
PLAN_HASH_VALUE QBLOCK_NAME     ID OPERATION                                QBLOCK_NAME   OBJECT_ALIAS            OBJECT                               CARDINALITY  BYTES COST(IO) TEMP TIME
--------------- ------------- ---- ---------------------------------------- ------------- ----------------------- ------------------------------------ ----------- ------ -------- ---- ----
AWR_2751485074  SEL$092A3AC1   610 COUNT STOPKEY                            SEL$092A3AC1                                                                                  ()            
                SEL$092A3AC1   611  MAT_VIEW ACCESS BY INDEX ROWID BATCHED  SEL$092A3AC1  FACTS_INTERNAL@SEL$345  "JO"."FACTS_INTERNAL"                          1     26 1(1)             1
                SEL$092A3AC1   612   INDEX RANGE SCAN                       SEL$092A3AC1  FACTS_INTERNAL@SEL$345  "JO"."DT_INDEX_FACTS"                          1        1(1)             1
                SEL$46BA7E08   613    VIEW                                  SEL$46BA7E08  S_DATES@SEL$346                                                        1      6 2(2)             1
                SEL$46BA7E08   614     TABLE ACCESS FULL                    SEL$46BA7E08  T1@SEL$46BA7E08         "SYS"."SYS_TEMP_0FDA00BE8_88879527"            1     18 2(2)             1
--------------- -------------      ---------------------------------------- ------------- ----------------------- ------------------------------------                                  
AWR_723482314   SEL$092A3AC1   631 COUNT STOPKEY                            SEL$092A3AC1                                                                                  ()            
                SEL$092A3AC1   632  MAT_VIEW ACCESS BY INDEX ROWID BATCHED  SEL$092A3AC1  FACTS_INTERNAL@SEL$345  "JO"."FACTS_INTERNAL"                          1     26 1(1)             1
                SEL$092A3AC1   633   INDEX RANGE SCAN                       SEL$092A3AC1  FACTS_INTERNAL@SEL$345  "JO"."FACTS_INVOICE_ID_IDX"                    1        1(1)             1
                SEL$46BA7E08   634   VIEW                                   SEL$46BA7E08  S_DATES@SEL$346                                                        1      6 2(2)             1
                SEL$46BA7E08   635    TABLE ACCESS FULL                     SEL$46BA7E08  T1@SEL$46BA7E08         "SYS"."SYS_TEMP_0FD9FFAD5_88879527"            1     18 2(2)             1
 
------------------------------
SQL Plan "Notes" sections diff
------------------------------
 
PHV_2751485074                                               PHV_723482314
------------------------------------------------------------ ------------------------------------------------------------
                                                             
   sql_profile:                                                 sql_profile:
   sql_patch:                                                   sql_patch:
   baseline:                                                    baseline:
   outline:                                                     outline:
   dyn_sampling:    2                                           dyn_sampling:    2
   dop:             8                                           dop:             8
   dop_reason:      hint                                        dop_reason:      hint
   card_feedback:                                               card_feedback:
   perf_feedback:                                               perf_feedback:
   adaptive_plan:                                               adaptive_plan:
   spd_used:        3                                           spd_used:        2
   spd_valid:       12                                          spd_valid:       11
   gtt_sess_stat:                                               gtt_sess_stat:
   db_version:      12.1.0.2                                    db_version:      12.1.0.2
   plan_hash_full:  4086979989                                  plan_hash_full:  959870096
   plan_hash:       2751485074                                  plan_hash:       723482314
   plan_hash_2:     676128529                                   plan_hash_2:     616014436
 
 
--------------------------------
SQL Plan "Outline" sections diff
--------------------------------
 
PHV_2751485074                                                                    PHV_723482314
--------------------------------------------------------------------------------- ----------------------------------------------------------------------------------------
INDEX_RS_ASC(@"SEL$092A3AC1" "FACTS_INTERNAL"@"SEL$345" ("FACTS_INTERNAL"."DT"))  
                                                                                  INDEX_RS_ASC(@"SEL$092A3AC1" "FACTS_INTERNAL"@"SEL$345" ("FACTS_INTERNAL"."INVOICE_ID"))

— из чего просто заключить, что в рассматриваемом блоке хороший план от плохого отличается индексом, а использование быстрого для этого запроса индекса можно форсировать при след.запуске(*):

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('bwy903fg3guqb',0,format => 'all allstats -projection'));

SQL_ID  bwy903fg3guqb, child number 0
-------------------------------------
insert /*+ INDEX(@"SEL$092A3AC1" "FACTS_INTERNAL"@"SEL$345"("FACTS_INTERNAL"."INVOICE_ID")) */...  -- например, так*
 
Plan hash value: 2073117071
 
-----------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                       | Name                           | E-Rows |E-Bytes|E-Temp | Cost (%CPU)| E-Time   |    TQ  |IN-OUT|
-----------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | INSERT STATEMENT                                |                                |        |       |       |  5483K(100)|          |        |      |

| 621 |                  VIEW                           |                                |   1796 |   126K|       | 15385   (1)| 00:00:02 |  28,80 | PCWP |
| 622 |                   UNION-ALL                     |                                |        |       |       |            |          |  28,80 | PCWP |
|*623 |                    COUNT STOPKEY                |                                |        |       |       |            |          |  28,80 | PCWP |
|*624 | WID BATCHED         MAT_VIEW ACCESS BY INDEX RO | FACTS_INTERNAL                 |      1 |    26 |       |     1   (0)| 00:00:01 |  28,80 | PCWP |
|*625 |                      INDEX RANGE SCAN           | FACTS_INVOICE_ID_IDX           |      1 |       |       |     1   (0)| 00:00:01 |  28,80 | PCWP |
| 626 |                      VIEW                       |                                |      1 |     6 |       |     2   (0)| 00:00:01 |        |      |
| 627 |                       TABLE ACCESS FULL         | SYS_TEMP_0FDA00F5B_88879527    |      1 |    18 |       |     2   (0)| 00:00:01 |        |      |

|1034 |                           INDEX UNIQUE SCAN     | MV_ANY_DELICIOUS_DISCOUNT_MPK2 |      1 |       |       |     1   (0)| 00:00:01 |  28,56 | PCWP |
-----------------------------------------------------------------------------------------------------------------------------------------------------------
 
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------

 623 - SEL$092A3AC1
 624 - SEL$092A3AC1 / FACTS_INTERNAL@SEL$345
 625 - SEL$092A3AC1 / FACTS_INTERNAL@SEL$345

Predicate Information (identified by operation id):
---------------------------------------------------

 620 - access(:Z>=:Z AND :Z<=:Z)
 623 - filter(ROWNUM=1)
 624 - filter(("HIDDEN"<4 AND "TYPE"='generic' AND "DT"<))
 625 - access("INVOICE_ID"=:B1)

Note
-----
   - dynamic statistics used: dynamic sampling (level=2)
   - Degree of Parallelism is 8 because of hint
   - 4 Sql Plan Directives used for this statement

— и, кроме использования нужного индекса, получить разумное время выполнения (отражаемое в Main SQL Stats в виде MAX_SAMPLE_TIME — MIN_SAMPLE_TIME) ~ 15 минут против 3+ часов:

SQL> @ash_sqlmon12s bwy903fg3guqb 2073117071
 
LAST_PLSQL            ID    DISP  PLAN_OPERATION                                    QBLOCK_NAME     COST  ASH_ROWS MIN_SAMPLE_TIME     MAX_SAMPLE_TIME     WAIT_PROFILE
--------------------- ----- ----- ------------------------------------------------- ------------ ------- --------- ------------------- ------------------- ------------ 
Main Query                0    0    INSERT STATEMENT                                             5483491         5 11.04.2016 23:56:34 11.04.2016 23:58:56 ON CPU(5)
...
                        622  622        UNION-ALL                                   SET$8                                                                                                                                                                                                                                                                           
                        623  623          COUNT STOPKEY                             SEL$092A3AC1                 2 12.04.2016 0:02:56  12.04.2016 0:02:57  ON CPU(2)                                                                                                                                                                                                
                        624  624            MAT_VIEW ACCESS BY INDEX ROWID BATCHED  SEL$092A3AC1       1         1 12.04.2016 0:03:00  12.04.2016 0:03:00  ON CPU(1)                                                                                                                                                                                                
                        625  625              INDEX RANGE SCAN                      SEL$092A3AC1       1         4 12.04.2016 0:02:56  12.04.2016 0:02:57  ON CPU(4)                                                                                                                                                                                                
...
                       1034 1034                        INDEX UNIQUE SCAN           SEL$91766163       1         3 12.04.2016 0:00:57  12.04.2016 0:00:59  ON CPU(3)                                                                                                                                                                                                
Main SQL Stats                    ASH fixed 1 execs from 171 sessions                                         7852 11.04.2016 23:53:33 12.04.2016 0:08:43                                                                                                                                                                                                           
Stats by QBlock Name      0 1023                                                                              2859 11.04.2016 23:53:33 12.04.2016 0:08:40                                                                                                                                                                                                           
Stats by QBlock Name    397  411                                                    SEL$A7295DBC                 1 12.04.2016 0:01:05  12.04.2016 0:01:05                                                                                                                                                                                                           
...
Stats by QBlock Name    507  507                                                    SEL$187                     22 11.04.2016 23:54:35 11.04.2016 23:55:00                                                                                                                                                                                                          
Stats by QBlock Name    649  684                                                    SEL$6CBAC421              1438 11.04.2016 23:59:34 12.04.2016 0:02:51                                                                                                                                                                                                           
Stats by QBlock Name    789  790                                                    SEL$84FBED01                 2 12.04.2016 0:04:01  12.04.2016 0:04:05                                                                                                                                                                                                           
...
Stats by QBlock Name    623  625                                                    SEL$092A3AC1                 7 12.04.2016 0:02:56  12.04.2016 0:03:00                                                                                                                                                                                                           
...
Stats by QBlock Name    583  618                                                    SEL$93C10A84              1513 11.04.2016 23:55:36 11.04.2016 23:58:38                                                                                                                                                                                                          
...
Stats by QBlock Name    47    85                                                    SEL$8A0C09A4               574 11.04.2016 23:53:34 11.04.2016 23:54:11                                                                                                                                                                                                          
...

— с более равномерным распределением ASH активности по блокам плана, и т.д и т.п…

Интересно также отметить, что стоимость получившегося плана в 2 с небольшим раза превышает стоимость первого «медленного» плана — для крупных планов Cost имхо по причинам сложности (и напряжённости вычислений)) не имеет большого значения

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

  1. Игорь, скажите а где можно взять этот скрипт? часть скриптов которые вы используете в своих статьях (shared_cu12_noxml ,ash_sql_lock_hist скажем) — их нет в разделе Scripts. Это связано с тем что вы не планируете их пока обнародовать или просто пока на это времени?

    комментарий от Вячеслав — 17.05.2016 @ 10:38 | Ответить

    • Вячеслав, все скрипты можно найти на странице Scripts — там первая ссылка на zip со всеми скриптами, который я периодически обновляю

      комментарий от Игорь Усольцев — 17.05.2016 @ 11:48 | Ответить


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