Oracle mechanics

26.07.2015

Одиночное выполнение SQL запроса с несколькими SQL_EXEC_ID и различными планами

Filed under: heuristics,Oracle,SQL Tuning — Игорь Усольцев @ 00:46
Tags: ,

В процессе совместного с Евгением Калининым тестирования с целью стандартизации/оптимизации времени выполнения запроса посчастливилось наблюдать диво дивное нечасто встречающееся событие: выполнение одного запроса очевидно затягивалось по причине периодической инвалидации используемого курсора, следом генеровался новый курсор (с новым планом) и начинал выполняться с начала, при этом со стороны запускающего приложения выполнение запроса не прерывалось, просто затянулось на 1,5 часа вместо обычных 20 минут:

12.1.0.2@ SQL> select nvl(qc_session_id, session_id) sid,
  2         nvl(qc_session_serial#, session_serial#) serial#,
  3         sql_exec_id,
  4         sql_child_number                    as CHILD,
  5         sql_plan_hash_value                 as PHV,
  6         sql_full_plan_hash_value            as FPHV,
  7         min(sample_time),
  8         max(sample_time),
  9         count(*)                            as ASH_ROWS,
 10         count(distinct session_id) - 1      as PX_COUNT,
 11         max(sample_time) - min(sample_time) as DURATION
 12    from v$active_session_history
 13   where module = 'sqlplus.exe'
 14     and sql_id = '5s0w4cubz5yyt'
 15     and sql_child_number >= 0
 16   group by nvl(qc_session_id, session_id),
 17            nvl(qc_session_serial#, session_serial#),
 18            sql_exec_id,
 19            sql_child_number,
 20            sql_plan_hash_value,
 21            sql_full_plan_hash_value
 22   order by max(sample_time)
 23  /
 
 SID SERIAL# SQL_EXEC_ID CHILD        PHV       FPHV MIN(SAMPLE_TIME)       MAX(SAMPLE_TIME)       ASH_ROWS PX DURATION
 --- ------- ----------- ----- ---------- ---------- ---------------------- ---------------------- -------- -- -------------------
  43    2250    16777216     0 1177121823 1348556722 21.07.15 14:56:58,291  21.07.15 15:15:56,736      3802  8 +000000000 00:18:58
  43    2250                 1  598640444 1944960939 21.07.15 15:15:57,736  21.07.15 15:15:58,736         2  1 +000000000 00:00:01
  43    2250                 1 2027645636 2114082327 21.07.15 15:15:59,736  21.07.15 15:16:13,736        15  0 +000000000 00:00:14
  43    2250                 1 2864496871 3345652639 21.07.15 15:16:14,736  21.07.15 15:16:27,736        14  0 +000000000 00:00:13
  43    2250                 0 1852732831 4122082463 21.07.15 15:16:28,736  21.07.15 15:16:28,736         1  0 +000000000 00:00:00
--43    2250                 1          0          0 21.07.15 15:54:16,636  21.07.15 15:54:30,646        15  0 +000000000 00:00:14
--43    2250                 3 3013780789 4105931067 21.07.15 15:55:48,694  21.07.15 15:56:00,694        13  0 +000000000 00:00:12
--43    2250                 2  667538297 1913179438 21.07.15 15:56:28,694  21.07.15 15:58:23,740         4  2 +000000000 00:01:55
--43    2250                 2 3013780789 4105931067 21.07.15 15:55:18,674  21.07.15 15:59:47,777       112  5 +000000000 00:04:29
--43    2250                 1  667538297 1913179438 21.07.15 15:27:52,024  21.07.15 16:00:50,807        16  5 +000000000 00:32:58
--43    2250                 1 3013780789 4105931067 21.07.15 15:27:53,024  21.07.15 16:01:17,807       332  6 +000000000 00:33:24
--43    2250                 0          0 4122082463 21.07.15 16:11:06,080  21.07.15 16:11:06,080         4  3 +000000000 00:00:00
  43    2250    16777217     0 1852732831 4122082463 21.07.15 15:16:29,736  21.07.15 16:11:06,080      7198  8 +000000000 00:54:36
  43    2250    16777218     0 2628977128  173302026 21.07.15 16:11:07,080  21.07.15 16:16:07,196       630  8 +000000000 00:05:00

— SID, SERIAL# я вывел, чтобы показать принадлежность одной сессии, а по незакомментированным записям ASH можно наблюдать непрерывность процесса. После начала выполнения третьего по счёту SQL_EXEC_ID = 16777218 процесс был прерван, поведение запроса было стабильным и легко воспроизводилось, например с помощью SQL*Plus

Пара снимков V$SQL_SHARED_CURSOR, сделанных в процессе этого выполнения подтверждают, что скорее всего наблюдалась именно инвалидация курсоров ибо все действующие курсоры имели CHILD_NUMBER = 0 и не сосуществовали в Shared Pool:

SQL> @shared_cu12_noxml 5s0w4cubz5yyt
 
EXECS USERS_OPENING FIRST_LOAD_TIME      LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CURSOR_STATUS  PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS REOPT REOPT_HINTS ADAPT SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON OPTIMIZER_STATS  BIND_EQ_FAILURE  ROLL REASON#1
----- ------------- -------------------- -------------------- ------------------- ------------ -------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----- --------- --------- -------- --- ---------- ---------------- ---------------- ---- --------
    0             9 2015-07-21/14:56:57  2015-07-21/14:56:57  21.07.2015 15:08:37   2184806362 INVALID_UNAUTH      1177121823           1348556722        5871284     0 N          N          Y          N                  N                                                    4   hint       N                N                N            
 
SQL> @shared_cu12_noxml 5s0w4cubz5yyt
 
EXECS USERS_OPENING FIRST_LOAD_TIME      LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CURSOR_STATUS  PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS REOPT REOPT_HINTS ADAPT SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON OPTIMIZER_STATS  BIND_EQ_FAILURE  ROLL REASON#1
----- ------------- -------------------- -------------------- ------------------- ------------ -------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----- --------- --------- -------- --- ---------- ---------------- ---------------- ---- --------
    1             0 2015-07-21/14:56:57  2015-07-21/16:11:05  21.07.2015 16:16:07    633283193 VALID               2628977128            173302026        6040233     0 N          N          Y          N                  N                                                    4   hint       N                N                N            

— необычно то, что при намеренно выключенных адаптивных эффектах 12c (OPTIMIZER_ADAPTIVE_FEATURES = FALSE) в поле V$SQL_SHARED_CURSOR.REASON
на этом этапе ничего интересного не наблюдалось, т.е. похоже на какой-то редкий случай типа недоказанного (видимо, от усталоссти) Bug 20137221 : LONG RUNNING SQL STATEMENT DUE TO MULTIPLE INVALIDATIONS/RELOADS или Insert Statement On Partitioned Tables Is RE-Started After Invalidation (Doc ID 1462003.1), что, вероятно, ближе к рассматриваемому случаю, поскольку запрос представлял собой обыкновенный CONVENTIONAL (не direct-path) INSERT в партицированную таблицу с параллельным планом выполнения объёмом ~1000 строк

Из описания соотв.Bug 14102209 : INSERT STATEMENT IS RESTARTING BY ITSELF AFTER INVALIDATION можно узнать несколько любопытных фактов:)

This mechanism is there to guarantee insert correctness, that
the inserted rows really go into the correct partition. This
mechanism only comes into play for inserts into partitioned
tables. It should not affect inserts into a non-partitioned
temp table.

Therefore a work around should be to use a two stage process:
First insert the rows into a temp table.
Second insert into the partitioned table as select from temp.

Особенно понравилось:

There is no a way of determining exactly what changed in the metadata, and
for this reason, the problem cannot be addressed as a bug fix. Changes
required for addressing this issue would be extensive — something that can
only be addressed in the 12.2 timeframe at this point

— хорошо, материя тёмная, но Oracle говорит, что проблема в партицированной таблице, повторяем тест на НЕпартицированной таблице и опять получаем второй SQL_EXEC_ID без прерывания выполнения:

SQL> select nvl(qc_session_id, session_id) sid,
  2         nvl(qc_session_serial#, session_serial#) serial#,
  3         sql_id,
  4         sql_exec_id,
  5         sql_child_number as CHILD,
  6         sql_plan_hash_value as PHV,
  7         sql_full_plan_hash_value as FPHV,
  8         count(*),
  9         count(distinct session_id) - 1 as PX,
 10         min(sample_time) as MIN_SAMPLE_TIME,
 11         max(sample_time) as MAX_SAMPLE_TIME,
 12         max(sample_time) - min(sample_time) as DURATION
 13    from v$active_session_history
 14   where module like 'calc:%' and sample_time > trunc(sysdate)+10/24
 15     and (nvl(qc_session_id, session_id),nvl(qc_session_serial#, session_serial#)) in ((710,61424))
 16   group by nvl(qc_session_id, session_id),
 17            nvl(qc_session_serial#, session_serial#),
 18            sql_id,
 19            sql_exec_id,
 20            sql_child_number,
 21            sql_plan_hash_value,
 22            sql_full_plan_hash_value
 23   order by max(sample_time)
 24  /
 
SID    SERIAL# SQL_ID        SQL_EXEC_ID CHILD        PHV       FPHV   COUNT(*)  PX MIN_SAMPLE_TIME   MAX_SAMPLE_TIME  DURATION
--- ---------- ------------- ----------- ----- ---------- ---------- ---------- --- ----------------- ---------------- ------------
710      61424 4d0gaxcnkytvy                 4 1743174890 4166744448         12   0 02.31.48.234 PM   02.31.59.231 PM  00:00:10.997
710      61424 4d0gaxcnkytvy                 4   37057858 4216621503         13   0 02.45.45.545 PM   02.45.57.551 PM  00:00:12.006
710      61424 4d0gaxcnkytvy                 1 1743174890 4166744448        400  15 02.21.19.980 PM   02.57.05.805 PM  00:35:45.825
710      61424 4d0gaxcnkytvy                 3 1743174890 4166744448        130   9 02.21.43.000 PM   02.58.48.862 PM  00:37:05.862
710      61424 4d0gaxcnkytvy                 2 1743174890 4166744448        427  16 02.21.30.980 PM   03.00.17.879 PM  00:38:46.899
710      61424 4d0gaxcnkytvy                 3   37057858 4216621503         96   4 02.23.21.016 PM   03.00.45.899 PM  00:37:24.883
710      61424 4d0gaxcnkytvy                 0 1723488966 1936819223      16668  22 02.21.07.980 PM   03.00.58.899 PM  00:39:50.919
710      61424 4d0gaxcnkytvy                 2   37057858 4216621503        402  15 02.23.48.036 PM   03.00.58.899 PM  00:37:10.863
710      61424 4d0gaxcnkytvy                 1   37057858 4216621503        592  16 02.22.05.996 PM   03.01.12.909 PM  00:39:06.913
710      61424 4d0gaxcnkytvy    16777221     0 1723488966 1936819223        814   0 02.24.40.074 PM   03.09.28.086 PM  00:44:48.012
710      61424 4d0gaxcnkytvy                 1 1012325131 2715365581         13   0 03.09.29.086 PM   03.09.41.106 PM  00:00:12.020
710      61424 4d0gaxcnkytvy                 3 2368119228 3517088034         13   0 03.11.07.142 PM   03.11.19.142 PM  00:00:12.000
710      61424 4d0gaxcnkytvy                -1 3615433771 3168271419       2077  14 03.09.29.086 PM   03.14.43.225 PM  00:05:14.139
710      61424 4d0gaxcnkytvy                 2 2368119228 3517088034         66   4 03.11.58.159 PM   03.15.50.251 PM  00:03:52.092
...
710      61424 4d0gaxcnkytvy    16777222     0 3583395179  160132217       1091   0 03.19.52.346 PM   04.09.50.504 PM  00:49:58.158 -- bingo
 
38 rows selected

при вставке в переделанную уже без партиций таблицу:

SQL> select sql_text from v$sql where sql_id = '4d0gaxcnkytvy';
 
SQL_TEXT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
insert /*+ parallel(8) opt_param('optimizer_adaptive_features' 'false') opt_param('optimizer_dynamic_sampling' 0) */into t_target select s.*, :d1 as insert_dt  from v_source s
 
SQL> select partitioned from dba_tables where table_name = 'T_COMM_PROF_SRC';
 
PARTITIONED
-----------
NO

, при этом основным состоянием процессов наблюдалось ожидание на cursor: pin S wait on X:

SQL> select nvl(qc_session_id, session_id) sid,
  2         nvl(qc_session_serial#, session_serial#) serial#,
  3         session_state || ' ' || event as state,
  4         in_parse,
  5         in_hard_parse,
  6         in_sql_execution,
  7         count(*),
  8         count(distinct session_id) - 1 as PX
  9    from gv$active_session_history
 10   where sql_id = '4d0gaxcnkytvy'
 11     and (nvl(qc_session_id, session_id),nvl(qc_session_serial#, session_serial#)) in ((710,61424))
 12   group by nvl(qc_session_id, session_id),
 13            nvl(qc_session_serial#, session_serial#),
 14            session_state || ' ' || event,
 15            in_parse,
 16            in_hard_parse,
 17            in_sql_execution
 18   order by count(*) desc
 19  /
 
STATE                            IN_PARSE IN_HARD_PARSE IN_SQL_EXECUTION   COUNT(*)         PX
-------------------------------- -------- ------------- ---------------- ---------- ----------
WAITING cursor: pin S wait on X  Y        N             N                     26207         34
ON CPU                           Y        Y             Y                      3728         35
ON CPU                           N        N             Y                      3371          0
WAITING direct path read temp    N        N             Y                       332          0
WAITING db file sequential read  N        N             Y                       109          0
WAITING db file parallel read    N        N             Y                        47          0
...

, с профилем ожиданий, при котором PX-процессы постоянно блокировали друг друга на этапе IN_PARSE:

SQL> @ash_sql_wait_tree "sql_id = '4d0gaxcnkytvy' and event = 'cursor: pin S wait on X'" 0
 
LVL BLOCKING_TREE        EVENT                     WAITS_COUNT EXECS_COUNT AVG_WA  SESS_COUNT PLSQL_OBJECT_ID          DATA_OBJECT                                          BLOCK_SID      SQL_ID        SQL_PLAN_LINE_ID SQL_PLAN_OPERATION
--- -------------------- ------------------------- ----------- ----------- ------ ----------- ------------------------ ---------------------------------------------------- -------------- ------------- ---------------- ------------------
  1 (P...)               cursor: pin S wait on X          7799           0    983          91 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  1 (P...)               cursor: pin S wait on X          1850           0    977          23 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                                    
  2   (P...)             On CPU / runqueue               26324           0      0         110 ..                       ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  2   (P...)             cursor: pin S wait on X          1115           0   4910          81 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  2   (P...)             cursor: pin S wait on X           377           0   4187          19 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                                    
  2   (P...)             library cache lock                244           0   5313          28 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  2   (P...)             db file scattered read             59           0      1           4 ..                       ..                                                   NO HOLDER i#   4d0gaxcnkytvy                                    
  2   (P...)             On CPU / runqueue                  29           0      0           1 ..                       SYS.WRH$_SQLSTAT_INDEX.WRH$_SQLSTA_1241709836_65012  NOT IN WAIT i# 4d0gaxcnkytvy                                    
  2   (P...)             On CPU / runqueue                  26           0      0           1 SYS.DBMS_STATS.GET_PREFS ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  2   (P...)             gc cr multi block request          18           0      0           2 ..                       ..                                                   UNKNOWN i#     4d0gaxcnkytvy                                    
  2   (P...)             kksfbc child completion             6           0     51           1 ..                       ..                                                   UNKNOWN i#     4d0gaxcnkytvy                0 INSERT STATEMENT  
  2   (P...)             db file sequential read             3           0      1           1 ..                       SYS.WRH$_SQLSTAT_INDEX.WRH$_SQLSTA_1241709836_65012  NO HOLDER i#   4d0gaxcnkytvy                                    
  3     (P...)           On CPU / runqueue                2531           0      0         103 ..                       ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  3     (P...)           cursor: pin S wait on X           473           0   3195          35 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  3     (P...)           cursor: pin S wait on X           193           0   3592          10 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                                    
  3     (P...)           library cache lock                158           0   3633          18 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  3     (P...)           db file scattered read             19           0      2           2 ..                       ..                                                   NO HOLDER i#   4d0gaxcnkytvy                                    
  3     (P...)           On CPU / runqueue                  13           0      0           1 SYS.DBMS_STATS.GET_PREFS ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  3     (P...)           gc cr multi block request           6           0      0           2 ..                       ..                                                   UNKNOWN i#     4d0gaxcnkytvy                                    
  3     (P...)           kksfbc child completion             5           0     51           1 ..                       ..                                                   UNKNOWN i#     4d0gaxcnkytvy                0 INSERT STATEMENT  
  4       (P...)         On CPU / runqueue                1114           0      0          52 ..                       ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  4       (P...)         cursor: pin S wait on X           270           0   1317          19 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  4       (P...)         cursor: pin S wait on X           102           0   2282           6 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                                    
  4       (P...)         library cache lock                 83           0   3676           7 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  4       (P...)         On CPU / runqueue                   6           0      0           1 SYS.DBMS_STATS.GET_PREFS ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  5         (P...)       On CPU / runqueue                 605           0      0          32 ..                       ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  5         (P...)       cursor: pin S wait on X           146           0   2278          13 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  5         (P...)       library cache lock                 49           0   4168           4 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  5         (P...)       cursor: pin S wait on X            44           0   4647           3 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                                    
  5         (P...)       On CPU / runqueue                   7           0      0           1 SYS.DBMS_STATS.GET_PREFS ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  6           (P...)     On CPU / runqueue                 347           0      0          15 ..                       ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  6           (P...)     cursor: pin S wait on X            61           0   2989           5 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  6           (P...)     On CPU / runqueue                   7           0      0           1 SYS.DBMS_STATS.GET_PREFS ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  7             (P...)   On CPU / runqueue                  98           0      0           4 ..                       ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy                                    
  7             (P...)   cursor: pin S wait on X            11           0  13912           1 ..                       ..                                                   VALID i#2      4d0gaxcnkytvy                0 INSERT STATEMENT  
  8               (P...) On CPU / runqueue                  22           0      0           1 ..                       ..                                                   NOT IN WAIT i# 4d0gaxcnkytvy

и следующими типичными блокировками/ожиданиями Shared Pool:

SQL> @kgllockpin
 
HANDLER          KGLLKTYPE  NAMESP          KGLOBTYD  KGLNAOWN  KGLNAOBJ          MODE_HELD  MODE_REQ   SECS_IN_WAIT EVENT                 SECONDS_IN_WAIT SID    SERIAL  SADDR            PROGRAM                     SQL_ID
---------------- ---------- --------------- --------- --------- ----------------- ---------- ---------- ------------ --------------------- --------------- ------ ------- ---------------- --------------------------- -------------
00000016DDFD3A38 Lock       SQL AREA BUILD  CURSOR    $BUILD$   4e66ea688730b93b  None       Share      10           library cache lock                 10 1177   46870   0000001811120050 oracle@hostname1.ru (P000)  4d0gaxcnkytvy
00000016DDFD3A38 Lock       SQL AREA BUILD  CURSOR    $BUILD$   4e66ea688730b93b  Exclusive  None       2            gc current grant busy               2 355    46225   000000185114D430 oracle@hostname1.ru (P007)  4d0gaxcnkytvy
 
... 
 
LVL WAITING_SID PROGRAM                     SQL_ID        EVENT                   SECONDS_IN_WAIT BLOCKING_SID LC_SQL_ID     SID_HOLDING_MUTEX MUTEX_TYPE     MUTEX_LOCATION
--- ----------- --------------------------- ------------- ----------------------- --------------- ------------ ------------- ----------------- -------------- -------------------------
  1           7 oracle@hostname1.ru (P002)  4d0gaxcnkytvy cursor: pin S wait on X              11          355 4d0gaxcnkytvy               355 Cursor Pin     kkslce [KKSCHLPIN2]      
  1           7 oracle@hostname1.ru (P002)  4d0gaxcnkytvy cursor: pin S wait on X              11          355 4d0gaxcnkytvy               355 Cursor Parent  kksLoadChild [KKSPRTLOC5]
  1          45 oracle@hostname1.ru (P003)  4d0gaxcnkytvy cursor: pin S wait on X              11          355 4d0gaxcnkytvy               355 Cursor Pin     kkslce [KKSCHLPIN2]      
  1          45 oracle@hostname1.ru (P003)  4d0gaxcnkytvy cursor: pin S wait on X              11          355 4d0gaxcnkytvy               355 Cursor Parent  kksLoadChild [KKSPRTLOC5]
...

20 rows selected

, что также мало помогает решению проблемы

Единственной зацепкой может быть случайно* зафиксированная причина ре-валидации курсора Bind mismatch(19):

SQL> @shared_cu12_noxml 4d0gaxcnkytvy
 
INST    EXECS USERS_OPENING FIRST_LOAD_TIME      LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CURSOR_STATUS  PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS REOPT REOPT_HINTS ADAPT SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON OPTIMIZER_STATS  BIND_EQ_FAILURE  ROLL REASON#1
---- -------- ------------- -------------------- -------------------- ------------------- ------------ -------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----- --------- --------- -------- --- ---------- ---------------- ---------------- ---- -----------------
   1        0             2 2015-07-23/10:29:47  2015-07-23/12:06:29  23.07.2015 14:13:10   5842911795 INVALID_UNAUTH      2742927352           3263067145        2999021     1 N          N          Y          N                  N                                           11       8   hint       N                N                N    Bind mismatch(19)
   1        0             3 2015-07-23/10:29:47  2015-07-23/14:13:10  23.07.2015 14:13:10     12676603 VALID                        0                    0                    2 N          N          Y          N                  N                                                                   N                N                N

, приводящая по Metalink-у к цепочке:

Bug 14534978 : HIGH VERSION COUNT FOR SQL WHEN RUNNING DBMS_STATS

Bug 12976376 High VERSION_COUNT for SQL with binds, including recursive dictionary SQL — superseded

— где из названия последнего бага можно предположить связь проблемы с использованием в активно параллельно выполняемом запросе связанных переменных/binds:

SQL> select sql_text from v$sql where sql_id = '4d0gaxcnkytvy';
 
SQL_TEXT
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
insert /*+ parallel(8) opt_param('optimizer_adaptive_features' 'false') opt_param('optimizer_dynamic_sampling' 0) */into t_target select s.*, :d1 as insert_dt  from v_source s

— точнее, единственной переменной, причём достаточно декларативного типа)

Проблему действительно удалось решить просто отказавшись от использования этой единственной формальной и очевидно никак не влияющей связанной переменной, что в нашем случае оказалось несложно + нечасто выполняемый запрос вполне позволял, далее привожу профиль выполнения в точности того же проблемного запроса уже без использования bind:

SQL> select session_state || ' ' || event as STATE,
  2         sql_child_number              as CHILD,
  3         sql_exec_id,
  4         sql_plan_hash_value           as PLAN_HASH_VALUE,
  5         in_parse,
  6         in_hard_parse,
  7         in_sql_execution,
  8         count(*),
  9         min(sample_time),
 10         max(sample_time),
 11         max(sample_time) - min(sample_time) as DURATION
 12    from gv$active_session_history
 13   where sql_id = 'fqd6vv9zu9a66'
 14     and (nvl(qc_session_id, session_id),
 15          nvl(qc_session_serial#, session_serial#)) in ((982, 9346))
 16   group by session_state || ' ' || event,
 17            sql_child_number,
 18            sql_exec_id,
 19            sql_plan_hash_value,
 20            in_parse,
 21            in_hard_parse,
 22            in_sql_execution
 23   order by count(*) desc
 24  /
 
STATE                             CHILD SQL_EXEC_ID PLAN_HASH_VALUE IN_PARSE IN_HARD_PARSE IN_SQL_EXECUTION COUNT(*) MIN(SAMPLE_TIME)  MAX(SAMPLE_TIME)  DURATION
--------------------------------- ----- ----------- --------------- -------- ------------- ---------------- -------- ----------------- ----------------- ------------
ON CPU                                0    16777216       905552754 N        N             Y                    3960 02.08.42.596 PM   02.24.50.979 PM   00:16:08.383
WAITING direct path read temp         0    16777216       905552754 N        N             Y                     298 02.09.12.606 PM   02.22.13.910 PM   00:13:01.304
WAITING direct path write temp        0    16777216       905552754 N        N             Y                     176 02.08.51.596 PM   02.22.09.910 PM   00:13:18.314
WAITING direct path read              0    16777216       905552754 N        N             Y                      74 02.08.45.596 PM   02.09.23.606 PM   00:00:38.010
WAITING db file sequential read       0    16777216       905552754 N        N             Y                      40 02.08.41.596 PM   02.22.24.913 PM   00:13:43.317
WAITING db file scattered read        0    16777216       905552754 N        N             Y                      38 02.09.16.606 PM   02.22.51.933 PM   00:13:35.327
WAITING db file parallel read         0    16777216       905552754 N        N             Y                      18 02.08.43.596 PM   02.10.49.652 PM   00:02:06.056
WAITING read by other session         0    16777216       905552754 N        N             Y                       4 02.08.48.596 PM   02.09.05.596 PM   00:00:17.000
WAITING gc cr grant 2-way             0    16777216       905552754 N        N             Y                       4 02.21.16.880 PM   02.22.22.913 PM   00:01:06.033
WAITING gc cr multi block request     0    16777216       905552754 N        N             Y                       3 02.09.18.606 PM   02.11.07.652 PM   00:01:49.046
WAITING gc current block 2-way        0    16777216       905552754 N        N             Y                       1 02.20.39.880 PM   02.20.39.880 PM   00:00:00.000
WAITING gc cr request                 0    16777216       905552754 N        N             Y                       1 02.08.43.596 PM   02.08.43.596 PM   00:00:00.000
ON CPU                                0                   905552754 Y        Y             Y                       1 02.08.40.596 PM   02.08.40.596 PM   00:00:00.000 -- parsing

Конечно же, правильным альтернативным вариантом могло было стать долгоиграющее общение с поддержкой с отнюдь неочевидным результатом — см., например, статус вышеупомянутого Bug 20137221, в связи, например, с нетривиальностью процесса воспроизведения бага для запроса с планом в 1000 строк)

*) «случайно зафиксированная причина ре-валидации курсора» — т.к. в последующих тестах видел в т.ч. гораздо менее очевидный V$SQL_SHARED_CURSOR.REASON = Different Call Duration(0)

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

Комментариев нет.

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