Oracle mechanics

08.11.2015

12c: hardcoded подсказка _fix_control и новая проблема High Version Count

Filed under: Диагностика системы (instance),hints,Oracle — Игорь Усольцев @ 22:22
Tags: ,

Как бы продолжая тему багов/особенностей 12c, появился запрос с заметной долей Shared Pool Concurrency ожиданий в процессе выполнения с ASH мониторингом вида:

SQL> @ash_sqlmon2 45u45mpanbatr
 
LAST_PLSQL SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                                 PX   ASH_ROWS WAIT_PROFILE
---------- ------------- --------------- ---- ------------------------------------------------- ---------- --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Hard Parse 45u45mpanbatr               0    0 sql_plan_hash_value = 0                       385      48755 cursor: pin S wait on X(47474); library cache lock(653); ON CPU(318); cursor: mutex X(121); cursor: mutex S(120); kksfbc child completion(52); cursor: pin S(8); library cache: mutex X(7);
Soft Parse 45u45mpanbatr      2447725225    0 sql_plan_hash_value > 0; sql_exec_id is null  514      37420 cursor: pin S wait on X(36708); library cache lock(454); cursor: mutex X(88); cursor: mutex S(77); ON CPU(44); kksfbc child completion(32); library cache: mutex X(11); SQL*Net message from dblink(3);
Soft Parse 45u45mpanbatr      2907472699    0 sql_plan_hash_value > 0; sql_exec_id is null  601     113412 cursor: pin S wait on X(107536); ON CPU(3566); library cache lock(1607); cursor: mutex X(286); cursor: mutex S(255); kksfbc child completion(88); PX Deq: Signal ACK EXT(26); library cache: mutex X(24);
...

— на этапах Hard/Soft Parse, доля которых для запроса составляла ~ 2/3 общего времени выполнения:

SQL> select session_state, event, wait_class, count(*), round((RATIO_TO_REPORT(count(*)) OVER ())*100) as "PerCent"
  2    from v$active_session_history
  3   where sql_id = '45u45mpanbatr'
  4   group by session_state, event, wait_class
  5   order by count(*) desc
  6  /
 
SESSION_STATE EVENT                       WAIT_CLASS    COUNT(*)    PerCent
------------- --------------------------- ----------- ---------- ----------
WAITING       cursor: pin S wait on X     Concurrency      45208         60
ON CPU                                                     24446         32
WAITING       db file sequential read     User I/O          2433          3
WAITING       library cache lock          Concurrency       1055          1
WAITING       cursor: mutex X             Concurrency        838          1
WAITING       SQL*Net message from dblink Network            796          1
WAITING       cursor: mutex S             Concurrency        556          1
WAITING       kksfbc child completion     Other              239          0 -- также Shared Pool Concurrency
...

Что отражалось в AWR:

Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                           Total Wait       Wait   % DB Wait    
Event                                Waits Time (sec)    Avg(ms)   time Class   
------------------------------ ----------- ---------- ---------- ------ -----------
cursor: pin S wait on X            179,283      44,1K     245.94   57.5 Concurrency -- примерно так
DB CPU                                          17,1K              22.2         
db file sequential read          9,771,947     6246,8       0.64    8.1 User I/O
db file scattered read             978,050     1153,2       1.18    1.5 User I/O
...

, на общем фоне запрос не потреблял каких-то экстраординарных ресурсов:

Elapsed                  Elapsed Time                                   
Time (s)    Executions  per Exec (s)  %Total   %CPU    %IO    SQL Id    
-------- -------------- ------------- ------ ------ ------ -------------
 2,388.0          4,189          0.57    3.1    9.5     .6 45u45mpanbatr

, за исключением:

SQL ordered by Sharable Memory DB/Inst:
-> Only Statements with Sharable Memory greater than 1048576 are displayed

Sharable Mem (b)  Executions   % Total    SQL Id    
---------------- ------------ -------- -------------
     239,326,770        4,189     0.84 45u45mpanbatr
      20,554,828           14     0.07 dfffkcnqfystw
