Oracle mechanics

17.05.2015

12c: конкуренция при компиляции курсоров

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

После обновления бд до версии 12.1.0.2 столкнулись с проблемой блокировок курсоров, сопровождавшей замедлившийся процесс разбора (parse) некоторых запросов, и материально выраженой большим кол-вом/долей ожиданий cursor: pin S wait on X и library cache lock в ASH/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                941      60,9K   64747.53   50.3 Concurrency
DB CPU                                          42,5K              35.1         
library cache lock                  20,478     6681,6     326.28    5.5 Concurrency

Наблюдение в режиме реального времени позволило достаточно быстро и пОлно диагностировать и разрешить проблему, начиная с топа запросов по ожиданиям:

SQL> select inst_id,
  2         sql_id,
  3         sql_plan_hash_value,
  4         sql_exec_id,
  5         sql_plan_operation,
  6         in_parse,
  7         in_hard_parse,
  8         in_sql_execution,
  9         count(*)
 10    from gv$active_session_history
 11   where event in ('library cache lock', 'cursor: pin S wait on X')
 12   group by inst_id,
 13            sql_id,
 14            sql_plan_hash_value,
 15            sql_exec_id,
 16            sql_plan_operation,
 17            in_parse,
 18            in_hard_parse,
 19            in_sql_execution
 20  having count(*) > 3000
 21   order by count(*) desc
 22  /
 
INST_ID SQL_ID        SQL_PLAN_HASH_VALUE SQL_EXEC_ID SQL_PLAN_OPERATION IN_PARSE IN_HARD_PARSE IN_SQL_EXECUTION   COUNT(*)
------- ------------- ------------------- ----------- ------------------ -------- ------------- ---------------- ----------
      2 fppuw3hpvww2d                   0                                Y        N             Y                     29864
      2 fppuw3hpvww2d          1453096163                                Y        N             Y                      3570
      2 ag930sspt2546          2736432056             INSERT STATEMENT   N        N             Y                      3030

, который указывает на запрос fppuw3hpvww2d, на этапе parse которого (SQL_PLAN_LINE_ID is null) сессии циклически ожидали друг друга:

SQL> @ash_sql_wait_tree "sql_id = 'fppuw3hpvww2d' and event in ('library cache lock', 'cursor: pin S wait on X')"
 
LVL INST_ID BLOCKING_TREE   EVENT                    WAIT_CLASS WAITS_COUNT EXECS_COUNT SESS_COUNT AVG_WA SQL_ID        SQL_OPNAME  BLOCK_SID      SQL_PLAN_LINE_ID
--- ------- --------------- ------------------------ ---------------------- ----------- ---------- ------ ------------- ----------- -------------- ----------------
  1       1 FOREGROUND      cursor: pin S wait on X  Concurrency       8437           0         46   1157 fppuw3hpvww2d SELECT      VALID i#1      
  1       2 FOREGROUND      cursor: pin S wait on X  Concurrency       6261           0         38   1280 fppuw3hpvww2d SELECT      VALID i#2      
  1       2 FOREGROUND      library cache lock       Concurrency        758           2         14      0 fppuw3hpvww2d SELECT      VALID i#2      
  1       1 FOREGROUND      library cache lock       Concurrency        616           2          8    314 fppuw3hpvww2d SELECT      GLOBAL i#      
  1       1 FOREGROUND      library cache lock       Concurrency         90           0          1      0 fppuw3hpvww2d SELECT      VALID i#1      
  1       2 FOREGROUND      library cache lock       Concurrency          4           2          4   3271 fppuw3hpvww2d SELECT      GLOBAL i#      
  2       1   FOREGROUND    library cache lock       Concurrency       8476           0          8    251 fppuw3hpvww2d SELECT      GLOBAL i#      
  2       2   FOREGROUND    library cache lock       Concurrency       6444           0          7      0 fppuw3hpvww2d SELECT      VALID i#2      
  2       2   FOREGROUND    On CPU / runqueue                           533           3          5      0 fppuw3hpvww2d SELECT      NOT IN WAIT i# 
  2       1   FOREGROUND    On CPU / runqueue                            51           0          3      0 fppuw3hpvww2d SELECT      NOT IN WAIT i# 
  2       2   FOREGROUND    library cache lock       Concurrency         42           0          2      0 fppuw3hpvww2d SELECT      GLOBAL i#      
  3       2     FOREGROUND  On CPU / runqueue                          6444           3          3      0 fppuw3hpvww2d SELECT      NOT IN WAIT i#

Модифицированный стандартный запрос kgllockpin.sql показавал более любопытное поведение:

SQL> @kgllockpin.sql
 
HANDLER          KGLLKTYPE  NAMESP                  KGLOBTYD               KGLNAOWN  KGLNAOBJ              MODE_HELD  MODE_REQ   SECS_IN_WAIT EVENT              SECONDS_IN_WAIT SID    SERIAL  PROGRAM                         SQL_ID        SQL_TEXT
---------------- ---------- ----------------------- ---------------------- --------- --------------------- ---------- ---------- ------------ ------------------ --------------- ------ ------- ------------------------------- ------------- -------------
0000002839234B48 Lock       SQL TUNING BASE OBJECT  SQL TUNING BASE OBJECT           10360884871991321708  None       Share      118          library cache lock             118 335    62088   STANDART@appl2.net (TNS V1-V3)  fppuw3hpvww2d SELECT * FROM
0000002839234B48 Lock       SQL TUNING BASE OBJECT  SQL TUNING BASE OBJECT           10360884871991321708  Exclusive  None       52           direct path read                52 80     13882   STANDARD@appl1.net (TNS V1-V3)  fppuw3hpvww2d SELECT * FROM
0000002839234B48 Pin        SQL TUNING BASE OBJECT  SQL TUNING BASE OBJECT           10360884871991321708  Exclusive  None       52           direct path read                52 80     13882   STANDARD@appl1.net (TNS V1-V3)  fppuw3hpvww2d SELECT * FROM
000000283D743800 Lock       SQL AREA BUILD          CURSOR                 $BUILD$   ead75c1c2bbe704d      Exclusive  None       118          library cache lock             118 335    62088   STANDART@appl2.net (TNS V1-V3)  fppuw3hpvww2d SELECT * FROM
000000283D743800 Lock       SQL AREA BUILD          CURSOR                 $BUILD$   ead75c1c2bbe704d      None       Share      118          library cache lock             118 1507   62599   STANDART@appl2.net (TNS V1-V3)  fppuw3hpvww2d SELECT * FROM

— т.е. в рассматриваемом типичном случае некая сессия (SID=80, 2-я и 3-я строки) активно что-то читают через direct path read, при этом блокируя как на объекте относительно нового типа SQL TUNING BASE OBJECT, так и на привычном объекте CURSOR другие сессии с Shared Pool ожиданиями library cache lock, как в данном случае

ASH-мониторинг планов блокирующих выполнений/сессий ничего ценного не даёт:

SQL> @ash_sqlmon2 fppuw3hpvww2d 1279999842 33554517
 
LAST_PLSQL   SQL_ID        PLAN_HASH_VALUE   ID PLAN_OPERATION                    PX MAX_TEMP_SPACE_ALLOCATED   ASH_ROWS WAIT_PROFILE
------------ ------------- --------------- ---- --------------------------------- -- ------------------------ ---------- --------------------------------------------------------------------
Main Query   fppuw3hpvww2d      1279999842    0   SELECT STATEMENT                 0                   393216       2080 ON CPU(2080)
                                              1     SORT AGGREGATE                                                       
...
                                            679         TABLE ACCESS FULL                                                
SQL Summary                              0    0 ASH fixed 1 execs from 1 sessions                                   2080  ash rows were fixed from 13.05.2015 12:00:00 to 13.05.2015 12:34:42

, в отличие от sql trace, который заполнен многократно повторяющимися операциями типа:

*** 2015-05-13 12:34:49.636
FETCH #140522313042784:c=1000,e=385,p=0,cr=2,cu=0,mis=0,r=1,dep=2,og=4,plh=1986334933,tim=6559577820008
LOBGETLEN: type=TEMPORARY LOB,bytes=74192,c=0,e=5,p=0,cr=0,cu=0,tim=6559577820091
LOBREAD: type=TEMPORARY LOB,bytes=74192,c=58000,e=58333,p=0,cr=0,cu=0,tim=6559577878456

*** 2015-05-13 12:34:52.231
FETCH #140522313042784:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=1986334933,tim=6559580415146
...

— относящимися к рекурсивному запросу:

PARSING IN CURSOR #140522313042784 len=1221 dep=2 uid=0 oct=3 lid=0 tim=6559396293135 hv=3402707883 ad='27bb8fd2c0' sqlid='5um3s635d2cxb'
SELECT ...,
       EXTRACTCLOBXML(other_xml, '/*/outline_data') outline
  FROM sqlobj$plan
 WHERE signature = :1
   AND category = :2
 ORDER BY signature, category, obj_type, plan_id, id
END OF STMT

