Oracle mechanics

23.03.2014

Определение SQL_ID/PLAN_HASH_VALUE для SPM Baseline

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

Внезапно замедлившиеся сессии при выполнении запроса 4y4bvy7bhkqbn согласованно ожидали read by other session / db file sequential read:

11.2.0.3.@ SQL> @ash_sql_wait_tree "event='read by other session' and ash.sql_id = '4y4bvy7bhkqbn'"
 
LVL INST_ID BLOCKING_TREE   EVENT                     WAITS_COUNT EXECS_COUNT AVG_WAIT_TIME_MS  EST_WAITS EST_AVG_LATENCY_MS SQL_ID       
--- ------- --------------- ------------------------- ----------- ----------- ---------------- ---------- ------------------ -------------
  1       1 FOREGROUND      read by other session            5297           8               35     651128                 17 4y4bvy7bhkqbn
  1       2 FOREGROUND      read by other session            1689           9               36      87337                 20 4y4bvy7bhkqbn
  2       1   FOREGROUND    db file sequential read          4921           8               37     429427                 23 4y4bvy7bhkqbn
  2       2   FOREGROUND    db file sequential read          1524          10               37      69937                 22 4y4bvy7bhkqbn
...

В историю выполнения обнаружилась нестабильность времени выполнения/планов запроса:

SQL> @dba_hist_sqlstat "sql_id = '4y4bvy7bhkqbn' and snap_id >= 64141 and executions_delta > 0"
 
INST    SNAP_ID BEGIN_SNAP_TIME EXECS SQL_ID               PLAN   COST ELA_PER_EXEC READ_MB_PER_EXEC IOWAITS_PER_EXEC
---- ---------- --------------- ----- -------------- ---------- ------ ------------ ---------------- ----------------
   1      65212 19.03 19:30         1 4y4bvy7bhkqbn  2284657640  85151  12365325840              732      11943939134
   2      65212 19.03 19:30         1 4y4bvy7bhkqbn  2284657640  85151   1115564811             1288       1094800275
   1      65210 19.03 18:30         1 4y4bvy7bhkqbn  2284657640  85151  15153230898             1211      14989630949
   2      65210 19.03 18:30         1 4y4bvy7bhkqbn  2284657640  85151    134584141               16          5372908
...
   2      65202 19.03 14:30         1 4y4bvy7bhkqbn  2284657640  85151    673675718              300        643385565
   1      64921 13.03 18:00       321 4y4bvy7bhkqbn  3948717229    690      1060372                0           696507 -- 1-й хороший план *
   2      64921 13.03 18:00       372 4y4bvy7bhkqbn  3948717229    690      1191965                0           786803
   2      64827 11.03 19:00         4 4y4bvy7bhkqbn  2284657640  30568   3961041370              146       3880494887
   2      64827 11.03 19:00         1 4y4bvy7bhkqbn  1218692124    688      8623864                8          8066787
   1      64825 11.03 18:00         1 4y4bvy7bhkqbn  2284657640  30568   6670487156              327       6617876873
   2      64825 11.03 18:00         1 4y4bvy7bhkqbn  2284657640  30568  12510991398              509      12412329565
...
   1      64821 11.03 16:00         1 4y4bvy7bhkqbn  2284657640  30568   1386784525              763       1369191473
   2      64813 11.03 12:00        13 4y4bvy7bhkqbn  3948717229    690      7497836                3          4404003
   2      64141 25.02 12:00         4 4y4bvy7bhkqbn  4232841616    699     19296237                0               22 -- 2-й хороший план **

— и поскольку отличия в значених связанных переменных были непринципиальны (NO skew data), а в случае частого выполнения (см.1-й хороший план) чаще выбирался быстрый план с временем выполнения ~ 1 сек., причиной замедления/изменения плана вполне могли стать прогрессивные технологии Adaptive Cursor Sharing (ибо запрос использует связанные переменные) или Cardinality Feedback (ибо применяется к сложным запросам независимо от использования связанных переменных), на что также намекает значение поля REASON1 из запроса к V$SQL_SHARED_CURSOR (и одно из значений USE_FEEDBACK_STATS):

