Oracle mechanics

14.12.2018

row cache lock: global deadlock

Filed under: Блокировки,Oracle,shared pool — Игорь Усольцев @ 00:33
Tags:

С Иваном Постниковым наблюдали/разбирали нечасто встречаемое ожидание library cache load lock, в течение заметного времени наблюдавшееся у ряда сессий 2-го инстанса:

12.1.0.2@inst#2 SQL> select * from v$session where state = 'WAITING' and event = 'library cache load lock';
 
  SID    SERIAL# USERNAME COMMAND STATUS   SERVER    SQL_ID        SQL_CHILD_NUMBER SQL_EXEC_START SQL_EXEC_ID MODULE                   ACTION ROW_WAIT_OBJ# LAST_CALL_ET  BLOCKING_SESSION_STATUS BLOCKING_INSTANCE BLOCKING_SESSION FINAL_BLOCKING_SESSION_STATUS FINAL_BLOCKING_INSTANCE FINAL_BLOCKING_SESSION EVENT                    P1TEXT          P1RAW            P2TEXT        P2RAW            P3TEXT             P3RAW            WAIT_CLASS  SECONDS_IN_WAIT STATE  
----- ---------- -------- ------- -------- --------- ------------- ---------------- -------------- ----------- ------------------------ ------ ------------- ------------ ------------------------ ----------------- ---------------- ----------------------------- ----------------------- ---------------------- ------------------------ --------------- ---------------- ------------- ---------------- ------------------ ---------------- ----------- --------------- -------
   13      54031 APPS           3 ACTIVE   DEDICATED 8r49n0b59js0a                0                            e:SQLGL:cp:xla/XLADRPGLT SQLGL/       2707322        81853  VALID                                   2              392 VALID                                               2                    392 library cache load lock  object address  0000005D14491B18 lock address  0000005CA8C05AD0 100*mask+namespace 0000000000010003 Concurrency           80854 WAITING
  652      55148 APPS           3 ACTIVE   DEDICATED a742atptz32bs                0                            e:SQLGL:cp:xla/XLADRPGLT SQLGL/            -1        81853  VALID                                   2              392 VALID                                               2                    392 library cache load lock  object address  0000005D14491B18 lock address  0000005DA2ACFDF0 100*mask+namespace 0000000000010003 Concurrency           80854 WAITING
 1632      58741 APPS           3 ACTIVE   DEDICATED gn7fg92jr1vkj                0                            e:SQLGL:cp:xla/XLADRPGLT SQLGL/       2707322        81851  VALID                                   2              392 VALID                                               2                    392 library cache load lock  object address  0000005D14491B18 lock address  0000005C037E1AC0 100*mask+namespace 0000000000010003 Concurrency           81758 WAITING
 1801      31526 APPS           3 ACTIVE   DEDICATED 99340wc8xpd52                0                            e:SQLGL:cp:xla/XLADRPGLT SQLGL/       2707322        81852  VALID                                   2              392 VALID                                               2                    392 library cache load lock  object address  0000005D14491B18 lock address  0000005BA6313E70 100*mask+namespace 0000000000010003 Concurrency           80854 WAITING
 2495      38991 APPS           3 ACTIVE   DEDICATED 39wnr00vh9t1b                0                            e:SQLGL:cp:xla/XLADRPGLT SQLGL/            -1        81852  VALID                                   2              392 VALID                                               2                    392 library cache load lock  object address  0000005D14491B18 lock address  0000005DA151AF38 100*mask+namespace 0000000000010003 Concurrency           80854 WAITING

, содержимое ROW_WAIT_OBJ# не очень полезно:

SQL> select * from dba_objects where object_id  = 2707322;
 
OWNER OBJECT_NAME  OBJECT_ID DATA_OBJECT_ID OBJECT_TYPE
----- ----------- ---------- -------------- -----------
SYS   USER$          2707322        2707320 TABLE

, судя по пустым SQL_EXEC_START / SQL_EXEC_ID запросы/курсоры находятся в процессе погрузки в Library Cache (на что указывает и название ожидания длительностью SECONDS_IN_WAIT 80000+ сек) и имеют сходные тексты, относящиеся к одной и той же временной по сути, но не по определению (TEMPORARY=N) таблице:

SQL> select sql_id, sql_text from v$sqlarea where sql_id in ('8r49n0b59js0a','a742atptz32bs','gn7fg92jr1vkj','99340wc8xpd52','39wnr00vh9t1b');
 
SQL_ID        SQL_TEXT
------------- -----------------------------------------------------------------------------------------------------------------------------------------------------
99340wc8xpd52 select count(*) from  (select /*+ first_rows(1) */ ledger_id from XLA_GLT_2943586 where rownum = 1 ) glt where glt.ledger_id not in (444,445)
8r49n0b59js0a select count(*) from  (select /*+ first_rows(1) */ ledger_id from XLA_GLT_2943586 where rownum = 1 ) glt where glt.ledger_id not in (282,402,422,283)
39wnr00vh9t1b select count(*) from  (select /*+ first_rows(1) */ ledger_id from XLA_GLT_2943586 where rownum = 1 ) glt where glt.ledger_id not in (154,222)
gn7fg92jr1vkj select count(*) from  (select /*+ first_rows(1) */ ledger_id from XLA_GLT_2943586 where rownum = 1 ) glt where glt.ledger_id not in (482,542,503)
a742atptz32bs select count(*) from  (select /*+ first_rows(1) */ ledger_id from XLA_GLT_2943586 where rownum = 1 ) glt where glt.ledger_id not in (150,205)

BLOCKING_SESSION / FINAL_BLOCKING_SESSION указывали на:

SQL> select * from v$session where sid = 392;
 
  SID    SERIAL# USERNAME COMMAND STATUS TYPE SQL_ID        SQL_CHILD_NUMBER SQL_EXEC_START SQL_EXEC_ID PREV_SQL_ID   PREV_EXEC_START     PREV_EXEC_ID ROW_WAIT_OBJ# LAST_CALL_ET FINAL_BLOCKING_SESSION_STATUS FINAL_BLOCKING_INSTANCE FINAL_BLOCKING_SESSION EVENT          P1TEXT   P1 P2TEXT P2 P3TEXT  P3 WAIT_CLASS  SECONDS_IN_WAIT STATE
----- ---------- -------- ------- ------ ---- ------------- ---------------- -------------- ----------- ------------- ------------------- ------------ ------------- ------------ ----------------------------- ----------------------- ---------------------- -------------- -------- -- ------ -- ------- -- ----------- --------------- -------
  392       3157 APPS           3 ACTIVE USER g5xb42bbt36x4                0                            ck1p7tpkfjsfm 26.11.2018 22:01:24     33554432      19336906        81866 UNKNOWN                                                                      row cache lock cache id  8 mode    0 request  3 Concurrency               0 WAITING

сессию с так же затянувшимся ожиданием row cache lock в попытке запустить/распарсить (пустые SQL_EXEC_START SQL_EXEC_ID) запрос g5xb42bbt36x4 к той же таблице:

SQL> select sql_id, sql_text from v$sqlarea where sql_id in ('g5xb42bbt36x4');
 
SQL_ID        SQL_TEXT
------------- ------------------------------------------------------------------------------------------------------------------------------------------------
g5xb42bbt36x4 select count(*) from (select /*+ first_rows(1) */ ledger_id from XLA_GLT_2943586 where rownum = 1 ) glt where glt.ledger_id not in (523,544,525)

, cache id ожидания row cache lock указывает на:

SQL> SELECT DISTINCT cache#, type, parameter FROM v$rowcache WHERE cache# = 8;
 
    CACHE# TYPE        PARAMETER
---------- ----------- --------------------------------
         8 PARENT      dc_objects
         8 SUBORDINATE dc_object_grants

, без текущих блокировок (mode=0), но желая для компиляции курсора получить на dc_object разделяемую блокировку типа share mode (request=3), как следует из исчерпывающего описания WAITEVENT: «row cache lock» Reference Note (Doc ID 34609.1):

  KQRMNULL 0   null mode - not locked
  KQRMS    3   share mode
  KQRMX    5   exclusive mode
  KQRMFAIL 10  fail to acquire instance lock

