Oracle mechanics

13.11.2016

Oracle 12.1: Library Cache Lock на объекте типа $BUILD$, Adaptive Plan и параллельное выполнение

Filed under: Oracle,Scripts,shared pool,wait events — Игорь Усольцев @ 23:37
Tags: ,

Активизировавшаяся конкуренция за объекты Library Cache в форме ожиданий library cache lock, и в меньшей степени kksfbc child completion, library cache: mutex X:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ -----------
DB CPU                                          10.3K              77.6         
library cache lock                 159,109     1554.8       9.77   11.7 Concurrency -- здесь
db file sequential read            297,807      436.2       1.46    3.3 User I/O
cursor: pin S wait on X             26,087      322.5      12.36    2.4 Concurrency
log file sync                      116,938      267.6       2.29    2.0 Commit  
SQL*Net more data from client    1,809,223      131.1       0.07    1.0 Network 
kksfbc child completion              2,213      108.3      48.94     .8 Other       -- , здесь
control file sequential read       290,199       72.9       0.25     .5 System I
direct path write                    6,026       46.3       7.69     .3 User I/O
library cache: mutex X              83,522       45.7       0.55     .3 Concurrency -- и здесь

оказалось вызвана PX-slave процессами (P…) одного параллельно выполнявшимся запроса dx0fckp3gckku в стадии подготовки (IN_PARSE) адаптивного плана (SQL_ADAPTIVE_PLAN_RESOLVED = 1):

SQL> @ash_sql_wait_tree "event = 'library cache lock' and sql_id = 'dx0fckp3gckku'"
 
LVL INST_ID BLOCKING_TREE   EVENT                     WAIT_CLASS    DATA_OBJECT_P1RAW  IN_PARSE SQL_ADAPTIVE_PLAN_RESOLVED SQL_CHILD_NUMBER WAITS_COUNT EXECS_COUNT AVG_WA SESS_COUNT BLOCK_SID        MIN_STIME           MAX_STIME           SQL_ID        SQL_PLAN_HASH_VALUE SQL_EXEC_ID SQL_PLAN_LINE_ID SQL_PLAN_OPERATION  SQL_TEXT
--- ------- --------------- ------------------------- ------------- ------------------ -------- -------------------------- ---------------- ----------- ----------- ------ ---------- ---------------- ------------------- ------------------- ------------- ------------------- ----------- ---------------- ------------------- ----------------------
  1       1 (P...)          library cache lock        Concurrency   000000015D55A1E8   N                                 1                4        1661           0     10       1646 VALID i#1        09-NOV-16 10.43.40  09-NOV-16 11.58.04  dx0fckp3gckku          2362884641           0                0 SELECT STATEMENT    select count(1) from (
  1       1 (P...)          library cache lock        Concurrency   000000015D55A1E8   N                                 1                4          11           0     16         11 UNKNOWN i#       09-NOV-16 10.43.40  09-NOV-16 11.51.17  dx0fckp3gckku          2362884641           0                0 SELECT STATEMENT    select count(1) from (
  2       1   (P...)        library cache lock        Concurrency   000000015D55A1E8   N                                 1                4         462           0      5         60 VALID i#1        09-NOV-16 10.43.40  09-NOV-16 11.57.29  dx0fckp3gckku          2362884641           0                0 SELECT STATEMENT    select count(1) from (
  2       1   (P...)        library cache: mutex X    Concurrency   ..                 N                                 1                4          60           0      8         20 NO HOLDER i#     09-NOV-16 11.03.18  09-NOV-16 11.57.29  dx0fckp3gckku          2362884641           0                0 SELECT STATEMENT    select count(1) from (
  2       1   (P...)        On CPU / runqueue                       000000015D55A1E8   Y                                 1              994          50           0      0          2 NOT IN WAIT i#   09-NOV-16 11.33.03  09-NOV-16 11.34.02  dx0fckp3gckku          1013165616           0                                      select count(1) from (
  2       1   (P...)        On CPU / runqueue                       000000015D55A1E8   Y                                 1              969          44           0      0          4 NOT IN WAIT i#   09-NOV-16 11.27.55  09-NOV-16 11.28.00  dx0fckp3gckku                   0           0                                      select count(1) from (
  2       1   (P...)        On CPU / runqueue                       000000015D55A1E8   Y                                 1              941          41           0      0          1 NOT IN WAIT i#   09-NOV-16 11.16.02  09-NOV-16 11.16.02  dx0fckp3gckku          1013165616           0                                      select count(1) from (
  2       1   (P...)        On CPU / runqueue                       000000015D55A1E8   Y                                 1              975          38           0      0          2 NOT IN WAIT i#   09-NOV-16 11.28.28  09-NOV-16 11.28.43  dx0fckp3gckku                   0           0                                      select count(1) from (
  2       1   (P...)        On CPU / runqueue                       000000015D55A1E8   Y                                 1              948          36           0      0          2 NOT IN WAIT i#   09-NOV-16 11.22.01  09-NOV-16 11.23.03  dx0fckp3gckku                   0           0                                      select count(1) from (
  2       1   (P...)        On CPU / runqueue                       000000015D55A1E8   Y                                 1              938          32           0      0          3 NOT IN WAIT i#   09-NOV-16 11.11.04  09-NOV-16 11.13.03  dx0fckp3gckku          2045682565           0                                      select count(1) from (
  2       1   (P...)        On CPU / runqueue                       ..                 Y                                 1             1006          31           0      0          1 NOT IN WAIT i#   09-NOV-16 11.50.03  09-NOV-16 11.50.03  dx0fckp3gckku          2045682565           0                                      select count(1) from (
  2       1   (P...)        On CPU / runqueue                       000000015D55A1E8   Y                                 1             1015          29           0      0          2 NOT IN WAIT i#   09-NOV-16 11.55.17  09-NOV-16 11.55.23  dx0fckp3gckku                   0           0                                      select count(1) from (
  2       1   (P...)        On CPU / runqueue                       000000015D55A1E8   Y                                 1              932          28           0      0          1 NOT IN WAIT i#   09-NOV-16 11.05.03  09-NOV-16 11.05.03  dx0fckp3gckku          2045682565           0                                      select count(1) from (
  2       1   (P...)        On CPU / runqueue                       000000015D55A1E8   Y                                 1             1018          27           0      0          2 NOT IN WAIT i#   09-NOV-16 11.56.58  09-NOV-16 11.57.18  dx0fckp3gckku          1013165616           0                                      select count(1) from (
  2       1   (P...)        On CPU / runqueue                       000000015D55A1E8   Y                                 1              955          27           0      0          1 NOT IN WAIT i#   09-NOV-16 11.27.02  09-NOV-16 11.27.02  dx0fckp3gckku          2045682565           0                                      select count(1) from (