SQL> @shared_cu 4y4bvy7bhkqbn
 
INST EXECS LAST_LOAD_TIME USERS_OPENING LAST_ACTIVE_TIME ELA_PER_EXEC PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS OPTIMIZER_STATS  BIND_EQ_FAILURE  REASON1                  
---- ----- -------------- ------------- ---------------- ------------ --------------- -------------- ----- ---------- ---------- ---------- ------------------ ---------------- ---------------- -------------------------
   1     1 19.03 17:25                1 19.03 19:02        5787759343      2284657640          85151     1 N          N          Y          N                  N                N                Optimizer mismatch(13)  |
   1     3 19.03 15:43                3 19.03 19:02       11322562518      2284657640          85151     0 N          N          Y          N                  N                N                Optimizer mismatch(13)  |
   1     3 19.03 17:53                3 19.03 19:02        2766754714      2284657640          85151     3 N          N          Y          N                  N                N                                         
   1     2 19.03 17:42                2 19.03 19:02        4781818089      2284657640          85151     2 N          N          Y          N                  N                N                                         
   2     1 19.03 18:44                0 19.03 18:46         134584141      2284657640          85151     1 N          N          Y          Y                  N                N                Optimizer mismatch(13)  |

Предположение подтверждает и «замечание» в плане ближайшего по времени, «1-го хорошего плана»:

SQL> SELECT * FROM TABLE(dbms_xplan.display_awr('4y4bvy7bhkqbn',3948717229));
...
Note
-----
   - cardinality feedback used for this statement

Поскольку план запроса не превышает 50 строк (т.е. не является сложногромоздким), его с достаточной вероятностью можно закрепить SPM Baseline-ом, предварительно удостоверившись, что в настоящее время Baseline-а для запроса не существует:

SQL> @bl_check4sql_id 4y4bvy7bhkqbn
 
no rows selected

Создаю Baseline из исторического «1-го хорошего плана» (как описано), после чего та же проверка показывает:

SQL> @bl_check4sql_id 4y4bvy7bhkqbn
 
SQL_HANDLE                     PLAN_NAME
------------------------------ ------------------------------
SQL_148cdf9124bc55dd           SQL_PLAN_1936zk4kbspfxee773f4d

Через некоторое время созданный Baseline начинает использоваться Oracle, успешно улучшая время выполнения запроса:

SQL> select * from dba_sql_plan_baselines where sql_handle = 'SQL_148cdf9124bc55dd';
 