...

— где лидировал при очень незначительном (по версии AWR) Version Count (ввиду погрешности заполнения DBA_HIST_SQLSTAT):

SQL ordered by Version Count   DB/Inst:
-> Only Statements with Version Count greater than 20 are displayed

 Version                           
  Count   Executions     SQL Id    
-------- ------------ -------------
...
      94        4,189 45u45mpanbatr

Что очевидно диссонировало с практическими наблюдениями согласно которым кол-во дочерних курсоров запроса было значительным и продолжало расти:

SQL> select count(*) from V$SQL where sql_id = '45u45mpanbatr';
 
  COUNT(*)
----------
     16978

...

SQL> select count(*) from v$sql where sql_id = '45u45mpanbatr';
 
  COUNT(*)
----------
     18454

, генерируя наблюдаемую online конкуренцию на этапах kksLoadChildhash table kkshinins (insert child into incomplete list):

SQL> @mutex_waits
 
LVL WAITING_SID PROGRAM                SQL_ID        EVENT                   SECONDS_IN_WAIT SID_HOLDING_MUTEX MUTEX_TYPE     MUTEX_LOCATION
--- ----------- ---------------------- ------------- ----------------------- --------------- ----------------- -------------- -------------------------
  1           7 python2.7 (TNS V1-V3)  45u45mpanbatr cursor: pin S wait on X               1              1333 hash table     kkshinins [KKSHBKLOC5]   
  1           7 python2.7 (TNS V1-V3)  45u45mpanbatr cursor: pin S wait on X               1              1333 Cursor Pin     kkslce [KKSCHLPIN2]      
  1           7 python2.7 (TNS V1-V3)  45u45mpanbatr cursor: pin S wait on X               1              1333 Cursor Parent  kksLoadChild [KKSPRTLOC5]
...

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

SQL> select plan_hash_value,
  2         full_plan_hash_value,
  3         child_number,
  4         object_status,
  5         executions as execs,
  6         count(distinct last_active_time) as exec_time_count,
  7         count(distinct child_address)    as child_addr_count,
  8         count(distinct optimizer_cost)   as cbo_cost_count,
  9         count(*)
 10    from V$SQL
 11   where sql_id = '45u45mpanbatr'
 12   group by plan_hash_value,
 13            full_plan_hash_value,
 14            child_number,
 15            object_status,
 16            executions
 17   order by child_number
 18  /
 
PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE CHILD_NUMBER OBJECT_STATUS  EXECS EXEC_TIME_COUNT CHILD_ADDR_COUNT CBO_COST_COUNT   COUNT(*)
--------------- -------------------- ------------ -------------- ----- --------------- ---------------- -------------- ----------
     2907472699           3719740186            0 INVALID_UNAUTH     1              17               17              9         17
     2907472699           3719740186            1 INVALID_UNAUTH     1              18               18              8         18
     2907472699           3719740186            2 INVALID_UNAUTH     1              19               19              5         19
...
     2907472699           3719740186         1023 INVALID_UNAUTH     1              16               16              8         16
 
1024 rows selected

— точнее, sub-дочерние (sub-child cursor), т.к. кол-во true дочерних курсоров ограничено 1024, и на каждый дочерний слот / CHILD_NUMBER использовалось несколько CHILD_ADDRESS (столбец CHILD_ADDR_COUNT), которые немедленно после исполнения переходили в статус INVALID_UNAUTH

Стандартные 100500 столбцов V$SQL_SHARED_CURSOR не объясняли ситуацию, кроме содержимого CLOB-столбца REASON:

SQL> select reason from V$SQL_SHARED_CURSOR where sql_id = '45u45mpanbatr' and rownum <= 1;

<ChildNode>
       <ChildNumber>0</ChildNumber>
       <ID>3</ID>
       <reason>Optimizer mismatch(12)</reason>
       <size>2x356</size>
       <_fix_control_key> 820120037            0</_fix_control_key> -- *
