Oracle forall DML save exceptions and ORA-04030: out of process memory (callheap,psdalf:RPI allocations)

The FORALL statement sends DML statements from PL/SQL to SQL in batches (rather than one at a time) to boost performance, notably in case of large bulk of DML statements. It saves exceptions in implicit cursor attribute SQL%BULK_EXCEPTIONS, and the number of rows affected by the ith DML statement in SQL%BULK_ROWCOUNT.

In this Blog, we will first show the limit of exceptions handling, and then demonstrate error:

    ORA-04030: out of process memory when trying to allocate 1048 bytes (callheap,psdalf:RPI allocations)

Note: Tested in Oracle 12c, 18c, 19c.

1. SQL%BULK_EXCEPTIONS Limit

At first, we setup our test using forall insert save exceptions on table psdalf_test_tab, which is created with a primary key so that in case of duplicated insert, one error is generated for each row:

   ORA-00001: unique constraint violated.

--------------- Test Code ---------------

drop table psdalf_test_tab purge;

create table psdalf_test_tab (
  id          number,
  txt         varchar2(100),
  constraint  psdalf_test_tab#p primary key (id));

create or replace procedure psdalf_test (p_cnt number) as
  type            t_tab    is table of psdalf_test_tab%rowtype;
  type            t_id_tab is table of number(12);
  l_tab           t_tab         := t_tab();
  l_txt           varchar2(100) := rpad('ABC', 100, 'X');
  l_id_tab        t_id_tab      := t_id_tab();
  l_excp_cnt      number;
begin
  for i in 1 .. p_cnt loop
    l_tab.extend;
    l_tab(i).id := i;
    l_tab(i).txt := l_txt;
  end loop;
  
  --select level, l_txt, l_txt, l_txt, l_txt, l_txt bulk collect into l_tab from dual connect by level <= p_cnt;  -- when p_cnt < 1e6
  
  forall i in l_tab.first .. l_tab.last save exceptions
    insert into psdalf_test_tab values l_tab(i)
    --returning id bulk collect into l_id_tab
  ;
    
  --** The COUNT method is not implemented on collection SQL%BULK_ROWCOUNT. Use the COUNT of the result set.
  --dbms_output.put_line('---*** bulk_rowcount.count='||l_id_tab.count);
  
  commit;
      
  exception when others then
    l_excp_cnt     := sql%bulk_exceptions.count;
    if l_excp_cnt > 0 then
       dbms_output.put_line('Insert '||p_cnt||' rows, Errors Hit bulk_exceptions.count='  ||l_excp_cnt);
       dbms_output.put_line('  Last Record sql%bulk_exceptions('|| l_excp_cnt ||'):'||
                            '  error_index=' || sql%bulk_exceptions(l_excp_cnt).error_index || 
                            ', error_code='  || sql%bulk_exceptions(l_excp_cnt).error_code);
    else
       dbms_output.put_line('Insert '||p_cnt||' rows, No Error Hit bulk_exceptions.count='||l_excp_cnt);
    end if;
end;
/

We will run three tests with different input parameters. In each test, we first truncate table, then perform two forall inserts with the same collection of rows. Since both inserts are with same rows, the second insert hit "ORA-00001: unique constraint violated" for each row.

If sql%bulk_exceptions.count is not zero, we print out its value and last record of sql%bulk_exceptions as well.
(Note: COUNT method is not implemented on collection SQL%BULK_ROWCOUNT)

Here three executions and their output:

---=========================== 10 rows insert ===========================---
begin
  execute immediate 'truncate table psdalf_test_tab';
  psdalf_test(10);
  psdalf_test(10);
end;
/

-------------- 10 rows insert Output count=10 --------------
Insert 10 rows, Errors Hit bulk_exceptions.count=10
  Last Record sql%bulk_exceptions(10):  error_index=10, error_code=1


--=========================== 65536 rows insert ===========================---
begin
  execute immediate 'truncate table psdalf_test_tab';
  psdalf_test(65536);
  psdalf_test(65536);
end;
/

-------------- 65536 rows insert Output count=0 --------------
 Insert 65536 rows, No Error Hit bulk_exceptions.count=0


--=========================== 65537 rows insert ===========================---
begin
  execute immediate 'truncate table psdalf_test_tab';
  psdalf_test(65537);
  psdalf_test(65537);
end;
/

-------------- 65537 rows insert Output count=1 --------------
Insert 65537 rows, Errors Hit bulk_exceptions.count=1
  Last Record sql%bulk_exceptions(1):  error_index=65537, error_code=1

The above tests showed that cursor attribute SQL%BULK_EXCEPTIONS has a Limit of 65536 (overflow) even though "forall insert" is conceived for large bulk DML. Once reaching 65536, sql%bulk_exceptions.count is wrongly set to zero. For 65537 rows insert, sql%bulk_exceptions.count returns 1, but error_index is not reset. Therefore, this special behaviour has to be handled when used in PL/SQL code.

By the way, associative array SQL%BULK_EXCEPTIONS is defined in SYS.STANDARD package as:

  type " SYS$BULK_ERROR_RECORD" is record (error_index pls_integer, error_code pls_integer);
          
  type " SYS$REC_V2TABLE" is table of " SYS$BULK_ERROR_RECORD" index by binary_integer;

In ASKTOM: Passing the SQL%BULK_EXCEPTIONS Collection to a Procedure , 65536 BULK_EXCEPTIONS limit was asked, but not further handled.

2. ORA-04030: out of process memory (callheap,psdalf:RPI allocations)

In this test, we will run two forall inserts in two executions:

2.1 First Execution

We truncate table and insert 30*1e6 rows (We choose 30*1e6 rows to generate ORA-04030 in the later Second Execution since ORA-04030 occurs when PGA reaches 32 GB with each row about 1500 Bytes).

begin
  execute immediate 'truncate table psdalf_test_tab';
  psdalf_test(30*1e6);
end;
/

During the execution, we monitor the session memory usage:

SQL> select s.sid, s.serial#, pid, spid, pga_used_mem, pga_alloc_mem, pga_max_mem
  2  from v$session s, v$process p where s.paddr=p.addr and pid = 77;

 SID SERIAL#  PID SPID                                   PGA_USED_MEM    PGA_ALLOC_MEM      PGA_MAX_MEM
---- ------- ---- ---------------------------------- ---------------- ---------------- ----------------
 672    4192   77 37290262                             10,043,543,018   10,079,497,394   10,079,497,394

SQL> select * from v$process_memory where pid= 77;

 PID SERIAL# CATEGORY          ALLOCATED             USED    MAX_ALLOCATED           CON_ID
---- ------- ---------- ---------------- ---------------- ---------------- ----------------
  77      46 SQL                 309,360          109,376        7,008,256                0
  77      46 PL/SQL        8,896,619,920    8,855,034,144    8,896,619,920                0
  77      46 Other         1,182,568,114                     1,182,568,114                0

We can see that the top CATEGORY consumers are 8 GB "PL/SQL" and 1 GB "Other" ("PL/SQL" is for nested table l_tab in psdalf_test).

To see the details of "PL/SQL" and "Other", we can use event PGA_DETAIL_GET to populate memory details (heap/subheap) into v$process_memory_detail: (see Blog: Oracle Memory Troubleshooting, Part 4: Drilling down into PGA memory usage with V$PROCESS_MEMORY_DETAIL , or pga_sampling in Blog: dbms_session.get_package_memory_utilization and limitations )

  
SQL> alter session set events'immediate trace name PGA_DETAIL_GET level 77';    -- 77 is Oracle session PID

SQL> select * from v$process_memory_detail_prog;

   PID SERIAL# STATUS  
  ---- ------- --------
    77      46 SCANNING

SQL> exec dbms_session.sleep(2);      -- wait 2 seconds for SCANNING changed to COMPLETE

SQL> select * from v$process_memory_detail_prog;

   PID SERIAL# STATUS  
  ---- ------- --------
    77      46 COMPLETE

SQL> select * from (select * from v$process_memory_detail order by bytes desc) where rownum <= 5;  --only top 5

 PID SERIAL# CATEGORY   NAME                   HEAP_NAME                  BYTES ALLOCATION_COUNT HEAP_DESCRIPTOR  PARENT_HEAP_DESC           CON_ID
---- ------- ---------- ---------------------- --------------- ---------------- ---------------- ---------------- ---------------- ----------------
  29     121 PL/SQL     pmucalm coll           koh-kghu call      4,407,120,008          269,781 0000000120FA26C0 0000000120C72CD8                0
  29     121 PL/SQL     pl/sql vc2             koh-kghu call      4,335,712,280          265,410 0000000120FA26C0 0000000120C72CD8                0
  29     121 Other      psdalf:RPI allocations callheap           1,140,000,072                3 0000000120C6E590 0000000120C72F88                0
  29     121 PL/SQL     DPAGE                  PLS UGA hp           124,556,056          124,204 0000000121064BD0 0000000120FB98F0                0
  29     121 PL/SQL     free memory            koh-kghu call         25,281,768            8,513 0000000120FA26C0 0000000120C72CD8                0

The above output shows that 8 GB CATEGORY "PL/SQL" includes "pmucalm coll" and "pl/sql vc2" in HEAP "koh-kghu call". (see Blog: PL/SQL Multidimensional Collection Memory Usage and Performance ).

1 GB CATEGORY "Other" is for "psdalf:RPI allocations" in HEAP "callheap" with "ALLOCATION_COUNT" 3.

It takes about 2 minutes, and maximum session PGA is about 9GB memory in this First Execution.

2.2 Second Execution

Now we run the second "forall insert" to generate ORA-00001 for each row insert:

begin
  psdalf_test(30*1e6);
end;
/

It will take about 1 and half hour. Here the memory usage a few minutes before finish:

SQL> select s.sid, s.serial#, pid, spid, pga_used_mem, pga_alloc_mem, pga_max_mem
     from v$session s, v$process p where s.paddr=p.addr and pid = 77;

   SID SERIAL#  PID SPID        PGA_USED_MEM    PGA_ALLOC_MEM      PGA_MAX_MEM
  ---- ------- ---- -------- --------------- ---------------- ----------------
   672    4192   77 37290262  32,417,511,642   32,465,677,490   32,465,677,490

SQL> select * from v$process_memory where pid= 77;

   PID SERIAL# CATEGORY          ALLOCATED             USED    MAX_ALLOCATED
  ---- ------- ---------- ---------------- ---------------- ----------------
    77      46 SQL                 511,176                0        7,006,880
    77      46 PL/SQL        8,942,286,944    8,899,000,728    9,023,735,784
    77      46 Freeable             65,536                0                 
    77      46 Other        23,522,813,834                    23,522,813,834

Here the populated memory details (only showed top 5):

SQL> alter session set events'immediate trace name PGA_DETAIL_GET level 77';    -- 77 is Oracle session PID

SQL> select * from v$process_memory_detail_prog;

   PID SERIAL# STATUS  
  ---- ------- --------
    77      46 SCANNING

SQL> exec dbms_session.sleep(10);     -- wait 10 seconds for SCANNING changed to COMPLETE

SQL> select * from v$process_memory_detail_prog;

   PID SERIAL# STATUS  
  ---- ------- --------
    77      46 COMPLETE

SQL> select * from (select * from v$process_memory_detail order by bytes desc) where rownum <= 5;  --only top 5

   PID SERIAL# CATEGORY NAME                   HEAP_NAME                BYTES ALLOCATION_COUNT HEAP_DESCRIPTOR  PARENT_HEAP_DESC
  ---- ------- -------- ---------------------- ------------- ---------------- ---------------- ---------------- ----------------
    77      46 Other    psdalf:RPI allocations callheap        22,423,878,184       20,309,047 0000000120C6E590 0000000120C72F88
    77      46 PL/SQL   pmucalm coll           koh-kghu call    4,407,120,008          269,781 0000000120FA26C0 0000000120C72CD8
    77      46 PL/SQL   pl/sql vc2             koh-kghu call    4,335,712,280          265,410 0000000120FA26C0 0000000120C72CD8
    77      46 Other    qerltcHashAllocCB      callheap         1,031,833,160       20,309,046 0000000120C6E6D8 0000000120C72F88
    77      46 PL/SQL   DPAGE                  PLS UGA hp         169,059,432          168,582 0000000121064BD0 0000000120FB98F0

Here the output of UNIX PS command (AIX nmon) about "Res Data":

     PID       %CPU     Size      Res    Res      Res   Char    RAM   Paging           Command 
               Used       KB      Set    Text     Data   I/O    Use  io   other repage        
   ---------- ----- -------- --------  ------ --------  -----  ----  ----------------- -------
   37290262    75.8 32331288 32229672  270528 31959144      0   49%   0      0      0  oracle 

The above output shows 8 GB CATEGORY "PL/SQL" similar to above First Execution.

However, in CATEGORY "Other", "psdalf:RPI allocations" is incresed to about 20 GB from 1 GB of First Execution. Its "ALLOCATION_COUNT" is increased to 20,309,047 ('qerltcHashAllocCB' is 20,309,046, one less). In the later Heap Dump, we can see that each ALLOCATION is for one single row insert exception, and allocated exactly 1048 Bytes. So 20,309,047 indicates same number of single row insert exceptions, and sums up to 21,283,881,256 (20,309,047 * 1048) Bytes.

After 1 and half hours, execution finished with error_code=4030 (Oracle session is not disconnected):

SQL> begin
       psdalf_test(30*1e6);
     end;
     /

  Insert 30000000 rows, Errors Hit bulk_exceptions.count=1
    Last Record sql%bulk_exceptions(1):  error_index=21646075, error_code=4030
  
  PL/SQL procedure successfully completed.
  
  Elapsed: 01:30:38.32

The incident trace (Oracle 19.8 AIX) shows that it cannot get 1048 bytes (callheap,psdalf:RPI allocations):

ORA-04030: out of process memory when trying to allocate 1048 bytes (callheap,psdalf:RPI allocations)
ORA-00001: unique constraint (K.PSDALF_TEST_TAB#P) violated

=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------
*** 2021-03-21T09:00:05.707385+01:00
70%   22 GB, 21646003 chunks: "psdalf:RPI allocations    "  
         callheap        ds=120c6e590  dsprt=120c72f88
13% 4203 MB, 269781 chunks: "pmucalm coll              "  PL/SQL
         koh-kghu call   ds=120fa26c0  dsprt=120c72cd8
13% 4135 MB, 265410 chunks: "pl/sql vc2                "  PL/SQL
         koh-kghu call   ds=120fa26c0  dsprt=120c72cd8
 3% 1100 MB, 21646003 chunks: "qerltcHashAllocCB         "  
         callheap        ds=120c6e6d8  dsprt=120c72f88
 1%  172 MB, 179680 chunks: "DPAGE                     "  PL/SQL
         PLS UGA hp      ds=121064bd0  dsprt=120fb98f0
 0%   24 MB, 8513 chunks: "free memory               "  PL/SQL
         koh-kghu call   ds=120fa26c0  dsprt=120c72cd8
 0%   20 MB, 375 chunks: "free memory               "  
         pga heap        ds=120c72cd8  dsprt=0
 0%   11 MB, 21648 chunks: "free memory               "  
         callheap        ds=120c6e590  dsprt=120c72f88
 0% 3348 KB, 247 chunks: "free memory               "  
         session heap    ds=120fb98f0  dsprt=120c73238
 0% 3288 KB, 732 chunks: "free memory               "  
         top call heap   ds=120c72f88  dsprt=0
         
=========================================
REAL-FREE ALLOCATOR DUMP FOR THIS PROCESS
-----------------------------------------
Dump of Real-Free Memory Allocator Heap [0x120f77ab0]
mag=0xfefe0001 flg=0x5000007 fds=0x0 blksz=65536
blkdstbl=0x120f77ac8, iniblk=524288 maxblk=524288 numsegs=314
In-use num=1750 siz=33975238656, Freeable num=2 siz=22085632, Free num=3 siz=38273024
Client alloc 33997324288 Client freeable 22085632

The above REAL-FREE ALLOCATOR DUMP shows the PGA limit of 32 GB (maxblk*blksz = 524288*65536/1024/1024/1024), and current used is 34,035,597,312 (33975238656+22085632+38273024) Bytes, that is 519342 (34,035,597,312/65536) times 64K blocks.

The Call Stack looks like:
(psdalf looks like a short form of PlSqlDmlALocationForall, invoked to allocate memory for Plsql BatchError handlng)

FRAME [11] (IPRA.$kghnospc()+5140 -> dbgeEndDDEInvocation())
FRAME [12] (kghalf()+2372 -> IPRA.$kghnospc())
FRAME [13] (psdalf()+48 -> kghalf())
FRAME [14] (IPRA.$qerltcLogBatchError()+308 -> psdalf())
FRAME [15] (IPRA.$qerltcRowProcessingErrorHandler()+516 -> IPRA.$qerltcLogBatchError())
FRAME [16] (IPRA.$qerltcInsertValues()+1316 -> IPRA.$qerltcRowProcessingErrorHandler())
FRAME [17] (qerltcFetch()+1812 -> IPRA.$qerltcInsertValues())
FRAME [18] (insexe()+788 -> qerltcFetch())
FRAME [19] (opiexe()+21296 -> insexe())
FRAME [20] (opipls()+2412 -> opiexe())
FRAME [21] (opiodr()+1256 -> opipls())
FRAME [22] (rpidrus()+208 -> opiodr())
FRAME [23] (skgmstack()+116 -> rpidrus())
FRAME [24] (rpidru()+152 -> skgmstack())
FRAME [25] (rpiswu2()+584 -> rpidru())
FRAME [26] (rpidrv()+1112 -> rpiswu2())
FRAME [27] (IPRA.$psddr0()+224 -> rpidrv())
FRAME [28] (psdnal()+676 -> IPRA.$psddr0())
FRAME [29] (pevm_EXECC()+336 -> psdnal())
FRAME [30] (pfrinstr_EXECC()+108 -> pevm_EXECC())
FRAME [31] (IPRA.$pfrrun_no_tool()+92 -> pfrinstr_EXECC())
FRAME [32] (pfrrun()+1176 -> IPRA.$pfrrun_no_tool())
FRAME [33] (plsql_run()+696 -> pfrrun())

Session throws ORA-04030 when its PGA memory usage reaches 32 GB. The above trace file shows the top consumer:

   70%   22 GB, 21646003 chunks: "psdalf:RPI allocations    "  

21646003 chunks of "psdalf:RPI allocations" takes about 22 GB, i.e. each chunk is about 1091 Bytes (22*1024*1024*1024/21646003).

If we make a HEAPDUMP dump, it shows that each "psdalf:RPI allo" Chunk is exactly 1048 Bytes:

	Received ORADEBUG command (#2) 'DUMP HEAPDUMP 255' from process '14998'
	******************************************************
	HEAP DUMP heap name="callheap"  desc=0x7f6dd76c9140
	 extent sz=0x440 alt=32767 het=32767 rec=0 flg=0x2 opc=0
	 dsx heap size=2538705328, dsx heap depth=1
	EXTENT 0 addr=0x7f6bd746b138
	  Chunk     7f6bd746b148 sz=   154560    free      "               "
	  Chunk     7f6bd7490d08 sz=     1048    freeable  "psdalf:RPI allo"
	  Chunk     7f6bd7491120 sz=     1048    freeable  "psdalf:RPI allo"
	  Chunk     7f6bd7491538 sz=     1048    freeable  "psdalf:RPI allo"
	  Chunk     7f6bd7491950 sz=     1048    freeable  "psdalf:RPI allo"
	  Chunk     7f6bd7491d68 sz=     1048    freeable  "psdalf:RPI allo"
	  Chunk     7f6bd7492180 sz=     1048    freeable  "psdalf:RPI allo"         

so above 21646003 chunks takes about 21 GB (21646003*1048/(1024*1024*1024)). In comparing to 22 GB reported in trace file, the extra 1 GB is probably some kind of base load, which is also reported in the First Execution (1,140,000,072 Bytes).

In the above populated memory details, "psdalf:RPI allocations" ALLOCATION_COUNT is 20,309,047, so it is very close to ORA-04030 of 21646003 chunks.

One more remark is that callheap "psdalf:RPI allocations" is classified in CATEGORY: "Other".

In fact, ORA-04030 (callheap,psdalf:RPI allocations) was also once revealed in ASKTOM: Problem with BULK COLLECT with million rows Problem with BULK COLLECT with million rows , but not further explored.