...
  3       1     (P...)      library cache: mutex X    Concurrency   ..                 N                                 1                4         222           0      3         20 NO HOLDER i#     09-NOV-16 11.03.18  09-NOV-16 11.57.29  dx0fckp3gckku          2362884641           0                0 SELECT STATEMENT    select count(1) from (
  3       1     (P...)      library cache lock        Concurrency   000000015D55A1E8   N                                 1                4         160           0      1         21 VALID i#1        09-NOV-16 10.59.50  09-NOV-16 11.54.28  dx0fckp3gckku          2362884641           0                0 SELECT STATEMENT    select count(1) from (
...
  4       1       (P...)    library cache: mutex X    Concurrency   ..                 N                                 1                4          57           0      1          7 NO HOLDER i#     09-NOV-16 11.16.03  09-NOV-16 11.54.27  dx0fckp3gckku          2362884641           0                0 SELECT STATEMENT    select count(1) from (
  4       1       (P...)    On CPU / runqueue                       000000015D55A1E8   Y                                 1              969          27           0      0          2 NOT IN WAIT i#   09-NOV-16 11.27.55  09-NOV-16 11.27.57  dx0fckp3gckku                   0           0                                      select count(1) from (
  4       1       (P...)    On CPU / runqueue                       000000015D55A1E8   Y                                 1             1014          14           0      0          1 NOT IN WAIT i#   09-NOV-16 11.54.28  09-NOV-16 11.54.28  dx0fckp3gckku                   0           0                                      select count(1) from (
...
  4       1       (P...)    kksfbc child completion   Other         ..                 N                                 1                4           1           0      0          1 UNKNOWN i#       09-NOV-16 11.19.01  09-NOV-16 11.19.01  dx0fckp3gckku          2362884641           0                0 SELECT STATEMENT    select count(1) from (
  5       1         (P...)  library cache: mutex X    Concurrency   ..                 N                                 1                4           9           0      0          2 NO HOLDER i#     09-NOV-16 11.19.02  09-NOV-16 11.27.18  dx0fckp3gckku          2362884641           0                0 SELECT STATEMENT    select count(1) from (