</ChildNode>

— с новым непустым тегом _fix_control_key, возможно, указывающим на причину проблемы, к тому же в тексте запроса, действительно, осталось/использовалось отключение фикса по проблеме, наблюдавшейся в версии 11.2.0.3:

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('45u45mpanbatr',format => '+outline'));
 
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID 45u45mpanbatr
--------------------
select ... /*+ OPT_PARAM('_fix_control' '4887636:0') */
...
Plan hash value: 2907472699
...
Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
 
PLAN_TABLE_OUTPUT
---------------------------------------------
      IGNORE_OPTIM_EMBEDDED_HINTS
...
      OPT_PARAM('_fix_control' '4887636:0')
...
  */

И, действительно, именно этот давноисправленный в 11.2.0.4 баг оптимизатора 4887636 при отключении на уровне запроса способствует генерации новых версий курсора для каждого выполнения, что легкопроверяемо:

12.1.0.2.@ SQL> select/*+ OPT_PARAM('_fix_control' '4887636:0')*/ count(*) from test_table;

  COUNT(*)
----------
    377402

SQL> select/*+ OPT_PARAM('_fix_control' '4887636:0')*/ count(*) from test_table;

  COUNT(*)
----------
    377402

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor('','',format => '+outline'));

PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID  52cn95s3s51t9, child number 1 -- **
-------------------------------------
...
Outline Data
-------------

  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('12.1.0.2')
      DB_VERSION('12.1.0.2')
      OPT_PARAM('_fix_control' '4887636:0') -- ***
...
      END_OUTLINE_DATA
  */


SQL> select/*+ OPT_PARAM('_fix_control' '4887636:0')*/ count(*) from test_table;

  COUNT(*)
----------
    377402

SQL> SELECT * FROM TABLE(dbms_xplan.display_cursor());

PLAN_TABLE_OUTPUT
-------------------------------------
SQL_ID  52cn95s3s51t9, child number 2 -- ****
-------------------------------------
...

Подправил скрипт SHARED_CU12_NOXML.SQL для быстрой диагностики такого рода проблем:

SQL> @shared_cu12_noxml 52cn95s3s51t9
 
EXECS LAST_LOAD_TIME       LAST_ACTIVE_TIME    ELA_PER_EXEC CURSOR_STATUS PLAN_HASH_VALUE FULL_PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE USE_FEEDBACK_STATS REOPT REASON#1               FIX_CONTROL#1         
----- -------------------- ------------------- ------------ ------------- --------------- -------------------- -------------- ----- ---------- ------------------ ----- ---------------------- ----------------------
    1 2015-11-08/15:19:26  08.11.2015 15:19:28      2803056 VALID              2513758755           3820356417          11395     0 N          N                  N     Optimizer mismatch(12) 820120037            0
    1 2015-11-08/15:19:34  08.11.2015 15:19:34        78612 VALID              2513758755           3820356417          11395     1 N          N                  N     Optimizer mismatch(12) 820120037            0
    1 2015-11-08/15:20:08  08.11.2015 15:20:07        86112 VALID              2513758755           3820356417          11395     2 N          N                  N

Возвращаясь к проблемному запросу, попытки отключить hardcoded хинт /*+ OPT_PARAM(‘_fix_control’ ‘4887636:0’)*/ адмистративными методами, например, через SQL Patch с подсказками IGNORE_OPTIM_EMBEDDED_HINTS или OPT_PARAM(‘_fix_control’ ‘4887636:on’) не имели успеха, при этом в последнем случае после создания патча:

SQL> @sqlpatch+
&SQL_ID: 45u45mpanbatr
&SQL_PATCH_TEXT: OPT_PARAM(''_fix_control'' ''4887636:1'')
&SQL_PATCH_NAME: SQLPLAN_FIX-870
 
PL/SQL procedure successfully completed
 