SQL_HANDLE           SQL_TEXT                           PLAN_NAME                      ORIGIN      VERSION    CREATED               LAST_EXECUTED         ENABLED ACCEPTED FIXED REPRODUCED AUTOPURGE
-------------------- ---------------------------------- ------------------------------ ----------- ---------- --------------------- --------------------- ------- -------- ----- ---------- ---------
SQL_148cdf9124bc55dd select  nvl(decode(sign(accounted) SQL_PLAN_1936zk4kbspfxee773f4d MANUAL-LOAD 11.2.0.3.0 19-MAR-14 08.22.37 PM 20-MAR-14 03.25.03 PM YES     YES      YES   YES        NO       

SQL> @shared_cu 4y4bvy7bhkqbn
 
INST    EXECS LAST_LOAD_TIME USERS_OPENING LAST_ACTIVE_TIME ELA_PER_EXEC PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS OPTIMIZER_STATS  BIND_EQ_FAILURE REASON1                   SQL_PLAN_BASELINE             
---- -------- -------------- ------------- ---------------- ------------ --------------- -------------- ----- ---------- ---------- ---------- ------------------ ---------------- --------------- ------------------------- ------------------------------
   1       11 20.03 13:47                0 20.03 15:23            826588      3948717229            694     0 N          N          Y          N                  N                N               Optimizer mismatch(13)  | SQL_PLAN_1936zk4kbspfxee773f4d
   2       32 20.03 13:37                0 20.03 15:08            551939      3948717229            694     0 N          N          Y          N                  N                N                                         SQL_PLAN_1936zk4kbspfxee773f4d

— всё идёт по плану, но попутно возникает небесполезный теоретический вопрос — как определить sql_id/plan_hash_value существующего в системе Baseline-а?

Оригинальные варианты, найденные, например, у Marcin Przepiorowski показались недостаточно красивыми/убедительными и, кроме того, требующими «поднять» запрос в Shared Pool, как, например, при выполнении процедуры:

SQL> select * from table(dbms_xplan.DISPLAY_SQL_PLAN_BASELINE('SQL_148cdf9124bc55dd'));

— для получения PLAN_HASH_VALUE фактически (т.е. по трейсу) выполняется разбор запроса в соответствии с правилами Baseline с последующим закрытием курсора без следов выполнения выполнения:

PARSING IN CURSOR #139790476626776 len=2818 dep=1 uid=173 oct=3 lid=173 tim=1395310203516892 hv=1975862413 ad='a4b453050' sqlid='cpaggqpuwaj4d'
/* SQL Analyze(1819,0) */ select  nvl(decode(sign(accounted),1,accounted,0), 0) P_CUST_BAL,
...
PARSE #139790476626776:c=0,e=365,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=1395310203516892
WAIT #139790476626776: nam='library cache lock' ela= 222 handle address=44088393072 lock address=44371854352 100*mode+namespace=124785979883522 obj#=1718090 tim=1395310203517873
WAIT #139790476626776: nam='library cache pin' ela= 176 handle address=44088393072 pin address=44371854096 100*mode+namespace=124785979883522 obj#=1718090 tim=1395310203518129
...
CLOSE #139790476626776:c=0,e=4,dep=1,type=0,tim=1395310203555516

Кроме этого, в указанной заметке точно отмечается соответствие между DBA_SQL_PLAN_BASELINES.SQL_HANDLE и V$SQL.EXACT_MATCHING_SIGNATURE, что можно было бы использовать для определения sql_id/plan_hash_value соответствующего Baseline-а:

SQL> select distinct sql_id, plan_hash_value
  2    from gv$sqlarea
  3   where 'SQL_148cdf9124bc55dd' = 'SQL_' || ltrim(to_char(EXACT_MATCHING_SIGNATURE, 'xxxxxxxxxxxxxxxxxx'))
  4  union
  5  select distinct sql_id, plan_hash_value
  6    from dba_hist_sqlstat
  7   where 'SQL_148cdf9124bc55dd' = 'SQL_' || ltrim(to_char(FORCE_MATCHING_SIGNATURE, 'xxxxxxxxxxxxxxxxxx'))
  8  /
 
SQL_ID                                        PLAN_HASH_VALUE
------------------------------ ------------------------------
4y4bvy7bhkqbn                                       942988296
4y4bvy7bhkqbn                                      1218692124
4y4bvy7bhkqbn                                      1757799850
4y4bvy7bhkqbn                                      2284657640
4y4bvy7bhkqbn                                      2825342613
4y4bvy7bhkqbn                                      3948717229
4y4bvy7bhkqbn                                      4232841616
64uvzkjj8chz8                                      3948717229 -- лишний SQL_ID из GV$SQLAREA (не из истории) по причине отличий форматирования

— если бы запрос использовал лишь один план)

Написал скрипт определения SQL_ID/PLAN_HASH_VALUE по значению DBA_SQL_PLAN_BASELINES.SQL_HANDLE, сопоставляющий тексты запросов + содержимое списков подсказок (из секции Outline Data), составляющих планы действующих запросов (из V$SQL_PLAN и DBA_HIST_SQL_PLAN) с содержимым Baseline-ов — без необходимости повторного разбора и/или выполнения запроса — BL_FIND_SQL_ID.SQL

Однако выполнение моего скрипта для только что созданного Baseline выдавало сразу 2 соответствующих плана выполнения:

SQL> @bl_find_sql_id SQL_148cdf9124bc55dd
 
SQL_ID                                        PLAN_HASH_VALUE
------------------------------ ------------------------------
4y4bvy7bhkqbn                                      3948717229 -- 1-й хороший план **
4y4bvy7bhkqbn                                      4232841616 -- 2-й хороший план **

— что было несколько неожиданно, при этом планы отличались незначительно:

 -- 1-й хороший план **

|  38 | PARTITION RANGE SINGLE            |                               |KEY(AP)|KEY(AP)|
|  39 |  TABLE ACCESS BY LOCAL INDEX ROWID| XXXGL_BALANCES_BY_MONTH       |KEY(AP)|KEY(AP)|
|  40 |   INDEX RANGE SCAN                | XXXGL_BALANCES_BY_MONTH_N11   |KEY(AP)|KEY(AP)|

-- 2-й хороший план **

|  38 | TABLE ACCESS BY INDEX ROWID      | XXXGL_BALANCES_BY_MONTH        |
|  39 |  INDEX RANGE SCAN                | XXXGL_BALANCES_BY_MONTH_N1     |

— т.е. в «1-м хорошем плане» использовался локальный, а во 2-м (более старом) плане — глобальный индекс XXXGL_BALANCES_BY_MONTH_N1, не существующий в настоящий момент:

SQL> select index_name from dba_indexes where table_name = 'XXXGL_BALANCES_BY_MONTH';
 
INDEX_NAME
------------------------------
XXXGL_BALANCES_BY_MONTH_N21
XXXGL_BALANCES_BY_MONTH_N11

— глобальный индекс был эволюционно заменён на локальным XXXGL_BALANCES_BY_MONTH_N11, PLAN_HASH_VALUE (собственно план выполнения) при этом изменился при том же наборе определяющих план подсказок (Outline Data), в чём легко убедиться, сравнив содержимое Outline Data для обоих планов с помощью одного из Скриптов для сравнения планов выполнения:

SQL> @plan_ol_diff_awr 4y4bvy7bhkqbn 3948717229 4232841616 ""

no rows selected

— таким образом, один и тот же набор подсказок оптимизатора (представленный в секции outline обоих «хороших планов», и составляющий/зафиксированный с помощью SPM Baseline) допускает построение отличных планов (PLAN_HASH_VALUE) в зависимости от окружающих условий, в данном случае — от наличия и типа подходящего индекса

1 комментарий »

  1. Модифицировал скрипт, добавив опциональный входной параметр PLAN_NAME (для случая когда кол-во Baseline-ов > 1 для SQL_HANDLE), и разширил вывод скрипта временем последнего зафиксированного в DBA_SQL_PLAN_BASELINES использования (BL_EXEC_TIMESTAMP) и текущего статуса (BL_REPRODUCED) Baseline-а:

    SQL> @bl_find_sql_id SQL_148cdf9124bc55dd SQL_PLAN_1936zk4kbspfxee773f4d
    
    SQL_ID         PLAN_HASH_VALUE SQL_EXEC_TIMESTAMP   SQL_TYPE BL_EXEC_TIMESTAMP    BL_REPRODUCED
    ------------- ---------------- -------------------- -------- -------------------- -------------
    4y4bvy7bhkqbn       3948717229 26.03.2014 18:03:18  CURRENT  20.03.2014 09:25:03  YES           -- теперь легче определить, что именно этот план зафиксирован
    4y4bvy7bhkqbn       4232841616 25.02.2014 12:17:45  ARCHIVE                                     -- , а этот - просто совпадающий из архива

    комментарий от Игорь Усольцев — 26.03.2014 @ 19:06 | Ответить


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