On Oracle: One Case of ORA-00036: Maximum Number Of Recursive SQL Levels (50) Exceeded

ORA-00036 is documented as:

  00036, 00000, "maximum number of recursive SQL levels (%s) exceeded"
  // *Cause:  An attempt was made to go more than the specified number
  //          of recursive SQL levels.
  // *Action: Remove the recursive SQL, possibly a recursive trigger.

The most (possibly only) circulated test code is about recursive trigger
(see MOS: PL/SQL Trigger causes ORA-00036: Maximum Number Of Recursive SQL Levels (50) Exceeded (Doc ID 1478056.1)).

This Blog will demonstrate one most often occurred case of ORA-00036 in Oracle applications.

Note: Tested in Oracle 19.13, 19.7, 18.9, 12.1

1. Test Setup

We create a Plsql procedure, which makes dynamic recursive calls with execute immediate.


create or replace procedure recursive_dynamic (p_depth number) as 
begin
  dbms_output.put_line('Depth = '|| p_depth); 
  execute immediate q'[begin recursive_dynamic (:dep); end;]' using p_depth + 1;
end;
/

2. Dynamic Recursive Call

We run the test with "36 trace" and "10046 trace". (See MOS: OERR: ORA-36 "maximum number of recursive SQL levels (%s) exceeded" Reference Note (Doc ID 48793.1))


alter session set max_dump_file_size = UNLIMITED;
alter session set events='36 trace name errorstack level 3: 10046 trace name context forever, level 12' 
                  tracefile_identifier='recursive_trc';
            
begin      
  execute immediate q'[begin recursive_dynamic (:dep); end;]' using 1;
end;
/

alter session set events='36 trace name errorstack off: 10046 trace name context off';

After a few seconds, session throws ORA-00036 after 51 recursive calls:


Depth = 1
Depth = 2
Depth = 3
...
Depth = 49
Depth = 50
Depth = 51

ORA-00036: maximum number of recursive SQL levels (50) exceeded
ORA-06512: at "K.RECURSIVE_DYNAMIC", line 4
ORA-06512: at line 1

Elapsed: 00:00:02.92

Trace file shows 51 "PARSING IN CURSOR" with dep=1 to dep=51 and Bind#0 from value=1 to value=51:


PARSING IN CURSOR #140643820632152 dep=1 tim=142118502429 hv=3989675504 ad='8cbdaf18' sqlid='2s8jqqgqwv7gh'
begin recursive_dynamic (:dep); end;
END OF STMT
PARSE #140643820632152:c=238,e=238,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=142118502429
BINDS #140643820632152:

 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fea315aff88  bln=22  avl=02  flg=05
  value=1
  
...
 
PARSING IN CURSOR #140643819871240 dep=51 tim=142118509346 hv=3989675504 ad='8cbdaf18' sqlid='2s8jqqgqwv7gh'
begin recursive_dynamic (:dep); end;
END OF STMT
PARSE #140643819871240:c=12,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=51,og=1,plh=0,tim=142118509346
BINDS #140643819871240:

 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fea30ebb770  bln=22  avl=02  flg=09
  value=51

Here the Call Stack:


----- Error Stack Dump -----
ORA-00036: maximum number of recursive SQL levels (50) exceeded
Current SQL information unavailable - no cursor.
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x8cccbf90         4  procedure K.RECURSIVE_DYNAMIC
0x8cbcedf0         1  anonymous block
0x8cccbf90         4  procedure K.RECURSIVE_DYNAMIC
0x8cbcedf0         1  anonymous block
0x8cccbf90         4  procedure K.RECURSIVE_DYNAMIC
0x8cbcedf0         1  anonymous block
0x8cccbf90         4  procedure K.RECURSIVE_DYNAMIC  
  