Для нахождения цепочки блокировок можно попробовать использовать адрес объекта в Library Cache Shared Pool, за который идёт конкуренция между пятью сессиями на library cache load lock и указанный в качестве параметра ожидания P1RAW в выводе самого первого скрипта:

SQL> select * from x$kglob where kglhdadr = '0000005D14491B18';
 
ADDR                   INDX INST_ID     CON_ID KGLHDADR         KGLHDPAR           KGLHDCLT KGLNAOWN  KGLNAOBJ         KGLFNOBJ        KGLHDNSD        KGLOBTYD
---------------- ---------- ------- ---------- ---------------- ---------------- ---------- --------- ---------------- --------------- --------------- --------
00007F6F19A3DE78    1029010       2          0 0000005D14491B18 0000005D14491B18     122758 APPS      XLA_GLT_2943586  XLA_GLT_2943586 TABLE/PROCEDURE CURSOR

— видим объект типа CURSOR, очевидно относящийся к TABLE XLA_GLT_2943586, общей для всех запросов
При этом DBA_KGLLOCK на этом же 2-м инстансе показывает только известные нам 5+1 сессии (при этом последний SID 392, висящий на row cache lock, блокирует остальные 5 сессий), уже удерживающие эту блокировку (Lock):

SQL> select * from dba_kgllock where kgllkhdl = '0000005D14491B18';
 
KGLLKUSE         KGLLKHDL           KGLLKMOD   KGLLKREQ KGLLKTYPE
---------------- ---------------- ---------- ---------- ---------
0000006458D8C738 0000005D14491B18          1          0 Lock
0000006451048C10 0000005D14491B18          1          0 Lock
0000006428E3AA10 0000005D14491B18          1          0 Lock
0000006430F95A38 0000005D14491B18          1          0 Lock
000000643914C4A0 0000005D14491B18          1          0 Lock
0000006428DE8990 0000005D14491B18          1          0 Lock
 
6 rows selected

— в null mode (How to Analyze Library Cache Timeout…(Doc ID 1486712.1)):

-KGLLKMOD/KGLLKREQ  Holding/requested mode
0           no lock/pin held
1           null mode
2           share mode
3           exclusive mode

, но, неочевидно (KGLLKREQ=0), желающие для компиляции курсора бОльшего — share mode

В итоге на 2-м инстансе кроме проблем ничего найти не удалось, переходим к инстансу №1, где в виду несохранения адресации между нодами RAC ищем в Library Cache по имени объекта / KGLNAOBJ:

12.1.0.2@inst#1 SQL> select * from x$kglob where KGLNAOBJ in ('XLA_GLT_2943586');
 
ADDR                   INDX INST_ID KGLHDADR         KGLHDPAR           KGLHDCLT KGLNAOWN KGLNAOBJ         KGLFNOBJ        KGLHDNSD          KGLHDLMD   KGLHDPMD  KGLOBTYD
---------------- ---------- ------- ---------------- ---------------- ---------- -------- ---------------- --------------- --------------- ---------- ----------  --------
00007F39DC042FC0     359925       1 0000005B8DEEF1F0 0000005B8DEEF1F0      41312 GL       XLA_GLT_2943586  XLA_GLT_2943586 TABLE/PROCEDURE          3          3  TABLE
00007F39DBFDA320     959710       1 0000005B8DEEFE20 0000005B8DEEFE20     109877 APPS     XLA_GLT_2943586  XLA_GLT_2943586 TABLE/PROCEDURE          0          0  SYNONYM
00007F39DE80F8F8    1080203       1 0000005C3C7462B8 0000005C3C7462B8     122758 APPS     XLA_GLT_2943586  XLA_GLT_2943586 TABLE/PROCEDURE          0          0  SYNONYM
 
3 rows selected

— где находятся 3 объекта (TABLE + 2xSYNONYM) и судя по полям KGLHDLMD, KGLHDPMD с удерживаемыми Lock+Pin,
проверяем:

SQL> select * from dba_kgllock where kgllkhdl in ('0000005B8DEEF1F0','0000005B8DEEFE20','0000005C3C7462B8');
 
