По мотивам одного сбоя в БД Oracle

Всем привет! Я Тимур, инженер в команде Databases Т-Банка. Занимаюсь решением проблем и настройкой производительности СУБД Oracle и PostgreSQL Oracle — это СУБД для наших критичных  нагруженных legacy систем, в новой архитектуре используется PostgreSQL.

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

Первый взгляд на проблему

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

На одной из наших критичных баз данных мы заметили резкий рост ожиданий классов Concurrency и Configuration.

Первичная диагностика показала, что вставка в таблицу TABLE_NAME невозможна из-за конкуренции за ITL-слоты, а блокированные сессии ждут компиляции анонимного PL/SQL-блока, которая, несмотря на отсутствие в БД объектов со статусом invalid, завершалась с ошибкой.

 Из hanganalyze dump’а:

[a] Chain 1 Signature: 'library cache: mutex X'<='library cache  lock'<='library cache lock'<='enq: TX - allocate ITL entry'        Oracle session identified by:     {                 instance: 1 (inst_name)                    os id: 2434797               process id: 1536, oracle@host_name               session id: 19         session serial #: 21746              module name: 0 (JDBC Thin Client)     }     is waiting for 'enq: TX - allocate ITL entry' with wait info:     {                       p1: 'name|mode'=0x54580004                       p2: 'usn<<16 | slot'=0x570010                       p3: 'sequence'=0x2f1363e             time in wait: 0.836918 sec            timeout after: 0.163082 sec                  wait id: 482                 blocking: 0 sessions           current sql_id: 3073959386              current sql: insert into TABLE_NAME(...) values (:1 , :2, ...)              short stack: ksedsts()+426<-ksdxfstk()+58<-ksdxcb()+872<-sspuser()+223<-__sighandler()<-semtimedop()+14<-skgpwwait()+192<-k sliwat()+2199<-kslwaitctx()+205<-ksqcmi()+21656<-ksqgtlctx()+6620<-ksqgelctx()+838<-ktuGetTxForXid()+324<-ktcwit1()+502<-ktbgfi()+5287<- kdiins1()+51209<-kdiinsp0()+129<-kauxsin()+2040<-qesltcLoadIndexList()+873<-qerltcNoKdtBufferedInsRowCBK()+361<-qerltcSingleRowLoad()+29 3<-qerltcFetch()+391<-insexe()+736<-opiexe()+6705<-kpoal8()+2226<-opiodr()+1202<-ttcpip()+1231<-opitsk()+1900<-opiino()+936<-opiodr()+12 0 ... ...     and is blocked by  => Oracle session identified by:     {                 instance: 1 (inst_name)                    os id: 2422621               process id: 2142, oracle@host_name               session id: 2163         session serial #: 42658              module name: 0 (JDBC Thin Client)     }     which is waiting for 'library cache lock' with wait info:     {                       p1: 'handle address'=0x35f081870                       p2: 'lock address'=0x3ba1fb300                       p3: '100*mode+namespace'=0x520002                     Name: $BUILD$.5ae3613f4b754907   [Nsp: 82 Typ: 0 Id: 0]             time in wait: 0.093654 sec            timeout after: 14 min 59 sec                  wait id: 7370                 blocking: 3 sessions           current sql_id: 1524851007              current sql: BEGIN Owner.Package.Procedure(:1 , :2 , :3 ); END;              short stack: ksedsts()+426<-ksdxfstk()+58<-ksdxcb()+872<-sspuser()+223<-__sighandler()<-semtimedop()+14<-skgpwwait()+192<-k sliwat()+2199<-kslwaitctx()+205<-kglLockWait()+804<-kglUpgradeLock()+1080<-kksGetBuildLock()+317<-kksfbc()+17011<-kkspsc0()+1575<-kksPar seCursor()+114<-opiosq0()+2310<-kpooprx()+287<-kpoal8()+821<-opiodr()+1202<-ttcpip()+1231<-opitsk()+1900<-opiino()+936<-opiodr()+1202<-o pidrv()+1094<-sou2o()+165<-opimai_real()+422<-ssthrdmain()+417<-main()+256<-__libc_start_main()+229<-0x5541F689495641D7

В стеке, относящемся к вставке в TABLE_NAME, видим функцию kauxsin, предполагаемая расшифровка названия — kernel access perform inserts, updates, deletes modifying indexes on tables insert a key into x index segment(s) only. Это означает, что сессия, которая делает вставку строки в таблицу, добавляет запись в индекс, относящийся к этой таблице. При модификации блока сессия должна сделать запись о транзакции в специальную строку —  ITL-слот. Число слотов ограничено, и сессия начинает ожидание enq: TX — allocate ITL entry.

В стеке, относящемся к компиляции PL/SQL-блока, видим функцию kksfbc — kernel compile shared objects (cursor) find bound cursor. Это значит, что блокирующая вставку в таблицу TABLE_NAME сессия занимается не относящейся к этой таблице активностью — компилирует курсор для выполнения PL/SQL-блока. При этом в alert.log’е экземпляра были замечены ошибки, относящиеся к интересующему нас PL/SQL-блоку вида: 

WARNING: too many parse errors, count=700 SQL hash=0x4b754907 PARSE ERROR: ospid=2342730, error=6550 for statement:

Первый test case — получаем ожидания ‘enq: TX — allocate ITL entry’

Разберемся детально, что происходит, — сделаем пару небольших test case. 

Для начала вспомним, откуда берется конкуренция за ITL-слоты. Oracle ограничивает число активных транзакций для листового блока индекса. Например, если 350 сессий конкурентно вставляют данные в таблицу, одновременно в листовом блоке может быть не более 168 активных транзакций.

В версии 11.2.0.4 и 12.1.0.1 внесено исправление: Bug 8767925 — ITL wasting a lot of space in indexes with high concurrency (Doc ID 8767925.8), которое описано так: During concurrent access to a hot index leaf block, it is possible for the ITL size to grow disproportionately to the number of concurrent transactions.

Один ITL-слот занимает 24 байта, максимальное число слотов — 168 плюс 1 слот для service ITL, Oracle может занять половину листового блока ITL-слотами. Это довольно много несмотря на вышеупомянутое исправление.

Test case1. Воспроизводим ожидания enq: TX — allocate ITL entry:

SQL> create table app.instab(n number,v varchar2(40)); SQL> create index app.instabn on app.instab(n);   SQL> create sequence app.instabseq;    $ cat itlslots.sh insert(){ sqlplus -s "/ as sysdba"<<EOF declare r varchar2(300); n number; begin  n:=app.instabseq.nextval;  insert into app.instab values (n,'varchar value '||n);  dbms_session.sleep(120); end; / EOF }    for ((i=1;i<=256;i++))  do     insert $i & done

Скрипт запускает одновременную вставку в таблицу, из-за задержки 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 под нагрузкой может привести к усугублению ситуации.

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

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

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