SQL_ID        NAME            CATEGORY CREATED               STATUS   FMATCH
------------- --------------- -------- --------------------- -------- ------
45u45mpanbatr SQLPLAN_FIX-870 DEFAULT  06.11.2015 14:39:46   ENABLED  NO
 
SQL_PATCH_HINTS
-------------------------------------
OPT_PARAM('_fix_control' '4887636:1')

несмотря на то, что вписанная в запрос подсказка /*+ OPT_PARAM(‘_fix_control’ ‘4887636:0’)*/ в Outline Data плана, как и ожидалось/требовалось, не попала, т.е. SQL Patch действовал, это не уменьшало генерацию курсоров (!):

SQL> @shared_cu12_noxml 45u45mpanbatr
 
EXECS LAST_LOAD_TIME       LAST_ACTIVE_TIME    CURSOR_STATUS  PLAN_HASH_VALUE OPTIMIZER_COST CHILD BIND_SENSE BIND_AWARE SHAREABLE REASON#1               REASON#2               FIX_CONTROL#1          FIX_CONTROL#2          SQL_PATCH
----- -------------------- ------------------- -------------- --------------- -------------- ----- ---------- ---------- --------- ---------------------- ---------------------- ---------------------- ---------------------- ---------------
    1 2015-11-06/15:30:44  06.11.2015 15:31:00 INVALID_UNAUTH      2907472699          27199     0 Y          N          Y         Optimizer mismatch(12) Optimizer mismatch(12) -1478960655          0 820120037            0 SQLPLAN_FIX-870
    1 2015-11-06/16:08:34  06.11.2015 16:08:46 INVALID_UNAUTH      2907472699          27199     1 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/16:45:44  06.11.2015 16:45:44 INVALID_UNAUTH      2907472699          27252     2 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:30  06.11.2015 18:31:42 INVALID_UNAUTH      2907472699          27229     3 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:44  06.11.2015 18:31:43 INVALID_UNAUTH      2907472699          27229     4 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:45  06.11.2015 18:31:45 INVALID_UNAUTH      2907472699          27207     6 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:45  06.11.2015 18:31:44 INVALID_UNAUTH      2907472699          27207     5 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:46  06.11.2015 18:31:46 INVALID_UNAUTH      2907472699          27207     7 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:47  06.11.2015 18:31:46 INVALID_UNAUTH      2907472699          27207     8 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:48  06.11.2015 18:31:48 INVALID_UNAUTH      2907472699          27194    10 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:48  06.11.2015 18:31:47 INVALID_UNAUTH      2907472699          27194     9 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:49  06.11.2015 18:31:49 INVALID_UNAUTH      2907472699          27194    11 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:50  06.11.2015 18:31:49 INVALID_UNAUTH      2907472699          27194    12 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:51  06.11.2015 18:31:50 INVALID_UNAUTH      2907472699          27195    13 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:52  06.11.2015 18:31:51 INVALID_UNAUTH      2907472699          27195    14 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:52  06.11.2015 18:31:52 INVALID_UNAUTH      2907472699          27252    15 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:53  06.11.2015 18:31:53 INVALID_UNAUTH      2907472699          27252    16 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:54  06.11.2015 18:31:53 INVALID_UNAUTH      2907472699          27199    17 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870
    1 2015-11-06/18:31:55  06.11.2015 18:31:54 INVALID_UNAUTH      2907472699          27199    18 Y          N          Y         Optimizer mismatch(12)                        -1478960655          0                        SQLPLAN_FIX-870

— одно выполнения = один курсор, вплоть до хирургического вмешательства физического устранения хинта из текста запроса

Ещё один аргумент против использования hardcoded подсказок

UPD. Проблема оказалась общеизвестной — Bug 20476175 High VERSION_COUNT (in V$SQLAREA) for query with OPT_PARAM(‘_fix_control’) hint, исправлено в 12.1.0.2.5 (Oct 2015) Database Patch Set Update (DB PSU)

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

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

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