KGLLKUSE         KGLLKHDL           KGLLKMOD   KGLLKREQ KGLLKTYPE
---------------- ---------------- ---------- ---------- ---------
0000006458E763D8 0000005B8DEEF1F0          3          0 Lock
0000006458E763D8 0000005B8DEEF1F0          3          0 Pin

и далее по адресу сессии KGLLKUSE остаётся определить локального блокера на 1-й ноде:

SQL> select * from gv$session where SADDR = '0000006458E763D8';
 
INST_ID SADDR              SID    SERIAL# USERNAME COMMAND TADDR            LOCKWAIT STATUS   SERVER       SCHEMA# SCHEMANAME OSUSER PROCESS PROGRAM                                    TYPE  SQL_ADDRESS      SQL_HASH_VALUE SQL_ID        SQL_CHILD_NUMBER SQL_EXEC_START      SQL_EXEC_ID PLSQL_ENTRY_OBJECT_ID PLSQL_ENTRY_SUBPROGRAM_ID LAST_CALL_ET BLOCKING_SESSION_STATUS BLOCKING_INSTANCE BLOCKING_SESSION FINAL_BLOCKING_SESSION_STATUS FINAL_BLOCKING_INSTANCE FINAL_BLOCKING_SESSION EVENT                       P1TEXT            P1 P2TEXT P2 P3TEXT  P3 WAIT_CLASS   WAIT_TIME SECONDS_IN_WAIT STATE  
------- ---------------- ----- ---------- -------- ------- ---------------- -------- -------- --------- ---------- ---------- ------ ------- ------------------------------------------ ----- ---------------- -------------- ------------- ---------------- ------------------- ----------- --------------------- ------------------------- ------------ ----------------------- ----------------- ---------------- ----------------------------- ----------------------- ---------------------- --------------------------- --------- ---------- ------ -- ------- -- ----------- ---------- --------------- -------
      2 0000006458E763D8   835      38222 APPS           0                           INACTIVE DEDICATED        173 APPS       oracle 26051   frmweb@appl2.oebs.server.net (TNS V1-V3)   USER  00                            0                                                                                                                        6115 NO HOLDER                                                  NO HOLDER                                                                    SQL*Net message from client driver id 1952673792 #bytes  1          0 Idle                 0            6115 WAITING
      1 0000006458E763D8   835      62590 APPS          12 0000006362960418          ACTIVE   DEDICATED          5 SYSTEM     oracle 48261   STANDART@appl2.oebs.server.net (TNS V1-V3) USER  00007FCDAF74A9C8     1704457051 6bfcq9dktgwuv                0 26.11.2018 22:01:24    16777216              16499064                         2        82789 UNKNOWN                                                    UNKNOWN                                                                      row cache lock              cache id           8 mode    0 request  5 Concurrency          0               0 WAITING

— тут интересно заметить, что один адрес / SADDR определяет пару сессий с совпадающими SID, нас интересует вторая строка — сессия на 1-м инстансе без видимых блокеров многократно ожидавщая row cache lock в течение 82789 секунд на том же cache id:

SQL> SELECT DISTINCT cache#, type, parameter FROM v$rowcache WHERE cache# = 8;
 
CACHE# TYPE        PARAMETER
------ ----------- ----------------
     8 PARENT      dc_objects
     8 SUBORDINATE dc_object_grants

в exclusive mode (request=5) — что нормально для DDL, и выполняющая отсутствующий в видимом кэше (рекурсивный) SQL_ID 6bfcq9dktgwuv типа / COMMAND:

SQL> select * from v$sqlcommand where command_type = '12';
 
COMMAND_TYPE COMMAND_NAME
------------ ------------
          12 DROP TABLE

Т.о. в 26.11.2018 22:01:24 на 1-й ноде была запущена команда DROP TABLE XLA_GLT_2943586:

SQL> select SQL_EXEC_START, PREV_EXEC_START from v$session where SADDR = '0000006458E763D8';
 
SQL_EXEC_START                 PREV_EXEC_START
------------------------------ ------------------------------
26.11.2018 22:01:24            26.11.2018 22:01:24