--------------------- Binary Stack Dump ---------------------
[13] (dbkePostKGE_kgsf()+71 -> dbgePostErrorKGE()) 
[14] (kgeade()+392 -> dbkePostKGE_kgsf()) 
[15] (kgeselv()+89 -> kgeade()) 
[16] (ksesec1()+205 -> kgeselv()) 
[17] (ksuprc()+1629 -> ksesec1()) 
[18] (opiodr()+760 -> ksuprc()) 
[19] (rpidrus()+198 -> opiodr()) 
[20] (skgmstack()+65 -> rpidrus()) 
[21] (rpidru()+132 -> skgmstack()) 
[22] (rpiswu2()+543 -> rpidru()) 
[23] (rpidrv()+1266 -> rpiswu2()) 
[24] (psddr0()+467 -> rpidrv()) 
[25] (psdopn()+72 -> psddr0()) 
[26] (plcurOpen()+64 -> psdopn()) 
[27] (kgscGetCursor()+4842 -> plcurOpen()) 
[28] (pevm_I4EXIM()+601 -> kgscGetCursor()) 
[29] (pfrinstr_I4EXIM()+167 -> pevm_I4EXIM()) 
[30] (pfrrun_no_tool()+60 -> pfrinstr_I4EXIM()) 
[31] (pfrrun()+902 -> pfrrun_no_tool()) 
[32] (plsql_run()+752 -> pfrrun())

In Call Stack Trace, we can see that Oracle detected "recursion pattern":


----- Call Stack Trace -----

**** At frame 91 recursion pattern of size 17 found, for return address 
     rpiswu2()+543 suppressing  printing.
**** At frame 100 recursion pattern broken, last return was 
     plsql_run()
     
**** At frame 891 recursion pattern of size 17 found, for return address 
     rpidrv()+1266 suppressing  printing.
**** At frame 900 recursion pattern broken, last return was 
     peicnt()

The 51 recursive calls generated 51 Cursors from Cursor#7 to Cursor#57 with Bind#0 from value=1 to value=51:


----------------------------------------
Cursor#7(0x7fea318a0908) state=BOUND curiob=0x7fea30f7f858
 curflg=0xcd fl2=0x0 fl3=0x0 par=(nil) ses=0xb8c54908
----- Dump Cursor sql_id=2s8jqqgqwv7gh xsc=0x7fea30f7f858 cur=0x7fea318a0908 -----

LibraryHandle:  Address=0x8cbdaf18 Hash=edcd9df0 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=begin recursive_dynamic (:dep); end; 
  
----- Bind Info (kkscoacd) -----
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fea315aff88  bln=22  avl=02  flg=05
  value=1
  
...

----------------------------------------
Cursor#57(0x7fea318a2848) state=BOUND curiob=0x7fea30ec5c08
 curflg=0xc5 fl2=0x0 fl3=0x0 par=(nil) ses=0xb8c54908
----- Dump Cursor sql_id=2s8jqqgqwv7gh xsc=0x7fea30ec5c08 cur=0x7fea318a2848 -----

LibraryHandle:  Address=0x8cbdaf18 Hash=edcd9df0 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD 
  ObjectName:  Name=begin recursive_dynamic (:dep); end; 

----- Bind Info (kkscoacd) -----
 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=7fea30ebb770  bln=22  avl=02  flg=09
  value=51

10046 SQL trace shows Parse and Execute with count=51:


SQL ID: 2s8jqqgqwv7gh Plan Hash: 0

begin recursive_dynamic (:dep); end;


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       51      0.00       0.00          0          0          0           0
Execute     51      2.76       2.89          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total      102      2.76       2.89          0          0          0           0

Misses in library cache during parse: 1
Misses in library cache during execute: 2
Optimizer mode: ALL_ROWS
Parsing user id: 49     (recursive depth: 1)

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  PGA memory operation                            7        0.00          0.00

3. Static Recursive Call

In contrast to "execute immediate" dynamic calls, we can also test static recursive calls as follows.


create or replace procedure recursive_static (p_depth number) as 
begin
  recursive_static(p_depth + 1);
end;
/
   
alter session set max_dump_file_size = UNLIMITED;
alter session set events='36 trace name errorstack level 3: 10046 trace name context forever, level 12' 
                  tracefile_identifier='static_trc'; 
begin      
  execute immediate q'[begin recursive_static (:dep); end;]' using 1;
end;
/

alter session set events='36 trace name errorstack off: 10046 trace name context off';

If the machine has sufficient memory (more than 32 GB), after about one hour, session throws ORA-03114.


begin
  execute immediate q'[begin recursive_static (:dep); end;]' using 1;
end;
 /
 
ORA-03114: not connected to ORACLE

ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 11285
Session ID: 564 Serial number: 15134

Elapsed: 00:59:46.25

