По мотивам одного сбоя в БД Oracle12.11.2024 16:31

Скрипт запускает одновременную вставку в таблицу, из-за задержки commit часть сессий ожидает enq: TX — allocate ITL entry, 168 сессий ждет PL/SQL lock timer из-за искусственной задержки.

SQL> select count(*),event from v$session where type='USER' group by event;
  
2 	SQL*Net message from client
152   enq: TX - allocate ITL entry
168   PL/SQL lock timer
1 	SQL*Net message to clien

Сдампим структуру индекса, найдем интересующий нас листовой блок и сделаем его дамп:

$ cat treedump.sql
col tracefile new_value tf noprint
select value as tracefile   from v$diag_info where name = 'Default Trace File';
col object_id new_value oid noprint
select object_id from dba_objects where object_name='INSTABN';
alter session set events 'immediate trace name treedump level &oid';
host less &tf
col rfn new_value file_id
col bl new_value block_id
select dbms_utility.data_block_address_file(&&rdba) rfn, dbms_utility.data_block_address_block(&&rdba) bl from dual;
alter system dump datafile &file_id block &block_id;
host less &tf
  
  
----- begin tree dump
leaf: 0x1c4f76b 29685611 (0: row:168.168 avs:1470)
----- end tree dump
  
...
...
  
Block header dump:  0x01c4f76b
 Object id on Block? Y
 seg/obj: 0x1acec  csc:  0x00000272596a2163  itc: 169  flg: E  typ: 2 - INDEX
     brn: 0  bdba: 0x1c4f768 ver: 0x01 opc: 0
     inc: 0  exflg: 0
  
 Itl       	Xid              	Uba     	Flag  Lck    	Scn/Fsc
0x01   0x0000.000.00000000  0x00000000.0000.00  ----	0  fsc 0x0000.00000000
0x02   0x0180.009.00000005  0x0107cb3d.0008.0c  ----	1  fsc 0x0000.00000000
0x03   0x02fc.010.00000004  0x0107e379.0015.31  ----	1  fsc 0x0000.00000000
0x04   0x0297.021.00000006  0x0107f111.0015.14  ----	1  fsc 0x0000.00000000
0x05   0x02d0.01c.00000006  0x0107e787.0013.0f  ----	1  fsc 0x0000.00000000
...
...
0xa9   0x0261.011.00000004  0x0107d9d1.0008.21  ----	1  fsc 0x0000.00000000

Если убрать задержку commit«а в вызове dbms_session.sleep, число ITL-слотов сократится до 35, задержка в 1 секунду даст те же 168 слотов.

На нашей БД выборочная проверка листовых блоков последней секции индекса TABLE_NAME_PK показала наличие 45 ITL-слотов.

Мы воспроизвели первую часть сбоя, успешно получили ожидания enq: TX — allocate ITL entry с помощью искусственного замедления подтверждения транзакций.

В реальном сбое, о котором идет речь в статье, транзакции не проходили по другой причине — считаем это второй частью сбоя.

Второй testcase — разбираем причину ошибок ORA-06550

Второй testcase поможет нам понять причину ошибок компиляции PL/SQL-блока. Воспроизводим ошибку компиляции PL/SQL-блока. Для этого создадим пакет testpak в схеме APP.

Testcase2:  

SQL> conn app/app
Connected.
SQL> create or replace package testpak as
 function add(n1 number,n2 number,n3 number) return number;
end testpak;
/
SQL> create or replace package body testpak as
 function add(n1 number,n2 number,n3 number) return number is
  begin
   return n1+n2+n3;
  end;
end testpak;
/  

Создадим таблицу APP в схеме APP, которая не используется в нашем PL/SQL-блоке:

SQL> create table app.app as select * from all_objects;

Выполним PL/SQL-блок, обращающийся к ранее созданному пакету, под пользователем SYS. Блок выполнится без ошибок:

SQL> conn / as sysdba
SQL> declare
 r number;
 b1 number:=1;
 b2 number:=2;
 b3 number:=3;
begin
 r:=app.testpak.add(b1,b2,b3);
end;
/  
PL/SQL procedure successfully completed.

Выполним тот же блок под пользователем APP:

SQL> conn app
SQL> declare
 r number;
 b1 number:=1;
 b2 number:=2;
 b3 number:=3;
begin
 r:=app.testpak.add(b1,b2,b3);
end;
/ 
 
 r:=app.testpak.add(b1,b2,b3);
        *
ERROR at line 7:
ORA-06550: line 7, column 9:
PLS-00302: component 'TESTPAK' must be declared
ORA-06550: line 7, column 2:
PL/SQL: Statement ignored

Мы получили ошибку, хотя пакет APP.TESTPAK существует и он валидный.

Методы диагностики

Попробуем разные методы диагностики, чтобы понять причины возникновения ошибки. 

1. Errorstack, настроим автоматический сбор диагностики при возникновении ошибки. Errorstack описывает текущее состояние процесса, включая в себя выполняющийся на момент сбора SQL-запрос (PL/SQL-блок) и PROCESS STATE. Последний содержит дамп объектов состояния для ресурсов СУБД, к которым обращался процесс. Объекты состояния — state objects — создаются для всех объектов, которыми управляет СУБД, размещаются в SGA.

SQL> alter system set events '6550 {occurence:end_after 1} trace name errorstack level 3 ';
SQL> declare
 r number;
 b1 number:=1;
 b2 number:=2;
 b3 number:=3;
begin
 r:=app.testpak.add(b1,b2,b3);
end;
/ 

В полученном трейсе среди объектов состояния видим таблицу APP в схеме APP. Это странно: наш код к ней ни прямо, ни косвенно не обращается.

SO: 0x7143e338, type: LIBRARY OBJECT PIN (119), map: 0x71792768
            state: LIVE (0x4532), flags: 0x1
            owner: 0x73ea05e8, proc: 0xf7effff8
            link: 0x7143e358[0x703382f8, 0x73ea0658]
            child list count: 0, link: 0x7143e3a8[0x7143e3a8, 0x7143e3a8]
            pg: 0
SOC: 0x71792768, type: LIBRARY OBJECT PIN (119), map: 0x7143e338
             state: LIVE (0x99fc), flags: INIT (0x1)
  
        LibraryObjectPin: Address=0x71792768 Handle=0x7259df10 Mode=S Lock=0x71792a20
User=0xf1a13cc0 Session=0xf1a13cc0 Count=1 Mask=0005 Flags=[00] SavepointNum=0x518
        LibraryHandle:  Address=0x7259df10 Hash=e6852b43 LockMode=S PinMode=S LoadLockMode=0 Status=VALD
          ObjectName:  Name=APP.APP
            FullHashValue=0eea8c511eefcf0b804f6c48e6852b43 Namespace=TABLE/PROCEDURE(01) Type=TABLE(02) ContainerId=0 ContainerUid=0 Identifier=109807 OwnerIdn=108
          Statistics:  InvalidationCount=0 ExecutionCount=0 LoadCount=1 ActiveLocks=1 TotalLockCount=9 TotalPinCount=5
          Counters:  BrokenCount=2 RevocablePointer=2 KeepDependency=0 Version=0 BucketInUse=6 HandleInUse=6 HandleReferenceCount=0
          Concurrency:  DependencyMutex=0x7259dfc0(0, 7, 0, 0) Mutex=0x7259e060(0, 57, 0, 0)

2. Расширенная трассировка SQL (10046 trace). SQL_TRACE, хорошо известный как event 10046 trace, позволяет получить трейс с операциями, проводимыми серверным процессом Oracle. В него попадают операции PARSE, EXEC, FETCH, ошибки ERR, XCTEND. Можем увидеть, например, какой-нибудь служебный запрос, который поможет прояснить ситуацию.

SQL> alter session set events '10046 level 12';
SQL> declare
 r number;
 b1 number:=1;
 b2 number:=2;
 b3 number:=3;
begin
 r:=app.testpak.add(b1,b2,b3);
end;
/ 

В полученном трассировочном файле видим события ожидания SQL*Net break/reset to client. Эти сообщения говорят об ошибке или необработанной исключительной ситуации во время обращения к Oracle, но причина этого неясна.

WAIT #47923813001880: nam='SQL*Net message from client' ela= 8078271 driver id=1650815232 #bytes=1 p3=0 obj#=771 tim=19541137491723
CLOSE #47923813001880:c=10,e=10,dep=0,type=1,tim=19541137491818
WAIT #47923811822928: nam='SQL*Net break/reset to client' ela= 3 driver id=1650815232 break?=1 p3=0 obj#=771 tim=19541137492613
WAIT #47923811822928: nam='SQL*Net break/reset to client' ela= 37 driver id=1650815232 break?=0 p3=0 obj#=771 tim=19541137492672
WAIT #47923811822928: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=771 tim=19541137492683

3. Трассировка обращения к row cache. Речь идет о data dictionary cache.  

Фрагмент из официальной документации.

This cache holds information about database objects. The cache is also known as the row cache because it holds data as rows instead of buffers.

Хорошее объяснение предназначения row cache от Tanel Poder:

First, we need to think how Oracle looks up objects from database. You all know there’s a data dictionary in SYSTEM tablespace. Whenever you parse a statement which references any database objects, then Oracle process will go to dictionary cache and get that object’s information from there. This is assuming the object’s info is cached in dictionary cache. If it isn’t, a cache miss happens, which causes a recursive SQL statement (or many) to be fired against data dictionary base tables (such OBJ$, TAB$, SEG$, etc…) and the result is used for populating relevant objects in dictionary cache.

So, the dictionary cache acts as a cache for existing objects in data dictionary. Makes very much sense performance wise, as otherwise you would need to always execute the same recursive SQL again when parsing statements.

SQL> alter session set events '10222 level 4';
SQL> ALTER SESSION SET EVENTS 'immediate trace name row_cache level 8';
SQL> declare
 r number;
 b1 number:=1;
 b2 number:=2;
 b3 number:=3;
begin
 r:=app.testpak.add(b1,b2,b3);
end;
/ 

В полученном трейсе видно, что Oracle читает объект APP (объект схемы) po=0xc79dbd68 и к другим объектам сессия не обращается:

kqrpre: start hash=183481d3 mode=S keyIndex=1 dur=CALL opt=FALSE hot=TRUE
kqrScan: hot hash chain: primary scan: processing po 0xc79dbd68
kqrScan: continue processing 0xc79dbd68 locked 0
kqrScan: uncloned object 0xc79dbd68 on hot hash chain
row cache parent object: addr=0xc79dbd68 cid=10(dc_users)
conid=0 conuid=0 inc=1, pdbinc=1
hash=2231874c typ=1 transaction=(nil) flags=00000002
version=1 mtx version=26
user#=108 name=APP edition#=-1
...
kqrpre: found cached object po=0xc79dbd68 flg=2
kqrpre: pinned po=0xc79dbd68 flg=2 pso=0xdffab690
kqrAllocateEnqueue: bis: po=0xc79dbd68 flag=00010000 before=00000002 after=00010002
kqrget bic: po=0xc79dbd68 flag=00010000 before=00010002 after=00000002
kqrpre: done po=0xc79dbd68 cid=10 flg=2 eq=0xb3f7b638 pso=0xdffab690 dur=CALL
kqreqd: processing po=0xc79dbd68 flag=2 mode=S
kqrpre: found cached object po=0xc79dbd68 flg=2
kqrpre: pinned po=0xc79dbd68 flg=2 pso=0xdffab690
kqrAllocateEnqueue: bis: po=0xc79dbd68 flag=00010000 before=00000002 after=00010002
kqrget bic: po=0xc79dbd68 flag=00010000 before=00010002 after=00000002
kqrpre: done po=0xc79dbd68 cid=10 flg=2 eq=0xb3f7b808 pso=0xdffab690 dur=CALL
kqreqd: processing po=0xc79dbd68 flag=2 mode=S
kqrpre: done po=0x2b1a398b6dd0 cid=10 flg=2 eq=0xb3f7b720 pso=0xdffa2c60 dur=CALL
kqrpre: done po=0x2b1a398b6dd0 cid=10 flg=2 eq=0xb3f7b720 pso=0xdffa2c60 dur=CALL

Вместо четвертого способа попробуем показать, откуда Oracle берет информацию об объектах. Сделаем dump library cache:

SQL> alter session set events 'immediate trace name library_cache level 10' ;