, конкурировавшими за конкретный объект Library Cache типа $BUILD$ — DATA_OBJECT_P1RAW = 000000015D55A1E8:

SQL> select * from x$kglob w where w.kglhdadr = '000000015D55A1E8';

ADDR               INDX INST_ID KGLHDADR         KGLHDCLT KGLNAOWN KGLNAOBJ         KGLFNOBJ           KGLNAHSH KGLNAHSV                         KGLHDNSP KGLHDNSD        KGLOBTYD
---------------- ------ ------- ---------------- -------- -------- ---------------- ---------------- ---------- -------------------------------- -------- --------------- --------
00007FB3D20C3C18 131613       1 000000015D55A1E8    30414 $BUILD$  ca564d4327733ec2 2c1b2e0a6fa1578c 2585264380 17cebd609ec862a650fba106528a0104       82 SQL AREA BUILD  CURSOR  ...

Такого типа конкуренция описана в фолиантах — Bug 12633340 Heavy «library cache lock» and «library cache: mutex X» contention for a «$BUILD$.xx» lock (правда, для Oracle 11g, что, имхо, не влияет на актульность), где рекомендуют, в частности, обратить внимание на проблему High Version Count, на что формально указывают высокие значения [V$ACTIVE_SESSION_HISTORY.]SQL_CHILD_NUMBER в вышеприведённом выводе ASH_SQL_WAIT_TREE.SQL

Однако, соответствуют эти высокие CHILD_NUMBER либо SQL_PLAN_HASH_VALUE = 0, либо несуществующим/несохранившимся значениям PHV:

SQL> SELECT * FROM TABLE(dbms_xplan.display_awr('dx0fckp3gckku',1013165616));

no rows selected

— что подтверждает и видимое состояние курсоров:

SQL> @shared_cu12_noxml dx0fckp3gckku 0
 
 EXECS USERS_OPENING ROWS_PER_EXEC ELA_PER_EXEC PARSES_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 V$SQL.Adapt XML.Adapt SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON REASON#1                REASON#2                REASON#3                SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE IS_OBSOLETE
------ ------------- ------------- ------------ --------------- ------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----------- --------- --------- --------- -------- --- ---------- ----------------------- ----------------------- ----------------------- ----------------- --------- ---------------- ----------- -----------
     0             0             0      6447467               0 VALID              2362884641            446753540             52     3 N          N          Y          N                  N                 Y           yes       5         0                                 PQ Slave mismatch(2)    Top Level RPI Cursor(0) Top Level RPI Cursor(0)                                                          N
     0            16             0   5677701136           36798 VALID              2362884641            446753540             52     4 N          N          Y          N                  N                 Y           yes       5         0                                 Top Level RPI Cursor(0) Top Level RPI Cursor(0)                                                                                  N -- **
  2343            39             1        20923               1 VALID              2362884641            446753540             52     2 N          N          Y          N                  N                 Y           yes       5         0                                 Bind UACs mismatch(0)   Top Level RPI Cursor(0) Bind UACs mismatch(0)                                                            N -- *
 
 
--------------------------------------------------------------
SQL_ID=dx0fckp3gckku Shared Pool statistics by PLAN_HASH_VALUE
--------------------------------------------------------------
 
 EXECS ELA_PER_EXEC PARSES_PER_EXEC FETCH_PER_EXEC ROWS_PER_EXEC PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE AVG_CBO_COST     CHILDS BIND_SENSE BIND_AWARE REOPT ADAPT SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE
------ ------------ --------------- -------------- ------------- --------------- -------------------- ------------ ---------- ---------- ---------- ----- ----- ----------------- --------- ---------------- -----------
  2343      2446936              17              1             1      2362884641            446753540           52          3 N          N          N     Y
 
 
--------------------------------------------------------------
SQL_ID=dx0fckp3gckku Shared Pool GV$SQLSTATS
--------------------------------------------------------------
 
 EXECS SQL_ID              PLAN ELA_PER_EXEC ROWS_PER_EXEC PX_PER_EXEC
------ ------------- ---------- ------------ ------------- -----------
  2343 dx0fckp3gckku 2362884641      2446936             1          16