In DB alert.log / Trace / Incident file, we can see ORA-04030: out of process memory due to PL/SQL STACK.


-- DB alert.log / Trace / Incident file
ORA-04030: out of process memory when trying to allocate 8216 bytes (PLS PGA hp,PL/SQL STACK)

82%   26 GB, 3421439 chunks: "PL/SQL STACK              "  PL/SQL
         PLS PGA hp      ds=7fffbdb2bd40  dsprt=7fffbdb831f0
17% 5436 MB, 349774 chunks: "pl/sql vc2                "  PL/SQL
         koh-kghu sessi  ds=7fffbbfa3050  dsprt=7fffbd8f96b8
 1%  200 MB, 12842 chunks: "pmucalm coll              "  PL/SQL
         koh-kghu sessi  ds=7fffbd749660  dsprt=7fffbd8f96b8

If the machine has not sufficient memory (less than 32 GB), session also hits ORA-03114.


begin
  execute immediate q'[begin recursive_static (:dep); end;]' using 1;
end;
/

ORA-03114: not connected to ORACLE

ERROR at line 1:
ORA-03113: end-of-file on communication channel
Process ID: 20417
Session ID: 14 Serial number: 53851

Elapsed: 00:01:27.51

But DB alert.log / Trace / Incident file reported ORA-6544:


ORA-6544 [pevm_peruws_callback-1] [27102] [] [] [] [] [] [] [] [] [] []

========= Dump for incident 28438 (ORA 6544 [pevm_peruws_callback-1]) ========

----- Current SQL Statement for this session (sql_id=g3u50dymhsuwn) -----
begin recursive_static (:dep); end;

----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x8cccb400         1  procedure K.RECURSIVE_STATIC
0x8cccb400         4  procedure K.RECURSIVE_STATIC
0x8cccb400         4  procedure K.RECURSIVE_STATIC
0x8cccb400         4  procedure K.RECURSIVE_STATIC
0x8cccb400         4  procedure K.RECURSIVE_STATIC
0x8cccb400         4  procedure K.RECURSIVE_STATIC

[8]  (dbgePostErrorDirect()+798 -> dbgePostErrorDirectVaList_int()) 
[9]  (pevm_peruws_callback()+1233 -> dbgePostErrorDirect()) 
[10] (kgepop()+438 -> pevm_peruws_callback()) 
[11] (kgersel()+256 -> kgepop()) 
[12] (ksmrf_init_alloc()+508 -> kgersel()) 
[13] (ksmapg()+539 -> ksmrf_init_alloc()) 
[14] (kgh_invoke_alloc_cb()+494 -> ksmapg()) 
[15] (kghgex()+2751 -> kgh_invoke_alloc_cb()) 
[16] (kghfnd()+1030 -> kghgex()) 
[17] (kghalo()+6631 -> kghfnd()) 
[18] (kghgex()+760 -> kghalo()) 
[19] (kghalf()+1607 -> kghgex()) 
[20] (pfrsgr()+246 -> kghalf()) 
[21] (pevm_ENTER()+3089 -> pfrsgr()) 
[22] (pfrinstr_ENTER()+59 -> pevm_ENTER()) 
[23] (pfrrun_no_tool()+60 -> pfrinstr_ENTER()) 
[24] (pfrrun()+902 -> pfrrun_no_tool()) 
[25] (plsql_run()+752 -> pfrrun())

In Oracle, ORA-6544 is documented as:

  06544, 00000, "PL/SQL: internal error, arguments: [%s], [%s], [%s], [%s], [%s], [%s], [%s], [%s]"
  // *Cause: A pl/sql internal error occurred.
  // *Action:Report as a bug; the first argument is the internal error nuber.

Note*: typo "nuber"

In such case, Linux dmesg shows that session process hits "Out of memory", so in-kernel, that is still something similar to ORA-04030.


[09:55:19] Out of memory: Kill process 20417 (oracle_20417_c0) score 784 or sacrifice child
[09:55:19] Killed process 20417 (oracle_20417_c0) total-vm:23949296kB, anon-rss:18819800kB, file-rss:2332kB, shmem-rss:375432kB

Tuesday, May 24, 2022

One Case of ORA-00036: Maximum Number Of Recursive SQL Levels (50) Exceeded

1. Test Setup

2. Dynamic Recursive Call

3. Static Recursive Call