Найдем описание таблицы APP.APP в дампе library cache.

Bucket: #=76611 Mutex=0xd06c8ef0(107374182400, 149, 0, 6)
  LibraryHandle:  Address=0xc142d2a8 Hash=e6852b43 LockMode=0 PinMode=0 LoadLockMode=0 Status=VALD Subpool=1
    ObjectName:  Name=APP.APP
      FullHashValue=0eea8c511eefcf0b804f6c48e6852b43 Namespace=TABLE/PROCEDURE(01) Type=TABLE(02) ContainerId=0 ContainerUid=0 Identifier=109807 OwnerIdn=108
    Statistics:  InvalidationCount=0 ExecutionCount=0 LoadCount=1 ActiveLocks=0 TotalLockCount=25 TotalPinCount=25
    Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=0 Version=0 BucketInUse=24 HandleInUse=24 HandleReferenceCount=0
    Concurrency:  DependencyMutex=0xc142d358(0, 42, 0, 0) Mutex=0xc142d3f8(25, 345, 0, 6)
    Flags=PIN/TIM/[00002801] Flags2=[0000]
    WaitersLists:
      Lock=0xc142d338[0xc142d338,0xc142d338]
      Pin=0xc142d318[0xc142d318,0xc142d318]
      LoadLock=0xc142d390[0xc142d390,0xc142d390]
    Timestamp:  Current=08-07-2024 18:10:58
    HandleReference:  Address=0xc142d470 Handle=0xc79dbb38 Flags=OWN[200]
    LibraryObject:  Address=0xc142bc40 HeapMask=0000-0705-0705-0000 Flags=EXS/LOC[0004] Flags2=/CSC[4000000] Flags3=[0000] PublicFlags=[0000]

Подключимся отладчиком к процессу, в котором будем запускать наш проблемный PL/SQL-блок, установим watchpoint’ы на Address и Handle, относящиеся к таблице APP.APP:  

awatch *(0xc142d2a8)
awatch *(0xc142d470)
awatch *(0xc79dbb38)
awatch *(0xc142bc40)

Снова запускаем наш проблемный PL/SQL-блок кода:  

SQL> declare
 r number;
 b1 number:=1;
 b2 number:=2;
 b3 number:=3;
begin
 r:=app.testpak.add(b1,b2,b3);
end;
/

Сработал watchpoint на 0xc142bc40 — адрес LibraryObject:  

#0  0x00000000137d35ac in kglobpn () <-kglobpn - kernel generic library cache management object pin heaps and load data pieces
#1  0x00000000137ce16a in kglpim ()
#2  0x00000000137cbaee in kglpin ()
#3  0x0000000004b5db57 in kglgob () <- kglgob - kernel generic library cache management get an object locked and pinned
#4  0x0000000004b5a446 in kgldpo0 ()
#5  0x0000000004b5a144 in kgldpo ()
#6  0x0000000004b59d78 in kgldon () <- kgldon - kernel generic library cache management depend on an object
#7  0x00000000056df77b in pkldon ()
#8  0x00000000056df575 in pkloud ()
#9  0x00000000056a3fb4 in phnnrl_name_resolve_by_loading ()
#10 0x00000000056a3d43 in phngdl_get_defining_libunit ()
#11 0x00000000056a3199 in phnrpls_resolve_prefix_libscope ()
#12 0x00000000056a1080 in phnrp_resolve_prefix ()
#13 0x00000000056a08dc in phnr_resolve ()
#14 0x0000000005681538 in ph2exp () <- ph2exp - PLSQL phase 2 (semantic analyzer) process IDL class EXP
#15 0x0000000005659f01 in ph2stm ()
#16 0x00000000056683fd in ph2sms ()
#17 0x000000000565d926 in ph2blo ()
#18 0x0000000005659fe6 in ph2stm ()
#19 0x00000000056539e5 in ph2uni ()
#20 0x00000000056509c7 in ph2dr2 ()
#21 0x000000000564f619 in ph2drv ()
#22 0x00000000055cc615 in phpsem ()
#23 0x00000000055c8272 in phpcmp ()
#24 0x00000000055cdae6 in pcisem2 ()
#25 0x0000000003899d3a in kkxsem ()
#26 0x00000000041695aa in opitca ()
#27 0x000000000350b651 in kksFullTypeCheck ()
#28 0x00000000135004f4 in rpiswu2 ()
#29 0x0000000003518439 in kksLoadChild ()
#30 0x00000000134ebdff in kxsGetRuntimeLock ()
#31 0x0000000013497865 in kksfbc ()
#32 0x0000000013490450 in kkspsc0 ()
#33 0x000000001348fb62 in kksParseCursor ()