— где заметно, что «рабочим» (с ненулевым кол-вом выполнений EXECS = 2343) является курсор с CHILD_NUMBER = 2 (*) со ср.временем выполнения ELA_PER_EXEC = 20923 us, а курсор с CHILD_NUMBER = 4 (**) выглядит странно и, вероятно, является служебным: ELA_PER_EXEC = 5677 s при EXECS = 0 и огромное кол-во PARSES_PER_EXEC = 36798 — что при усреднении даёт в V$SQLSTATS ср.время запроса ELA_PER_EXEC ~ 2,4 s

Учитывая, что DYNAMIC SAMPLING отключен на уровне системы:

SQL> @param optimizer_dynamic_sampling
 
NAME                        VALUE  IS_DEF   IS_MOD   
--------------------------- ------ -------- ---------
optimizer_dynamic_sampling  0      FALSE    FALSE

и поскольку Automatic Reoptimization (как следует из SHARED_CU12_NOXML.SQL — REOPT = N) не применяется, причиной library cache lock теоретически могут быть только Adaptive Plan и/или параллельное выполнение, причины которого из содержимого V$SQL_PLAN.OTHER_XML не совсем ясны:

SQL> @sql_plan_notes dx0fckp3gckku 2362884641
 
FULL_NOTES
---------------------------------------------
   sql_profile:
   sql_patch:
   baseline:
   outline:
   dyn_sampling:
   dop:
   dop_reason:
   pdml_reason:
   idl_reason:
   queuing_reason:
   px_in_memory:
   px_in_memory_imc:
   row_shipping:
   index_size:
   result_checksum:
   card_feedback:
   perf_feedback:
   xml_suboptimal:
   adaptive_plan:   yes
   spd_used:        0
   spd_valid:       5
   gtt_sess_stat:
   db_version:      12.1.0.2
   plan_hash_full:  446753540
   plan_hash:       2362884641
   plan_hash_2:     111047763

и, как следствие, отсутствуют в выводе DBMS_XPLAN.DISPLAY_CURSOR:

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('dx0fckp3gckku',2,format => '+note'));
 
PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID  dx0fckp3gckku, child number 2
-------------------------------------
select count(1) from (   select
...
Plan hash value: 2362884641
---------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                                    | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
---------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                             |       |       |    52 (100)|          |        |      |            |
|   1 |  SORT AGGREGATE                              |     1 |    28 |            |          |        |      |            |
|   2 |   PX COORDINATOR                             |       |       |            |          |        |      |            |
|   3 |    PX SEND QC (RANDOM)                       |     1 |    28 |            |          |  Q1,02 | P->S | QC (RAND)  |
|   4 |     SORT AGGREGATE                           |     1 |    28 |            |          |  Q1,02 | PCWP |            |
|*  5 |      HASH JOIN                               |    53 |  1484 |     5   (0)| 00:00:01 |  Q1,02 | PCWP |            |
|   6 |       BUFFER SORT                            |       |       |            |          |  Q1,02 | PCWC |            |
|   7 |        PX RECEIVE                            |       |       |            |          |  Q1,02 | PCWP |            |
|   8 |         PX SEND HASH                         |       |       |            |          |        | S->P | HASH       |
|   9 |          NESTED LOOPS                        |     1 |    23 |     3   (0)| 00:00:01 |        |      |            |
|* 10 |           TABLE ACCESS BY INDEX ROWID BATCHED|     1 |    13 |     2   (0)| 00:00:01 |        |      |            |
|* 11 |            INDEX RANGE SCAN                  |     1 |       |     1   (0)| 00:00:01 |        |      |            |
|* 12 |           TABLE ACCESS BY INDEX ROWID        |     1 |    10 |     1   (0)| 00:00:01 |        |      |            |
|* 13 |            INDEX UNIQUE SCAN                 |     1 |       |     0   (0)|          |        |      |            |
|  14 |            SORT AGGREGATE                    |     1 |     8 |            |          |        |      |            |
|* 15 |             TABLE ACCESS FULL                |  3046 | 24368 |    47   (0)| 00:00:01 |        |      |            |
|  16 |       PX RECEIVE                             |    54 |   270 |     2   (0)| 00:00:01 |  Q1,02 | PCWP |            |
|  17 |        PX SEND HASH                          |    54 |   270 |     2   (0)| 00:00:01 |  Q1,01 | P->P | HASH       |
|  18 |         PX BLOCK ITERATOR                    |    54 |   270 |     2   (0)| 00:00:01 |  Q1,01 | PCWC |            |
|* 19 |          INDEX FAST FULL SCAN                |    54 |   270 |     2   (0)| 00:00:01 |  Q1,01 | PCWP |            |
---------------------------------------------------------------------------------------------------------------------------
Note
-----
   - this is an adaptive plan

Тем не менее одну из причин параллельного выполнения можно видеть из зависимостей плана запроса:

SQL> @sql_plan_dep3 dx0fckp3gckku 2362884641
 
LEVEL DEP_TREE                                    DEPENDS_ON TYPE REFERENCED                           LAST_MODIFIED     LAST_DDL          DOP
----- ------------------------------------------- ---------- ---- ------------------------------------ ----------------- ----------------- ---
    0 SQL_ID = 'dx0fckp3gckku' ; PHV = 2362884641            PLAN TABLE SHO.DATAFLUD                   11.11.16 15:03:59 20.02.16 23:01:02 1
    0 SQL_ID = 'dx0fckp3gckku' ; PHV = 2362884641            PLAN INDEX SHO.IDX_DATAFLUD_DATASOURCE_ID                   03.11.12 03:04:42 8  -- ***
    0 SQL_ID = 'dx0fckp3gckku' ; PHV = 2362884641            PLAN INDEX SHO.I_FLUD_CATEGORIES_FID                        03.11.12 03:04:41 8  -- ***
    0 SQL_ID = 'dx0fckp3gckku' ; PHV = 2362884641            PLAN TABLE SHO.MODERATION_AND_GAMMA       11.11.16 15:03:59 07.11.16 16:31:34 1
    0 SQL_ID = 'dx0fckp3gckku' ; PHV = 2362884641            PLAN TABLE SHO.FLUD_STATE                 11.11.16 13:33:47 07.07.16 12:51:53 1
    0 SQL_ID = 'dx0fckp3gckku' ; PHV = 2362884641            PLAN INDEX SHO.SYS_C0026580                                 03.11.12 03:13:52 1

— это «забытые» при построении/перестроении индексов DOP=8 у 2-х индексов SHO.IDX_DATAFLUD_DATASOURCE_ID и SHO.I_FLUD_CATEGORIES_FID (***)

К несчастью, DOP индексов (index property) как реально действующая причина параллельного выполнения, похоже, не занесена в списки DOP_REASON планов выполнения, в отличие от table property:

SQL> SELECT
  2  distinct extractvalue(xmlval, '/*/info[@type = "dop_reason"]') as DOP_REASONS
  3    from (select xmltype(other_xml) xmlval
  4            from dba_hist_sql_plan
  5           where other_xml is not null)
  6  /
 
DOP_REASONS
--------------------
degree limit
table property
session
hint

В итоге, мне удалось проверить обе вероятные причины Library Cache конкуренции для этого запроса: и Adaptive Plan, и параллельное выполнение с одинаково успешным результатом

1) Пока не трогая свойства индексов (DOP) при отключении Adaptive Plan добавлением хинта NO_ADAPTIVE_PLAN с помощью SQL Patch dx0fckp3gckku_NO_ADAPTIVE, и даже дополнительно «закрепив» (насколько это возможно) план параллельного выполнения PHV=2362884641 через SQL Profile dx0fckp3gckku_2362884641:

SQL> @spm_check4sql_id dx0fckp3gckku
 
SIGNATURE             SPM_TYPE          SQL_HANDLE                     PATCH_NAME                     ORIGIN         VERSION     CREATED             LAST_MODIFIED       LAST_EXECUTED LAST_VERIFIED ENABLED ACCEPTED FIXED REPRODUCED AUTOPURGE
--------------------- ----------------- ------------------------------ ------------------------------ -------------- ----------- ------------------- ------------------- ------------- ------------- ------- -------- ----- ---------- ---------
  1834185302292350168 SQL Patch         SQL_197455d08360c4d8           dx0fckp3gckku_NO_ADAPTIVE      MANUAL-SQLTUNE 12.1.0.2.0  09.11.2016 13:49:50 09.11.2016 13:49:50                             YES     NO       NO    YES        NO
  1834185302292350168 SQL Profile       SQL_197455d08360c4d8           dx0fckp3gckku_2362884641       MANUAL-LOAD    12.1.0.2.0  09.11.2016 13:48:10 09.11.2016 13:48:10                             YES     NO       NO    YES        NO