и примерно в то же время на 2-й ноде SID 392 (см.выше) попытался скомпилировать курсор в отношении той же таблицы XLA_GLT_2943586:

PREV_EXEC_START
------------------- 
26.11.2018 22:01:24

в рез-тате чего возникла взаимная блокировка / deadlock на относительно коротких row cache lock в shared / exclusive mode соответственно, породившая небольшой каскад желающих скомпилировать курсоры к той же таблице с долгоиграющими ожиданиями library cache load lock на 2-й ноде

Наблюдаемая проблема безостановочно отображается (но никак не обрабатывается) в трейсах diag на 2-й:

    Current Wait Stack:
     0: waiting for 'row cache lock'
        cache id=0x8, mode=0x0, request=0x3
        wait_id=57256 seq_num=57307 snap_id=1
        wait times: snap=0.002516 sec, exc=0.002516 sec, total=0.002516 sec
        wait times: max=3.000000 sec, heur=170 min 3 sec
        wait counts: calls=1 os=1
        in_wait=1 iflags=0x5a2
    There are 5 sessions blocked by this session.
    Dumping one waiter:
      inst: 2, sid: 1632, ser: 58741
      wait event: 'library cache load lock'
        p1: 'object address'=0x5d14491b18
        p2: 'lock address'=0x5c037e1ac0
        p3: '100*mask+namespace'=0x10003
      row_wait_obj#: 2707322, block#: 755268, row#: 0, file# 354
      min_blocked_time: 65535 secs, waiter_cache_ver: 16398
...
Enqueue blocker waiting on 'row cache lock'

, и 1-й нодах:

    Current Wait Stack:
     0: waiting for 'row cache lock'
        cache id=0x8, mode=0x0, request=0x5
        wait_id=62869 seq_num=62915 snap_id=1
        wait times: snap=0.002426 sec, exc=0.002426 sec, total=0.002426 sec
        wait times: max=3.000000 sec, heur=17.292131 sec
        wait counts: calls=1 os=1
        in_wait=1 iflags=0x5a2
...
    ---------------------------------------------------
    Sampled Session History Summary:
      longest_non_idle_wait: 'row cache lock'
      [3 samples, 21:25:19 - 21:25:21]
          time_waited: 3.000238 sec (sample interval: 2 sec)
    ---------------------------------------------------
...
  Repeat 31 times
Enqueue blocker waiting on 'row cache lock'

Поведение похоже на описанный Bug 7423411 — Process may hang waiting for «library cache load lock» with no holder (Doc ID 7423411.8)

It is possible for sessions to hang waiting on a "library cache load lock" 
with no apparent holder.
 
The following factors must be pressent :
- heavy concurrenty over a table
- DDLs are done over the same table. -- тут
 
Describe, Queries , DDLs and DMLs will later hang. -- и тут

P.S. Наверное, лучшее определение row cache lock:

In order for DDL (Data Definition Language) to execute, it must acquire a row cache lock to lock the data dictionary information. The shared pool contains a cache of rows from the data dictionary that helps reduce physical I/O to the data dictionary tables and allows locking of individual data dictionary rows. The locks on the data dictionary rows are called row cache enqueue locks. The enqueue lock structures are allocated from the shared pool as needed but when these requests wait and time out, we see the row cache lock wait event

— с единственным дополнением — не только DDL, но, и DML и даже просто SQL Query — как видно из описанного случая

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

  1. Как в всегда блестящий анализ. Скажите, сколько обычно времени у вас уходит на анализ проблемы и поиск ее решения, конкретно на данном примере?

    комментарий от dr.oracle — 28.06.2019 @ 17:20 | Ответить

    • спасибо, 1-2 часа, наверное, в любом случае, описание заняло больше)

      комментарий от Игорь Усольцев — 07.07.2019 @ 11:42 | Ответить


RSS feed for comments on this post. TrackBack URI

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

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход /  Изменить )

Google photo

Для комментария используется ваша учётная запись Google. Выход /  Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход /  Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход /  Изменить )

Connecting to %s

Блог на WordPress.com.

%d такие блоггеры, как: