С Иваном Постниковым наблюдали/разбирали нечасто встречаемое ожидание 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 — как видно из описанного случая
Oracle mechanics 
Как в всегда блестящий анализ. Скажите, сколько обычно времени у вас уходит на анализ проблемы и поиск ее решения, конкретно на данном примере?
комментарий от dr.oracle — 28.06.2019 @ 17:20
спасибо, 1-2 часа, наверное, в любом случае, описание заняло больше)
комментарий от Игорь Усольцев — 07.07.2019 @ 11:42