— запрос некоторое время выполняется быстро (~ 50 ms) параллельно, с целевым PHV=2362884641, после чего переключается на ещё более быстрый ELA_PER_EXEC ~ 11.5 ms непараллельный PHV=2045682565 с такой же стоимостью COST=52:

SQL> @shared_cu12_noxml dx0fckp3gckku
 
 EXECS USERS_OPENING ROWS_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC UIO_PER_EXEC CONC_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 V$SQL.Adapt XML.Adapt SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON REASON#1                SQL_PLAN_BASELINE SQL_PATCH                 SQL_PROFILE
------ ------------- ------------- ------------ ------------ --------------- ------------ ------------- ------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----------- --------- --------- --------- -------- --- ---------- ----------------------- ----------------- ------------------------- ------------------------
  1455             9             1        11462         5498               1         4579          1121 VALID              2045682565           3833540966             52     1 N          N          Y          N                  N                 N                     5         0                                 Top Level RPI Cursor(0)                   dx0fckp3gckku_NO_ADAPTIVE dx0fckp3gckku_2362884641
 
--------------------------------------------------------------
SQL_ID=dx0fckp3gckku Shared Pool statistics by PLAN_HASH_VALUE
--------------------------------------------------------------
 
 EXECS LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC FETCH_PER_EXEC ROWS_PER_EXEC PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE AVG_CBO_COST     CHILDS BIND_SENSE BIND_AWARE REOPT ADAPT SQL_PLAN_BASELINE SQL_PATCH                 SQL_PROFILE
------ -------------------- ------------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- -------------- ------------- --------------- -------------------- ------------ ---------- ---------- ---------- ----- ----- ----------------- ------------------------- ------------------------
  1455 2016-11-09/13:51:02  09.11.2016 18:09:01        11462         5498               1           133              0         4579          1121              1             1      2045682565           3833540966           52          1 N          N          N     N                       dx0fckp3gckku_NO_ADAPTIVE dx0fckp3gckku_2362884641
 
--------------------------------------------------------------
SQL_ID=dx0fckp3gckku Shared Pool GV$SQLSTATS
--------------------------------------------------------------
 
 EXECS SQL_ID              PLAN ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC CONC_PER_EXEC CLU_PER_EXEC UIO_PER_EXEC ROWS_PER_EXEC PX_PER_EXEC
------ ------------- ---------- ------------ ------------ ------------- ------------- ------------ ------------ ------------- -----------
  1455 dx0fckp3gckku 2045682565        11462         5498           133          1121            0         4579             1           0
 
--------------------------------------------------------------
ASH TOP5 SQL_ID=dx0fckp3gckku Executions by Elapsed Time
--------------------------------------------------------------
 
INST_ID SQL_ID        SQL_PLAN_HASH_VALUE SQL_EXEC_ID   CHILD_ID   ASH_ROWS DURATIONs                 MIN_SAMPLE_TIME           MAX_SAMPLE_TIME
------- ------------- ------------------- ----------- ---------- ---------- ------------------------- ------------------------- -------------------------
      1 dx0fckp3gckku          2362884641    16778502          2          2 +000000000 00:00:01.010   09-NOV-16 01.41.35.380 PM 09-NOV-16 01.41.36.390 PM
      1 dx0fckp3gckku          2362884641    16778192          2          2 +000000000 00:00:01.000   09-NOV-16 01.17.36.610 PM 09-NOV-16 01.17.37.610 PM
      1 dx0fckp3gckku          2362884641    16777967          2          2 +000000000 00:00:01.000   09-NOV-16 01.06.08.286 PM 09-NOV-16 01.06.09.286 PM
      1 dx0fckp3gckku          2362884641    16778612          3          1 +000000000 00:00:00.000   09-NOV-16 01.47.51.160 PM 09-NOV-16 01.47.51.160 PM
      1 dx0fckp3gckku          2362884641    16777930          3          1 +000000000 00:00:00.000   09-NOV-16 01.04.13.046 PM 09-NOV-16 01.04.13.046 PM

— в ASH TOP5 ещё заметны следы параллельного плана PHV=2362884641

При этом используемые параллельный и непаралльный планы отличаются незначительно:

SQL> @sql_plan_diff_outl dx0fckp3gckku 2362884641 dx0fckp3gckku 2045682565
 
--------------------------------
SQL Plan "Outline" sections diff
--------------------------------
 
PHV_2362884641                                        PHV_2045682565
----------------------------------------------------- -------------------------------------------------
PQ_DISTRIBUTE(@"SEL$5C160134" "FC"@"SEL$2" HASH HASH) 

— т.о. нельзя сказать чтобы созданный для фиксации PHV=2362884641 SQL Profile совсем уж не работал — просто инструкция PQ_DISTRIBUTE, вероятно, не является обязательной в общем случае;)

2) С другой стороны, удалив созданные на предыдущем шаге SQL Profile & Patch и вернув DOP индексов к исходному (и правильному!) состоянию:

SQL> @sqlpatch- dx0fckp3gckku_NO_ADAPTIVE dx0fckp3gckku
 
PL/SQL procedure successfully completed
 
SPM Elements (SQL Profile, or SQL Plan Baseline, or SQL Patch) List for SQL_ID = dx0fckp3gckku
 
SIGNATURE             SPM_TYPE          SQL_HANDLE                     PATCH_NAME                     ORIGIN         VERSION                                                          CREATED               LAST_MODIFIED         LAST_EXECUTED       LAST_VERIFIED       ENABLED ACCEPTED FIXED REPRODUCED AUTOPURGE
--------------------- ----------------- ------------------------------ ------------------------------ -------------- ---------------------------------------------------------------- --------------------- --------------------- ------------------- ------------------- ------- -------- ----- ---------- ---------
  1834185302292350168 SQL Profile       SQL_197455d08360c4d8           dx0fckp3gckku_2362884641       MANUAL-LOAD    12.1.0.2.0                                                       09.11.2016 13:48:10   09.11.2016 13:48:10                                           YES     NO       NO    YES        NO

SQL> exec dbms_sqltune.drop_sql_profile  (name => 'dx0fckp3gckku_2362884641', ignore => TRUE)

PL/SQL procedure successfully completed

SQL> alter index SHO.IDX_DATAFLUD_DATASOURCE_ID noparallel;
 
Index altered
 
Executed in 0,016 seconds
 
SQL> alter index SHO.I_FLUD_CATEGORIES_FID noparallel;
 
Index altered

— можно видеть ещё более приятную картину — ELA_PER_EXEC = 5283 us — практически сразу, и без применения средств SPM:

SQL> @shared_cu12_noxml dx0fckp3gckku
 
 EXECS USERS_OPENING LAST_ACTIVE_TIME    ROWS_PER_EXEC ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_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 V$SQL.Adapt XML.Adapt SPD_Valid SPD_Used  DS_LEVEL DOP DOP_REASON OPTIMIZER_STATS  BIND_EQ_FAILURE  CURSOR_PARTS_MISMATCH ROLL REASON#1                              SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE IS_OBSOLETE
------ ------------- ------------------- ------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- ------------- --------------- -------------------- -------------- ----- ---------- ---------- ---------- ------------------ ----- ----------- ----------- --------- --------- --------- -------- --- ---------- ---------------- ---------------- --------------------- ---- ------------------------------------- ----------------- --------- ---------------- ----------- -----------
  2856             0 12.11.2016 10:25:02             1         5311         4850               1           116              0          121             0 VALID              2045682565            755850606             52     1 Y          N          Y          N                  N                 Y           yes       5         0                                 N                N                N                     Y    Rolling Invalidate Window Exceeded(3)                                                          N
   374            40 12.11.2016 11:36:02             1         5071         4719               1           115              0           70             0 VALID              2045682565            755850606             52     0 Y          N          Y          N                  N                 Y           yes       5         0                                 N                N                N                     Y    Rolling Invalidate Window Exceeded(3)                                                          N
 
--------------------------------------------------------------
SQL_ID=dx0fckp3gckku Shared Pool statistics by PLAN_HASH_VALUE
--------------------------------------------------------------
 
 EXECS LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CPU_PER_EXEC PARSES_PER_EXEC GETS_PER_EXEC READS_PER_EXEC UIO_PER_EXEC CONC_PER_EXEC FETCH_PER_EXEC ROWS_PER_EXEC PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE AVG_CBO_COST     CHILDS BIND_SENSE BIND_AWARE REOPT ADAPT SQL_PLAN_BASELINE SQL_PATCH OUTLINE_CATEGORY SQL_PROFILE