Из полученного стека видим, что во время семантического анализа PL/SQL-блока Oracle приходит прямо в объект таблицы APP.

Ранее в трассировках мы не видели SQL-запросов к словарю, обращений к row cache, потому что Oracle получает закешированную информацию об объекте из library cache. 

Почему Oracle находит таблицу вместо выполнения корректного PL/SQL-блока?

Oracle объясняет такое поведение в PLS-302 When Table Name And Schema Name Are Identical (Doc ID 567376.1)

Фрагмент документа из официальной базы знаний.

This is the correct behaviour of the plsql parser. In an sql statement, when an object is identified with a dot-separated chain, the plsql parser initially looks for an object named as the first part of chain in the scope of the current schema. If the object exists then it looks for the second part of the chain in relation to that object.

Only when there is no object named in that way does it look for a username.

Так в нашем случае и произошло, Oracle нашел в текущей схеме APP таблицу APP, компиляция блока завершилась с ошибкой.

Под SYS наш блок отработал без ошибок, так как в схеме SYS не было таблицы с именем APP. Иначе plsql parser поступил бы так же, как и в случае схемы APP.

SQL> select user from dual;
 
USER
---------------------------------
SYS
 
SQL> create table app(n number);
 
Table created.
 
SQL> declare
r number;
b1 number:=1;
b2 number:=2;
b3 number:=3;
begin
r:=app.testpak.add(b1,b2,b3);
end;
/ 
 
r:=app.testpak.add(b1,b2,b3);
       *
ERROR at line 7:
ORA-06550: line 7, column 8:
PLS-00302: component 'TESTPAK' must be declared
ORA-06550: line 7, column 1:
PL/SQL: Statement ignored

Причина проблемы оказалась в особенности парсера PL/SQL — в порядке поиска объектов при разборе имен, состоящих из нескольких частей, разделенных точками. При одноименном названии схемы и имени таблицы Oracle сразу находил таблицу в кеше и выдавал ошибку 6550 при обращении к пакету. 

C точки зрения обращения к таблице выражение в PL/SQL-блоке оказывалось ошибочным, до PL/SQL-пакета дело не доходило. Это привело к блокировкам library cache lock за объект $BUILD$, к исчерпанию ITL-слотов в индексном блоке из-за блокировки коммита и, как следствие, росту конкуренции за enq: TX — allocate ITL entry.

Выводы

Рассмотренный инцидент показал, что для успешной диагностики проблемы необходимо сочетание понимания внутренних процессов Oracle и простых приемов, основанных на здравом смысле. При возникновении аномалий в работе СУБД полезно посмотреть, не менялось ли что-либо в самой БД, например не было ли каких-либо DDL-операторов, не менялся ли код приложения.

Конкуренция за ITL-слоты при вставке в таблицу может быть вызвана посторонним событием, если транзакция состоит из нескольких операций. В нашем случае это была компиляция PL/SQL-блока; хотя вместо этого могло быть и что-то другое.

Определение причин ошибки компиляции проблемного блока «в лоб» не всегда возможно в аварийных условиях: например, дампить компоненты SGA под нагрузкой может привести к усугублению ситуации.

Случайно или намеренно лучше не допускать совпадения имен объектов в БД. Нежелательно использовать одноименные объекты в БД, в данном случае имя схемы и имя таблицы. Из-за сбоя в работе скрипта мы получили неожиданные последствия.

На прощание оставляю ссылку на ресурс, где можно найти предполагаемые расшифровки имен оракловых функций. Надеюсь, что эта статья была вам полезна.

Буду рад обратной связи: возможно, вы тоже сталкивались с подобными проблемами и у вас есть опыт, которым можно поделиться.

© Habrahabr.ru