Oracle mechanics

14.10.2012

Library cache lock deadlock

Недавно наблюдали в некотором роде замечательный интересный описанием процесса параллельного разбора Bug 14356507 — Deadlock between partition maintenance and parallel query operations [ID 14356507.8]:

Library cache lock deadlock can occur between parallel query and a DDL (Eg: partition maintenance operations) on the same objects.
When a parallel query is hard parsed, first QC hard parses the query and then all the slaves. When a partition maintenance operation (DDL) comes in between the hard parses of QC and Slaves.

The QC holds the library cache lock in shared mode when the query is being hard parsed by the slaves. The exclusive mode requests from the session performing the DDL operation will block the parallel query getting the same lock in shared mode. At the same time, the exclusive request will not be served as the QC is holding the lock in shared mode and waiting for the slaves to complete the parsing.

This fix removes this limitation and the  slaves should get the lock in EXPRESS mode when the QC holds the same lock.

— сложный разбор (hard parse) параллельного запроса состоит из нескоскольких частей: вначале Query Coordinator, затем разбор выполняют PX Slaves. Deadlock возникает, когда на реально нагруженной OLTP системе сторонний запрос попытается получить блокировку Lock между этими событиями

В нашем случае deadlock проявлялся при одновременном параллельном DDL на партиции индекса:

alter index t1_idx rebuild partition SYS_P18934 online parallel 5

и случайно попавшим DML удаления строк из той же таблицы

delete from t1 where dt between :dt1 and :dt2


Картина интересующих блокировок типа Lock выглядела следующим образом: QC ожидал успешного разбора запроса PX Deq: Parse Reply от одного из PX Slave процессов, остальные участники ожидали блокировок library cache lock / row cache lock:

11.2.0.3.@ SQL> select kgllkmod as LOCKMOD, kgllkreq as LOCKREQ, SECONDS_IN_WAIT, event, p1raw, sid, serial#, program, sql_text
  2    from dba_kgllock w, v$session s, v$sqlarea a
  3   where w.kgllkuse = s.saddr
  4     and w.kgllkhdl in ('0000000CCF4F6E60', '0000000CBB910C38')
  5     and s.sql_address = a.address
  6     and s.sql_hash_value = a.hash_value;

LOCKMOD LOCKREQ SECONDS_IN_WAIT EVENT               P1RAW             SID SERIAL# PROGRAM                    SQL_TEXT
------- ------- --------------- ------------------- ---------------- ---- ------- -------------------------- ------------------------------------------------------------------
      0       2            2684 library cache lock  0000000CCF4F6E60  122   62575 prog2@userhost (TNS V1-V3) delete from t1 where dt between :dt1 and :dt2
      2       0               0 row cache lock      0000000000000008  405   21343 oracle@db1.host.ru (P002)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      0       2           32189 library cache lock  0000000CBB910C38  692   60431 oracle@db1.host.ru (P009)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      0       2           32189 library cache lock  0000000CBB910C38  508   53095 oracle@db1.host.ru (P007)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      0       2           32189 library cache lock  0000000CBB910C38 1457   29841 oracle@db1.host.ru (P005)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      0       2           32189 library cache lock  0000000CBB910C38  601   61511 oracle@db1.host.ru (P008)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      0       2           32189 library cache lock  0000000CBB910C38    6   57625 oracle@db1.host.ru (P000)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      0       2           32189 library cache lock  0000000CBB910C38  400   32627 oracle@db1.host.ru (P006)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      0       2           32189 library cache lock  0000000CBB910C38  505   45049 oracle@db1.host.ru (P003)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      0       2           32189 library cache lock  0000000CBB910C38  588   42227 oracle@db1.host.ru (P004)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      0       2           32189 library cache lock  0000000CBB910C38  307    5791 oracle@db1.host.ru (P001)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      3       0               0 row cache lock      0000000000000008  405   21343 oracle@db1.host.ru (P002)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
      2       0               0 row cache lock      0000000000000008  405   21343 oracle@db1.host.ru (P002)   alter index T1_IDX rebuild partition SYS_P18934 online parallel 5

Процессы конкурировали за следующие объекты Library Cache:

SQL> select * from x$kglob where kglhdadr in ('0000000CCF4F6E60','0000000CBB910C38');

INST_ID KGLHDADR         KGLNAOWN  KGLNAOBJ         KGLHDNSP KGLHDNSD        KGLOBTYP KGLOBTYD
------- ---------------- --------- ---------------- -------- --------------- -------- --------
      1 0000000CCF4F6E60 SCOTT     T1                      1 TABLE/PROCEDURE        2 TABLE
      1 0000000CBB910C38 $BUILD$   27695ad9bfd92ed7       82 SQL AREA BUILD         0 CURSOR

Содержимое hanganalyze level 3 trace достаточно точно совпадало с описанием бага:

Chains most likely to have caused the hang:
 [a] Chain 1 Signature: 'row cache lock'<='library cache lock'<='PX Deq: Parse Reply'
     Chain 1 Signature Hash: 0xb633f060
 [b] Chain 2 Signature: 'row cache lock'<='library cache lock'
     Chain 2 Signature Hash: 0x90c0c0fe
...
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 1 (ORCL.ORCL1)
                   os id: 16082
              process id: 124, oracle@db1.host.ru (J001)
              session id: 1172
        session serial #: 27045
    }
    is waiting for 'PX Deq: Parse Reply' with wait info: -- QC ожидал на этом характерном событии
    {
                      p1: 'sleeptime/senderid'=0xc8
                      p2: 'passes'=0x4736
            time in wait: 493 min 54 sec
           timeout after: never
                 wait id: 659329
                blocking: 0 sessions
             current sql: alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwaitctx()+163<-kxfpqidqr()+2902<-kxfpqdqr()+367<-kxfxgs()+51<-kxfxcp()+859<-qerpxSendParse()+1059<-kxfpValidateSlaveGroup()+192<-kxfpgsg()+4698<-kxfrAllocSlaves()+483<-kxfrialo()+2589<-kxfralo()+318<-qerpx_rowsrc_start()+1352<-qerpxStart()+578<-kdicrws()+1648<-kdicdrv()+500<-opiexe()+21741<-opiosq0()+3870<-opipls()+11479<-opiodr()+916<-rpidrus()+211<-skgmstack()+148<-rpiswu2()+638<-rpidr
            wait history:
...
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (ORCL.ORCL1)
                   os id: 3990
              process id: 151, oracle@db1.host.ru (P009)
              session id: 692
        session serial #: 60431
    }
    which is waiting for 'library cache lock' with wait info:
    {
                      p1: 'handle address'=0xcbb910c38
                      p2: 'lock address'=0xcbd6cea48
                      p3: '100*mode+namespace'=0x520002
            time in wait: 493 min 54 sec
           timeout after: never
                 wait id: 2
                blocking: 1 session
             current sql: alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-__poll()+47<-ssskgxp_poll()+40<-sskgxp_select()+263<-skgxpiwait()+3680<-skgxpwaiti()+1544<-skgxpwait()+162<-ksxpwait()+2501<-ksliwat()+12852<-kslwaitctx()+163<-ksfwaitctx()+14<-kglLockWait()+837<-kgllkal()+1147<-kglLock()+1843<-kglget()+343<-kksGetBuildLock()+365<-kksfbc()+12550<-kkspsc0()+1173<-kksParseCursor()+116<-opiosq0()+1965<-kpooprx()+274<-kpoal8()+829<-opiodr()+916<-kpoodr()+653<-upirtrc()+2497<-kpurcsc()+98<-kpuexec()+10807<-OCIS
            wait history:
...
    }
    and is blocked by
 => Oracle session identified by:
    {
                instance: 1 (ORCL.ORCL1)
                   os id: 14193
              process id: 116, oracle@db1.host.ru (P002)
              session id: 405
        session serial #: 21343
    }
    which is waiting for 'row cache lock' with wait info:
    {
                      p1: 'cache id'=0x8
                      p2: 'mode'=0x0
                      p3: 'request'=0x3
            time in wait: 2.840711 sec
      heur. time in wait: 253 min 26 sec
           timeout after: 0.159289 sec
                 wait id: 4623
                blocking: 11 sessions
             current sql: alter index T1_IDX rebuild partition SYS_P18934 online parallel 5
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-__poll()+47<-ssskgxp_poll()+40<-sskgxp_select()+263<-skgxpiwait()+3680<-skgxpwaiti()+1544<-skgxpwait()+162<-ksxpwait()+2501<-ksliwat()+12852<-kslwaitctx()+163<-kqrigt()+1148<-kqrLockAndPinPo()+870<-kqrpre1()+885<-kkpoffoc_find_frag_obj_cache()+357<-kkmpreddl()+1288<-kkmpre()+23<-opiSem()+1175<-opiprs()+293<-kksParseChildCursor()+569<-rpiswu2()+1618<-kksLoadChild()+5167<-kxsGetRuntimeLock()+2152<-kksfbc()+14972<-kkspsc0()+1173<-kksParseCurs
            wait history:
...
    }