, который, в свою очередь, показывает, что под объектом SQL TUNING BASE OBJECT имеется в виду что-то из области SQL Plan Management (SPM), вероятнее всего baseline, что можно незамедлительно проверить на наличие:

SQL> @spm_check4sql_id fppuw3hpvww2d
 
SIGNATURE             SPM_TYPE          SQL_HANDLE            PLAN_NAME                      ORIGIN         VERSION    LAST_MODIFIED       LAST_EXECUTED       LAST_VERIFIED       ENABLED ACCEPTED FIXED REPRODUCED AUTOPURGE
--------------------- ----------------- --------------------- ------------------------------ -------------- ---------- ------------------- ------------------- ------------------- ------- -------- ----- ---------- ---------
 10360884871991321708 SQL Plan Baseline SQL_8fc941e591c2e46c  SQL_PLAN_8zka1wq8w5t3c69194ff6 AUTO-CAPTURE   12.1.0.2.0 12.05.2015 19:25:34                                         YES     NO       NO    YES        YES
 10360884871991321708 SQL Plan Baseline SQL_8fc941e591c2e46c  SQL_PLAN_8zka1wq8w5t3c7ecd15e2 AUTO-CAPTURE   12.1.0.2.0 13.05.2015 10:21:27                                         YES     NO       NO    YES        YES
 10360884871991321708 SQL Plan Baseline SQL_8fc941e591c2e46c  SQL_PLAN_8zka1wq8w5t3ca0b32c79 AUTO-CAPTURE   12.1.0.2.0 12.05.2015 18:11:30                                         YES     NO       NO    YES        YES

— значение SIGNATURE в точности соответствует связанным переменным проблемно-рекурсивного запроса:

Peeked Binds (identified by position):
--------------------------------------
 
   1 - :1 (VARCHAR2(30), CSID=171): '10360884871991321708'
   2 - :2 (VARCHAR2(30), CSID=171): 'DEFAULT'

На первый взгляд сам факт автоматического (тип AUTO-CAPTURE) создания baseline-ов может казаться неожиданным при по умолчанию отключенном параметре автоматического создания:

SQL> @param optimizer_capture_sql_plan_baselines
 
NAME                                  VALUE  IS_DEF  IS_MOD  DSC
------------------------------------- ------ ------- ------- -----------------------------------------------------------------
optimizer_capture_sql_plan_baselines  FALSE  TRUE    FALSE   automatic capture of SQL plan baselines for repeatable statements

Но только на первый взгляд: из документации New Non-Accepted Plans Appear in DBA_SQL_PLAN_BASELINES Regardless Of How optimizer_capture_sql_plan_baselines Is Set (Doc ID 1520337.1) можно узнать, что автоматическое создание baseline-ов (запросы к содержимому которых замедляло/блокировало parsing в нашем случае) нежёстко определяется параметром и, в частности, возможно по историческим причинам:

This can happen when optimizer_capture_sql_plan_baselines = FALSE and one or more baselines have been created in the past…

— похоже на наш случай, но это лишь сопутствующая неопределяющая проблема

Основная проблема — долгое выполнение рекурсивных запросов с EXTRACTCLOBXML, что отмечено в Bug 20758617 : LOAD SMO PLAN ROWS QUERY IS VERY EXPENSIVE IN 12.1.0.2 с соответствующим Patch 20877664: EXTRACTCLOBXML, REPEATING PREVIOUS VALUES FOR NULL INPUT (FXD), уже готовым для x86_64 12.1.0.2 — надо тестировать и ставить)

В итоге проблема успешно решилась в несколько шагов:

1) удаление ненужных автоматических baseline-ов, которые, как справедливо предсказал Леонид, удалялить со скоростью, обратно пропорциональной кол-ву оставшихся в репозитории baseline-ов:)

SQL> @bl_drop SQL_PLAN_8zka1wq8w5t3c7ecd15e2 -- предпоследний
 
PL/SQL procedure successfully completed
 
Executed in 939,969 seconds
 
SQL> @bl_drop SQL_PLAN_8zka1wq8w5t3ca0b32c79 -- последний
 
PL/SQL procedure successfully completed
 
Executed in 68,281 seconds

— очевидно, по той же причине длинных рекурсивных запросов

2) до установки патча во избежание повторной генерации автоматических baseline-ов и, как следствие, проблем с рекурсивными запросами и конкуренцией в кэше курсоров, необходимо присутствие для запроса зафиксированного baseline-а (FIXED=YES), что и было сделано в ручном (MANUAL-LOAD) режиме:

SQL> @spm_check4sql_id fppuw3hpvww2dfppuw3hpvww2d
 
SIGNATURE            SPM_TYPE          SQL_HANDLE            PLAN_NAME                      ORIGIN       VERSION    LAST_MODIFIED       ENABLED ACCEPTED FIXED REPRODUCED AUTOPURGE
-------------------- ----------------- --------------------- ------------------------------ ------------ ---------- ------------------- ------- -------- ----- ---------- ---------
10360884871991321708 SQL Plan Baseline SQL_8fc941e591c2e46c  SQL_PLAN_8zka1wq8w5t3c6bbb0ecd MANUAL-LOAD  12.1.0.2.0 13.05.2015 14:36:58 YES     YES      YES   YES        NO

В рез-те ср.время выполнения запроса значительно сократилось:

SQL> @dba_hist_sqlstat "sql_id = 'fppuw3hpvww2d' and snap_id between 85345 and 85355 and executions_delta > 0"
 
INST BEGIN_SNAP_ID BEGIN_SNAP_TIME EXECS ROWS_PROCESSED SQL_ID              PLAN   COST ELA_PER_EXEC CPU_PER_EXEC CCWAITS_PER_EXEC
---- ------------- --------------- ----- -------------- ------------- ---------- ------ ------------ ------------ ----------------
   1         85344 13.05 10:30         6             55 fppuw3hpvww2d 2105483639   4477   1247259606    949454667        195533318
   2         85345 13.05 11:00         1             37 fppuw3hpvww2d 1279999842   4477   5530113562   2846149000       2670883410
   2         85346 13.05 11:30         1              0 fppuw3hpvww2d 1279999842   4477   3604784644   2086719000       1509428965
   2         85351 13.05 14:00         1              0 fppuw3hpvww2d 1345490355 134159     75627688     40641000             1960 -- добавлен фиксированный Baseline
   2         85352 13.05 14:30         1             20 fppuw3hpvww2d 1345490355 134159    103381684     86935000             3453
   1         85354 13.05 15:30         3            171 fppuw3hpvww2d 1345490355 134159     93474305     77273333            17893
   2         85354 13.05 15:30         7            539 fppuw3hpvww2d 1345490355 134159     74579192     73243571            35153

— как в результате сокращения CPU_PER_EXEC (исключение рекурсивных запросов), так и за счёт сокращения времени курсорных ожиданий класса Concurrency (CCWAITS_PER_EXEC)

Некоторые другие проблемы обновления на 12.1.0.2 описал Максим Филатов

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

  1. Леонид, установив-потестировав патч для исправления бага 20877664: EXTRACTCLOBXML, REPEATING PREVIOUS VALUES FOR NULL INPUT, наглядно продемонстрировал коварство последнего

    До установки патча вышеупомянутый рекурсивный запрос, точнее, EXTRACTCLOBXML в этом запросе:

    SQL> select id,
      2         nvl(dbms_lob.getlength(EXTRACTCLOBXML(other_xml, '/*/outline_data')), 0) OUTLINE_LENGTH
      3    FROM sys.sqlobj$plan a
      4   WHERE signature = 10360884871991321708
      5     AND category = 'DEFAULT'
      6   ORDER BY 1;
     
      ID OUTLINE_LENGTH
    ---- --------------
       0              0
       1              0
       2              0
       3              0
       4              0
       5              0
       6              0
       7              0
       8              0
       9              0
      10              0
      11              0
      12              0
      13              0
      14          73912 -- cчитал непустыми пустые LOB-ы, начиная с первого ненулевого
      15          73912
      16          73912
    ...
     568          73912
     569          73912
     
    570 rows selected

    , после установки патча функция EXTRACTCLOBXML, как и дОлжно, возвращает OUTLINE_DATA лишь для одного непустого CLOB-а:

    SQL> select id,
      2         nvl(dbms_lob.getlength(EXTRACTCLOBXML(other_xml, '/*/outline_data')), 0) OUTLINE_LENGTH
      3    FROM sys.sqlobj$plan a
      4   WHERE signature = 10360884871991321708
      5     AND category = 'DEFAULT'
      6   ORDER BY 1;
     
            ID OUTLINE_LENGTH
    ---------- --------------
             0              0
             1              0
             2              0
             3              0
             4              0
             5              0
             6              0
             7              0
             8              0
             9              0
            10              0
            11              0
            12              0
            13              0
            14          73912
            15              0
            16              0
    ...
           569              0
     
    570 rows selected

    комментарий от Игорь Усольцев — 19.05.2015 @ 14:35 | Ответить


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