------ -------------------- ------------------- ------------ ------------ --------------- ------------- -------------- ------------ ------------- -------------- ------------- --------------- -------------------- ------------ ---------- ---------- ---------- ----- ----- ----------------- --------- ---------------- -----------
  3230 2016-11-12/10:26:02  12.11.2016 11:36:02         5283         4835               1           116              0          115             0              1             1      2045682565            755850606           52          2 Y          N          N     Y                                                  
 
--------------------------------------------------------------
SQL_ID=dx0fckp3gckku Shared Pool GV$SQLSTATS
--------------------------------------------------------------
 
 EXECS SQL_ID              PLAN ELA_PER_EXEC CPU_PER_EXEC GETS_PER_EXEC CONC_PER_EXEC CLU_PER_EXEC UIO_PER_EXEC ROWS_PER_EXEC PX_PER_EXEC
------ ------------- ---------- ------------ ------------ ------------- ------------- ------------ ------------ ------------- -----------
  3230 dx0fckp3gckku 2045682565         5283         4835           116             0            0          115             1           0
 
--------------------------------------------------------------
ASH TOP5 SQL_ID=dx0fckp3gckku Executions by Elapsed Time
--------------------------------------------------------------
 
   INST_ID SQL_ID        SQL_PLAN_HASH_VALUE SQL_EXEC_ID   CHILD_ID   ASH_ROWS DURATIONs                 MIN_SAMPLE_TIME           MAX_SAMPLE_TIME
---------- ------------- ------------------- ----------- ---------- ---------- ------------------------- ------------------------- -------------------------
         1 dx0fckp3gckku          2045682565    16799324          1          1 +000000000 00:00:00.000   12.11.16 09:28:19,722     12.11.16 09:28:19,722
         1 dx0fckp3gckku          2045682565    16798816          1          1 +000000000 00:00:00.000   12.11.16 07:27:29,830     12.11.16 07:27:29,830
         1 dx0fckp3gckku          2045682565    16798767          1          1 +000000000 00:00:00.000   12.11.16 07:26:56,784     12.11.16 07:26:56,784
         1 dx0fckp3gckku          2045682565    16799384          1          1 +000000000 00:00:00.000   12.11.16 09:35:02,531     12.11.16 09:35:02,531
         1 dx0fckp3gckku          2045682565    16799824          0          1 +000000000 00:00:00.000   12.11.16 11:29:34,557     12.11.16 11:29:34,557

И, конечно же, оба описанных варианта успешно разрешают проблему ожидания library cache lock на уровне этой небольшой, но очень ответственной системы:)

SQL> @dba_hist_system_event "event_name = 'library cache lock' and snap_id >= 35740"
 
INST_ID    SNAP_ID BEGIN_INTERVAL_TIME EVENT_NAME          WAIT_COUNT AVG_WAIT_TIME_NS TIME_WAITED_S
------- ---------- ------------------- ------------------- ---------- ---------------- -------------
      1      35740 09.11.2016 09:20    library cache lock      159109             9772          1555
      1      35741 09.11.2016 09:40    library cache lock      114809            10649          1223
      1      35742 09.11.2016 10:00    library cache lock       32553            12382           403
      1      35743 09.11.2016 10:20    library cache lock       61195            11625           711
      1      35744 09.11.2016 10:40    library cache lock       20121            11133           224
      1      35745 09.11.2016 11:00    library cache lock       22878            12911           295
      1      35746 09.11.2016 11:20    library cache lock       73707            13234           975
      1      35747 09.11.2016 11:40    library cache lock       29147            12910           376
      1      35748 09.11.2016 12:00    library cache lock         227             9813             2 -- первое применение
      1      35749 09.11.2016 12:20    library cache lock         254            29244             7
      1      35750 09.11.2016 12:40    library cache lock         253             9535             2
      1      35751 09.11.2016 13:00    library cache lock         314            15272             5
      1      35752 09.11.2016 13:20    library cache lock         289            10969             3
      1      35753 09.11.2016 13:40    library cache lock         174            14782             3
      1      35754 09.11.2016 14:00    library cache lock         157            10034             2
      1      35755 09.11.2016 14:20    library cache lock         131            11025             1
      1      35756 09.11.2016 14:40    library cache lock         166            13924             2
      1      35757 09.11.2016 15:00    library cache lock         198            14637             3
      1      35758 09.11.2016 15:20    library cache lock         118             9657             1
      1      35759 09.11.2016 15:40    library cache lock         142             9438             1
      1      35760 09.11.2016 16:00    library cache lock         140             8842             1

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

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

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