Chain 1 Signature: 'row cache lock'<='library cache lock'<='PX Deq: Parse Reply'
Chain 1 Signature Hash: 0xb633f060
-------------------------------------------------------------------------------
-------------------------------------------------------------------------------

===============================================================================
Intersecting chains:

-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
    Oracle session identified by:
    {
                instance: 2 (ORCL.ORCL2)
                   os id: 27119
              process id: 307, oracle@db2.host.ru (J004) -- Job с другого инстанса
              session id: 316
        session serial #: 40953
    }
    is waiting for 'library cache lock' with wait info:  -- был также блокирован
    {
                      p1: 'handle address'=0xcd79d3c78
                      p2: 'lock address'=0xcbd6dae60
                      p3: '100*mode+namespace'=0xb6cca00010003
            time in wait: 253 min 25 sec
           timeout after: never
                 wait id: 1697631
                blocking: 0 sessions
             current sql: begin DBMS_STATS.CLEANUP_STATS_JOB_PROC(:1,:2,:3,:4,:5); end; -- системное задание по сбору статистики завершается неудачно
             short stack: ksedsts()+461<-ksdxfstk()+32<-ksdxcb()+1876<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+1865<-kslwaitctx()+163<-kjusuc()+3619<-ksipgetctxi()+1759<-kqlmLock()+2849<-kqlmClusterLock()+191<-kgllkal()+2109<-kglLock()+1843<-kglget()+343<-qostobkglcrt1()+590<-qostobkglcrt()+262<-qospsts()+1625<-spefcmpa()+196<-spefmccallstd()+235<-pextproc()+41<-peftrusted()+150<-psdexsp()+255<-rpiswu2()+1618<-psdextp()+700<-pefccal()+726<-pefcal()+224<-pevm_FCAL()+169<-pfrinstr_FCAL()+75<-pfrrun_no_tool(
            wait history:
              * time between current wait and wait #1: 0.000739 sec
...
    }
    and is blocked by 'instance: 1, os id: 14193, session id: 405', -- , блокирующая сессия SID=405 с первого инстанса
    which is a member of 'Chain 1'.

Chain 2 Signature: 'row cache lock'<='library cache lock'

— как указано в комментариях к Chain 2, в результате deadlock пострадало системное задание по сбору статистики, запущенное на соседнем инстансе 2, ожидавшее library cache lock, и блокированное в течение длительного времени сессией SID=405 (V$SESSION.SADDR = ‘0000000CA0E4C840’) одного из PX Slave процессов на 1-м инстансе на том же объекте Library Cache — таблице T1:

SQL> select * from dba_kgllock where KGLLKHDL in ('0000000CCF4F6E60','0000000CBB910C38')
  2  /

KGLLKUSE         KGLLKHDL           KGLLKMOD   KGLLKREQ KGLLKTYPE
---------------- ---------------- ---------- ---------- ---------
0000000CD8D1D850 0000000CCF4F6E60          0          2 Lock
0000000CA0E4C840 0000000CCF4F6E60          2          0 Lock -- SID=405 удерживает Lock на T1 в Shared Mode
0000000CB0E92368 0000000CBB910C38          0          2 Lock
0000000CB0DFD498 0000000CBB910C38          0          2 Lock
0000000CA1161D28 0000000CBB910C38          0          2 Lock
0000000CA0ED8818 0000000CBB910C38          0          2 Lock
0000000CD8CE4ED8 0000000CBB910C38          0          2 Lock
0000000CB0DBEBD0 0000000CBB910C38          0          2 Lock
0000000CA0E91058 0000000CBB910C38          0          2 Lock
0000000CB0E50AF8 0000000CBB910C38          0          2 Lock
0000000CA8D842D0 0000000CBB910C38          0          2 Lock
0000000CA0E4C840 0000000CBB910C38          3          0 Lock -- SID=405удерживает Lock на Cursor в Exclusive Mode
0000000CA0E4C840 0000000CCF4F6E60          2          0 Pin  -- SID=405 удерживает Pin на T1 в Shared Mode

Проблема была обсуждена и локализована с помощью техподдержки большого Oracle, представители которого поначалу настоятельно рекомендовали отключить параллельное выполнение проблемного DDL (!), но в итоге дали согласие на установку существующего для платформы Oracle 11.2.0.3 Linux x86_64 патча — слава Exadate!

P.S. Последствия описанной в документе MOS поэтапной технологии parallel query hard parse можно заметить не только по увеличивающемуся с ростом DOP version count:

SQL> select sample_time,
  2         program,
  3         sql_child_number as SQL_CHILD,
  4         sql_opname,
  5         sql_plan_operation ||' '|| sql_plan_options as PLAN_OPERATION,
  6         session_state,
  7         event
  8    from dba_hist_active_sess_history
  9   where instance_number = 2
 10     and sql_id = '9s1vaq16a1akv'
 11     and sql_exec_id = 33554437
 12     and sample_id = 213714076
 13  /

SAMPLE_TIME           PROGRAM                   SQL_CHILD SQL_OPNAME PLAN_OPERATION          SESSION_STATE EVENT
--------------------- ------------------------- --------- ---------- ----------------------  ------------- ----------------------
20.08.12 18:24:37,737 oracle@db2.host.ru (P032)        81 SELECT     HASH JOIN ANTI BUFFERED WAITING       direct path write temp
20.08.12 18:24:37,737 oracle@db2.host.ru (P026)        75 SELECT     SORT JOIN               ON CPU
20.08.12 18:24:37,737 oracle@db2.host.ru (P033)        83 SELECT     HASH JOIN ANTI BUFFERED WAITING       direct path write temp
20.08.12 18:24:37,737 oracle@db2.host.ru (P028)        76 SELECT     HASH JOIN ANTI BUFFERED WAITING       direct path write temp
20.08.12 18:24:37,737 oracle@db2.host.ru (P034)        82 SELECT     HASH JOIN ANTI BUFFERED ON CPU
20.08.12 18:24:37,737 oracle@db2.host.ru (P029)        73 SELECT     HASH JOIN ANTI BUFFERED WAITING       direct path write temp
20.08.12 18:24:37,737 oracle@db2.host.ru (P035)        86 SELECT     HASH JOIN ANTI BUFFERED WAITING       direct path write temp
20.08.12 18:24:37,737 oracle@db2.host.ru (P022)        80 SELECT     SORT JOIN               ON CPU
20.08.12 18:24:37,737 oracle@db2.host.ru (P031)        85 SELECT     HASH JOIN ANTI BUFFERED WAITING       direct path write temp

, но и по наблюдаемой по данным Active Session History возможности использования одним PX Slave процессом нескольких дочерних курсоров в течение выполнения одного запроса (вероятно, на разных шагах выполнения/ в разных parallel sets ?):

SQL> with sql_exec2child as
  2   (select inst_id, sql_exec_start, sql_id, sql_exec_id
  3      from (select inst_id,
  4                   sql_exec_start,
  5                   sql_opname,
  6                   sql_id,
  7                   sql_exec_id,
  8                   program,
  9                   count(distinct sql_child_number)
 10              from gv$active_session_history
 11             where sql_exec_id is not null
 12             group by inst_id,
 13                      sql_exec_start,
 14                      sql_opname,
 15                      sql_id,
 16                      sql_exec_id,
 17                      program
 18            having count(distinct sql_child_number) > 1
 19             order by count(distinct sql_child_number) desc)
 20     where rownum <= 1)
 21  select distinct ash.sql_id,
 22                  program,
 23                  sql_child_number,
 24                  sql_opname,
 25                  sql_plan_operation || ' ' || sql_plan_options as PLAN_OPERATION
 26    from gv$active_session_history ash, sql_exec2child
 27   where ash.sql_id = sql_exec2child.sql_id
 28     and ash.sql_exec_id = sql_exec2child.sql_exec_id
 29     and ash.sql_exec_start = sql_exec2child.sql_exec_start
 30   order by 1, 2
 31  /

SQL_ID        PROGRAM                   SQL_CHILD_NUMBER SQL_OPNAME PLAN_OPERATION
------------- ------------------------- ---------------- ---------- -------------------
98gkngsqj0aay oracle@db1.host.ru (J000)                0 INSERT     LOAD AS SELECT     -- QC использует один дочерний курсор CHILD_ID = 0
98gkngsqj0aay oracle@db1.host.ru (J000)                0 INSERT     PX COORDINATOR
98gkngsqj0aay oracle@db1.host.ru (P000)                0 INSERT     HASH UNIQUE        -- PX Slave P000 использует курсоры CHILD_ID = 0
98gkngsqj0aay oracle@db1.host.ru (P000)                0 INSERT     PX RECEIVE
98gkngsqj0aay oracle@db1.host.ru (P000)                0 INSERT     PX SEND HASH
98gkngsqj0aay oracle@db1.host.ru (P000)                0 INSERT     PX SEND QC (RANDOM)
98gkngsqj0aay oracle@db1.host.ru (P000)                0 INSERT     SORT GROUP BY
98gkngsqj0aay oracle@db1.host.ru (P000)                0 INSERT     TABLE ACCESS FULL
98gkngsqj0aay oracle@db1.host.ru (P000)                0 INSERT     WINDOW SORT
98gkngsqj0aay oracle@db1.host.ru (P000)                1 INSERT     HASH UNIQUE        -- и CHILD_ID = 1 !!!
98gkngsqj0aay oracle@db1.host.ru (P000)                1 INSERT     LOAD AS SELECT
98gkngsqj0aay oracle@db1.host.ru (P000)                1 INSERT     WINDOW SORT

SQL> @shared_cu 98gkngsqj0aay

INST_ID PLAN_HASH_VALUE CHILD BIND_SENSE BIND_AWARE SHAREABLE  USE_FEEDBACK_STATS OPTIMIZER_STATS  BIND_EQ_FAILURE  REASON
------- --------------- ----- ---------- ---------- ---------- ------------------ ---------------- ---------------- -----------------------
      1      2874971436     0 N          N          Y          N                  N                N                PQ Slave mismatch(5)  |
      1      2874971436     1 N          N          Y          N                  N                N                PQ Slave mismatch(5)  |
      1      2874971436     2 N          N          N          N                  N                N                PQ Slave mismatch(5)  |

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

4 комментария »

  1. «слава Exadate!» LOL. Da interesno. Oracle razvivajetsja a bugi ostajutsja. Pohozhe oni budut vsegda. Vsegda my budem zanjaty. Spasibo za statju i vremja udeljonnoje na opoisanije.

    комментарий от Yury Velikanov — 15.10.2012 @ 01:13 | Ответить

    • кстати, в версии 12 этот баг пока не планируется к исправлению — слишком поздно (11.2.0.3) заметили / исправили ;)
      так что работы, действительно, хватит

      комментарий от Igor Usoltsev — 15.10.2012 @ 11:51 | Ответить

  2. добрый день!
    Игорь, благодарю за статью!
    часто читаю ваши статьи и открываю для себя много нового..
    Уточните пожалуйста, у вас в статье есть постоянные привязки к KGLLKHDL in (‘0000000CCF4F6E60′,’0000000CBB910C38’)
    Откуда вы взяли именно такие значения ?

    комментарий от Павел — 15.10.2012 @ 11:03 | Ответить

    • адреса Library Cache Lock Handler (KGLLKHDL) могут быть получены:
      — из значений P1RAW обзоров V$SESSION / V$SESSION_WAIT для сессий, ожидающих library cache lock
      — из обзора dba_kgllock (построенном на x$kgllk) для тех же блокированных сессий
      — из hanganalyze trace «p1: ‘handle address’=0xcbb910c38»
      естественно, отображается везде одна и та же информация

      комментарий от Igor Usoltsev — 15.10.2012 @ 11:49 | Ответить


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