Tuesday, March 7, 2023

One Test of Oracle JSON Plsql PGA Memory Leak

In this Blog, we make a test to demonstrate JSON PGA Memory Leak and eventual ORA-04030.

Note: Tested in Oracle 19.17

Update (2023-04-15): With the reproducible test code, Oracle delivered fix:
     Patch 35166750: PLSQL JSON DOM API INTERNAL ERROR, QJSNPLSDESTROY CALLED TOO OFTEN AND NOT IMPLEMENTED


1. Test Setup


We create a helper procedure to report PGA usage, one procedure to test JSON, one procedure to test scalar type VARCHAR2.

create or replace procedure rpt_pga(p_name varchar) as
    l_v$process_mem            varchar2(4000);
    l_v$process_memory_mem     varchar2(4000);
    l_used_mem_mb              number;
    p_sid                      number; --     := sys.dbms_support.mysid;
  begin
   select sid into p_sid from v$mystat where rownum=1;
   select round(pga_used_mem/1024/1024),
          'Used/Alloc/Freeable/Max >>> '||
           round(pga_used_mem/1024/1024)    ||'/'||round(pga_alloc_mem/1024/1024)||'/'||
             round(pga_freeable_mem/1024/1024)||'/'||round(pga_max_mem/1024/1024)
       into l_used_mem_mb, l_v$process_mem
       from v$process where addr = (select paddr from v$session where sid = p_sid);
      
    select 'Category(Alloc/Used/Max) >>> '||
             listagg(Category||'('||round(allocated/1024/1024)||'/'||
                     round(used/1024/1024)||'/'||round(max_allocated/1024/1024)||') > ')
     within group (order by Category desc) name_usage_list
       into l_v$process_memory_mem
       from v$process_memory
       where pid = (select pid from v$process
                     where addr = (select paddr from v$session where sid = p_sid));
  
    dbms_output.put_line(rpad(p_name, 15, '-')||'PGA Used(MB): '||l_used_mem_mb);
    dbms_output.put_line(rpad(chr(32), 18, chr(32))||rpad(l_v$process_mem, 50));
    dbms_output.put_line(rpad(chr(32), 18, chr(32))||l_v$process_memory_mem);
end;
/

--test_json (Json)
create or replace procedure test_json(p_run number, p_loop number) as
  type t_tab is table of json_object_t index by pls_integer;
  l_tab t_tab;
begin
  for i in 1..p_run loop
    dbms_output.put_line(rpad('*', 30, '*')||' RUN-'||i||rpad('*', 30, '*'));
	  rpt_pga('Init');
	  for i in 1..p_loop loop
	    l_tab(i) := new json_object_t('{ "abcd":12345 }');
	  end loop;
	  rpt_pga('After Create');
	  l_tab.delete;
	  --l_tab := new t_tab();
	  dbms_session.free_unused_user_memory;
	  rpt_pga('Aftre Free');
  end loop;
  dbms_output.put_line('');
end;
/

--test_scalar (varchar2)
create or replace procedure test_scalar(p_run number, p_loop number) as
  type t_tab is table of varchar2(32000) index by pls_integer;
  l_tab t_tab;
begin
  for i in 1..p_run loop
    dbms_output.put_line(rpad('*', 30, '*')||' RUN-'||i||rpad('*', 30, '*'));
	  rpt_pga('Init');
	  for i in 1..p_loop loop
	    l_tab(i) := '{ "abcd":'|| rpad('12345', 30000, '-') ||'}';
	  end loop;
	  rpt_pga('After Create');
	  l_tab.delete;
	  --l_tab := new t_tab();
	  dbms_session.free_unused_user_memory;
	  rpt_pga('Aftre Free');
	  dbms_output.put_line('');
  end loop;
end;
/


2. Test Run


Open two Sqplus sessions, run following two tests:

  In Session-1: exec test_json(3, 10000);
  In Session-2: exec test_scalar(3, 10000);
Here the output of test_json:

SQL > exec test_json(3, 10000);

****************************** RUN-1******************************
Init-----------PGA Used(MB): 7
                  Used/Alloc/Freeable/Max >>> 7/8/1/10
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(3/3/3) > Other(4//4) > Freeable(1/0/) >
After Create---PGA Used(MB): 1253
                  Used/Alloc/Freeable/Max >>> 1253/1267/0/1267
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(4/4/4) > Other(1263//1263) >
Aftre Free-----PGA Used(MB): 1252
                  Used/Alloc/Freeable/Max >>> 1252/1267/1/1267
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(3/2/4) > Other(1263//1263) > Freeable(1/0/) >
                  
****************************** RUN-2******************************
Init-----------PGA Used(MB): 1252
                  Used/Alloc/Freeable/Max >>> 1252/1267/1/1267
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(3/2/4) > Other(1263//1263) > Freeable(1/0/) >
After Create---PGA Used(MB): 2501
                  Used/Alloc/Freeable/Max >>> 2501/2531/0/2531
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(4/4/4) > Other(2527//2527) >
Aftre Free-----PGA Used(MB): 2500
                  Used/Alloc/Freeable/Max >>> 2500/2531/1/2531
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(2/2/4) > Other(2528//2528) > Freeable(1/0/) >
                  
****************************** RUN-3******************************
Init-----------PGA Used(MB): 2500
                  Used/Alloc/Freeable/Max >>> 2500/2531/1/2531
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(2/2/4) > Other(2528//2528) > Freeable(1/0/) >
After Create---PGA Used(MB): 3749
                  Used/Alloc/Freeable/Max >>> 3749/3779/0/3779
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(4/4/4) > Other(3775//3775) >
Aftre Free-----PGA Used(MB): 3748
                  Used/Alloc/Freeable/Max >>> 3748/3779/1/3779
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(2/2/4) > Other(3776//3776) > Freeable(1/0/) >
The output showed that memory is NOT freed, PGA continuously increasing: 7 > 1252 > 2500 > 3748 (MB) after each RUN
when the used nested table is deleted and dbms_session.free_unused_user_memory is called.
The PGA memory is all allocated in Category "Other".

Here the output of test_scalar:

SQL > exec test_scalar(3, 10000);

****************************** RUN-1******************************
Init-----------PGA Used(MB): 7
                  Used/Alloc/Freeable/Max >>> 7/8/1/10
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(3/3/3) > Other(5//5) > Freeable(1/0/) >
After Create---PGA Used(MB): 320
                  Used/Alloc/Freeable/Max >>> 320/322/0/322
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(316/315/316) > Other(6//6) >
Aftre Free-----PGA Used(MB): 7
                  Used/Alloc/Freeable/Max >>> 7/322/315/322
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(3/2/316) > Other(4//4) > Freeable(315/0/) >

****************************** RUN-2******************************
Init-----------PGA Used(MB): 7
                  Used/Alloc/Freeable/Max >>> 7/322/315/322
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(3/2/316) > Other(4//4) > Freeable(315/0/) >
After Create---PGA Used(MB): 320
                  Used/Alloc/Freeable/Max >>> 320/322/1/322
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(316/314/316) > Other(5//5) > Freeable(1/0/) >
Aftre Free-----PGA Used(MB): 7
                  Used/Alloc/Freeable/Max >>> 7/322/315/322
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(2/2/316) > Other(5//5) > Freeable(315/0/) >

****************************** RUN-3******************************
Init-----------PGA Used(MB): 7
                  Used/Alloc/Freeable/Max >>> 7/322/315/322
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(2/2/316) > Other(5//5) > Freeable(315/0/) >
After Create---PGA Used(MB): 320
                  Used/Alloc/Freeable/Max >>> 320/322/1/322
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(315/314/316) > Other(6//6) > Freeable(1/0/) >
Aftre Free-----PGA Used(MB): 7
                  Used/Alloc/Freeable/Max >>> 7/322/315/322
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(2/2/316) > Other(5//5) > Freeable(315/0/) >
The output showed that memory is freed after each RUN: 7 > 320 > 7 (MB)
when the used nested table is deleted and dbms_session.free_unused_user_memory is called.


3. ORA-04030 Test and Incident File


The above test_json showed that 3 RUNs took 3748 MB, we can make a test with 30 RUNs to check if it reaches 32 GB PGA limit and hence:
      ORA-04030: out of process memory

The test hit ORA-04030 in RUN 27.

SQL > exec test_json(30, 10000);

****************************** RUN-1******************************
Init-----------PGA Used(MB): 7
                  Used/Alloc/Freeable/Max >>> 7/8/0/10
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(3/3/3) > Other(4//4) > Freeable(0/0/) >
After Create---PGA Used(MB): 1253
                  Used/Alloc/Freeable/Max >>> 1253/1267/0/1267
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(4/4/4) > Other(1263//1263) >
Aftre Free-----PGA Used(MB): 1252
                  Used/Alloc/Freeable/Max >>> 1252/1267/1/1267
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(3/2/4) > Other(1263//1263) > Freeable(1/0/) >
****************************** RUN-2******************************
Init-----------PGA Used(MB): 1252
                  Used/Alloc/Freeable/Max >>> 1252/1267/1/1267
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(3/2/4) > Other(1263//1263) > Freeable(1/0/) >
After Create---PGA Used(MB): 2501
                  Used/Alloc/Freeable/Max >>> 2501/2531/0/2531
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(4/4/4) > Other(2527//2527) >
Aftre Free-----PGA Used(MB): 2500
                  Used/Alloc/Freeable/Max >>> 2500/2531/1/2531
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(2/2/4) > Other(2528//2528) > Freeable(1/0/) >                 
.....

****************************** RUN-26******************************
Init-----------PGA Used(MB): 31044
                  Used/Alloc/Freeable/Max >>> 31044/31075/1/31075
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(2/2/4) > Other(31071//31071) > Freeable(1/0/) >
After Create---PGA Used(MB): 32293
                  Used/Alloc/Freeable/Max >>> 32293/32323/0/32323
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(4/4/4) > Other(32319//32319) >
Aftre Free-----PGA Used(MB): 32292
                  Used/Alloc/Freeable/Max >>> 32292/32323/1/32323
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(2/2/4) > Other(32319//32319) > Freeable(1/0/) >
****************************** RUN-27******************************
Init-----------PGA Used(MB): 32292
                  Used/Alloc/Freeable/Max >>> 32292/32323/1/32323
                  Category(Alloc/Used/Max) >>> SQL(0/0/6) > PL/SQL(2/2/4) > Other(32319//32319) > Freeable(1/0/) >

BEGIN test_json(30, 10000); END;
	ERROR at line 1:
	ORA-40441: JSON syntax error
	ORA-06512: at "SYS.JDOM_T", line 4
	ORA-06512: at "SYS.JSON_OBJECT_T", line 28
	ORA-06512: at "TEST_JSON", line 9
	ORA-06512: at line 1

Elapsed: 00:00:30.71
The incident file shows that the majority of PGA memory is allocated to "qjsnplsAllocMem" (97% or 31 GB of total 32 GB).

incident/incdir_51062/testdb_ora_30363_i51062.trc

ORA-04030: out of process memory when trying to allocate 65584 bytes (qjsngGetSessio,qjsnplsAllocMem)

=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------
*** 2023-03-07T09:36:56.901600+01:00
97%   31 GB, 3414723 chunks: "qjsnplsAllocMem           "  
         qjsngGetSessio  ds=0x7fb2ecb36af8  dsprt=0x7fb2ec627228
 3%  876 MB, 525337 chunks: "free memory               "  
         qjsnCrPlsHeap   ds=0x7fab015e4ea8  dsprt=0x7fb2ecb36af8
 0%  106 MB, 262669 chunks: "qjsnCrPlsHeap             "  
         qjsngGetSessio  ds=0x7fb2ecb36af8  dsprt=0x7fb2ec627228
 0%   36 MB, 525338 chunks: "qjsnCrPls_durArr          "  
         qjsnCrPlsHeap   ds=0x7fab015e4ea8  dsprt=0x7fb2ecb36af8
 0%   30 MB,  18 chunks: "free memory               "  
         top uga heap    ds=0x7fb2f2197e00  dsprt=(nil)
       
=========================================
REAL-FREE ALLOCATOR DUMP FOR THIS PROCESS
-----------------------------------------
Dump of Real-Free Memory Allocator Heap [0x7fb2ed325000]
mag=0xfefe0001 flg=0x5000007 fds=0x0 blksz=65536
blkdstbl=0x7fb2ed325018, iniblk=524288 maxblk=524288 numsegs=321
In-use num=1464 siz=34226634752, Freeable num=4 siz=1507328, Free num=3 siz=13041664
Client alloc 34228142080 Client freeable 1507328
Internal RfPga 33425920K RgPga 1275K

================================     
----- Current SQL Statement for this session (sql_id=2rs9n85h4rb90) -----
BEGIN test_json(30, 10000); END;
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0x98f121e0         4  type body SYS.JDOM_T.PARSE
0x98f1c368        28  type body SYS.JSON_OBJECT_T.JSON_OBJECT_T
0x9adad518         9  procedure TEST_JSON
0x98ef1180         1  anonymous block
     
--------------------- Binary Stack Dump ---------------------    
FRAME [8] (kghnospc()+2639 -> dbgeEndDDEInvocationImpl())    
FRAME [9] (kghalf()+2350 -> kghnospc())    
FRAME [10] (qjsngAllocMem()+545 -> kghalf())    
FRAME [11] (LpxMemAlloc()+1669 -> qjsngAllocMem())    
FRAME [12] (jzn0DomPutName()+2868 -> LpxMemAlloc())    
FRAME [13] (jzn0DomStoreFieldName()+129 -> jzn0DomPutName())    
FRAME [14] (jzn0DomLoadFromInputEventSrc()+2775 -> jzn0DomStoreFieldName())    
FRAME [15] (qjsnPlsCreateFromStr()+332 -> jzn0DomLoadFromInputEventSrc())    
FRAME [16] (qjsnplsParse()+183 -> qjsnPlsCreateFromStr())    
FRAME [17] (spefcpfa()+204 -> qjsnplsParse())    
FRAME [18] (spefmccallstd()+551 -> spefcpfa())    
FRAME [19] (peftrusted()+139 -> spefmccallstd())    
FRAME [20] (psdexsp()+285 -> peftrusted())    
FRAME [21] (rpiswu2()+2004 -> psdexsp())    
FRAME [22] (kxe_push_env_internal_pp_()+362 -> rpiswu2())    
FRAME [23] (kkx_push_env_for_ICD_for_new_session()+149 -> kxe_push_env_internal_pp_())    
FRAME [24] (psdextp()+387 -> kkx_push_env_for_ICD_for_new_session())    
FRAME [25] (pefccal()+663 -> psdextp())    
FRAME [26] (pefcal()+223 -> pefccal())    
FRAME [27] (pevm_FCAL()+171 -> pefcal())    
FRAME [28] (pfrinstr_FCAL()+62 -> pevm_FCAL())    
FRAME [29] (pfrrun_no_tool()+60 -> pfrinstr_FCAL())    
FRAME [30] (pfrrun()+902 -> pfrrun_no_tool())    
FRAME [31] (plsql_run()+747 -> pfrrun())             

Sunday, March 5, 2023

One Test of ORA-00600: [KGL-heap-size-exceeded] With AQ Subscriber

In this Blog, we will make tests with dbms_aqadm.add_subscriber / remove_subscriber to show:
     ORA-00600: internal error code, arguments: [KGL-heap-size-exceeded], [0x08F4BEDC8], [0], [524288176]

Note: Tested in Oracle 19.17


1. Test Setup


AQ Subscriber setup is based on Oracle Advanced Queuing by Example:

exec dbms_aqadm.stop_queue (queue_name         => 'msg_queue_multiple');
exec dbms_aqadm.drop_queue (queue_name         => 'msg_queue_multiple');
-- if failed, "startup restrict", re-run as sysdba
exec dbms_aqadm.drop_queue_table (queue_table  => 'MultiConsumerMsgs_qtab', force=> true);
drop type message_typ force;

create or replace noneditionable type message_typ as object (
	subject     varchar2(30),
	text        varchar2(256));
/   

exec dbms_aqadm.create_queue_table (queue_table => 'MultiConsumerMsgs_qtab', multiple_consumers => true, queue_payload_type => 'Message_typ');
exec dbms_aqadm.create_queue (queue_name => 'msg_queue_multiple', queue_table => 'MultiConsumerMsgs_qtab');
exec dbms_aqadm.start_queue (queue_name => 'msg_queue_multiple');


2. Test add_subscriber / remove_subscriber


First we create a procedure to show memory increasing of queue object in shared pool and library cache when repeatedly adding and removing multiple subscribers:

create or replace procedure lb_mem_test_add_remove(p_loop_cnt number) as
   subscriber    sys.aq$_agent;
   l_cnt         number;
   l_mem_KB      number;
   l_output      varchar2(1000);
begin    
  -- cleanup if already existed
	for idx in (select consumer_name from dba_queue_subscribers a where a.queue_name = 'MSG_QUEUE_MULTIPLE' and consumer_name like 'SUBSCB%') loop
	  subscriber := sys.aq$_agent(idx.consumer_name, null, null);
	  dbms_aqadm.remove_subscriber('MSG_QUEUE_MULTIPLE', subscriber);
	end loop;
	  
  for i in 1 .. p_loop_cnt loop
    dbms_output.put_line('--------------------RUN = '||i||' --------------------');
	  
	  -- maximum 1024:  ORA-24067: exceeded maximum number of subscribers for queue MSG_QUEUE_MULTIPLE
	  for j in 1..1020 loop  
		  subscriber := sys.aq$_agent('SUBSCB_'||j, null, null);
		  dbms_aqadm.add_subscriber(queue_name => 'msg_queue_multiple', subscriber => subscriber);
		end loop;

	  select count(*) into l_cnt from DBA_QUEUE_SUBSCRIBERS a where a.queue_name = 'MSG_QUEUE_MULTIPLE';
	  select round(sharable_mem/1024) into l_mem_KB from  v$db_object_cache v where name='MSG_QUEUE_MULTIPLE';
	  
	  dbms_output.put_line('After Add: Subscriber Count = '||l_cnt ||', Library Cache Mem(KB) = '||l_mem_KB);
	  
	  for idx in (select consumer_name from dba_queue_subscribers a where a.queue_name = 'MSG_QUEUE_MULTIPLE' and consumer_name like 'SUBSCB%') loop
	    subscriber := sys.aq$_agent(idx.consumer_name, null, null);
	    dbms_aqadm.remove_subscriber(queue_name => 'msg_queue_multiple', subscriber => subscriber);
	  end loop;
	  
	  select count(*) into l_cnt from DBA_QUEUE_SUBSCRIBERS a where a.queue_name = 'MSG_QUEUE_MULTIPLE';
	  select round(sharable_mem/1024) into l_mem_KB from  v$db_object_cache v where name='MSG_QUEUE_MULTIPLE';
	  
	  dbms_output.put_line('After Remove: Subscriber Count = '||l_cnt ||', Library Cache Mem(KB) = '||l_mem_KB);
  end loop;
end;
/
Now we run following test:

alter system flush shared_pool; 

col name for a20
select hash_value, name, sharable_mem, round(sharable_mem/1024) KB from  v$db_object_cache where name='MSG_QUEUE_MULTIPLE';
select ksmchcls, sum(ksmchsiz), round(sum(ksmchsiz)/1024/1024) mb, count(*) from  sys.X_ksmsp v where ksmchcom = 'KGLH0^bd46458' group by ksmchcls;
select v.*, round(bytes/1024/1024) mb from v$sgastat v where pool = 'shared pool' and name in ('KGLH0', 'free memory');

exec lb_mem_test_add_remove(3);

select v.*, round(bytes/1024/1024) mb from v$sgastat v where pool = 'shared pool' and name in ('KGLH0', 'free memory');
select ksmchcls, sum(ksmchsiz), round(sum(ksmchsiz)/1024/1024) mb, count(*) from  sys.X_ksmsp v where ksmchcom = 'KGLH0^bd46458' group by ksmchcls;
select hash_value, name, sharable_mem, round(sharable_mem/1024) KB from v$db_object_cache where name='MSG_QUEUE_MULTIPLE';
Here the output

12:21:00 SQL > select hash_value, name, sharable_mem, round(sharable_mem/1024) KB from v$db_object_cache where name='MSG_QUEUE_MULTIPLE';
	HASH_VALUE NAME                 SHARABLE_MEM         KB
	---------- -------------------- ------------ ----------
	 198468696 MSG_QUEUE_MULTIPLE           4032          4

12:21:00 SQL > select ksmchcls, sum(ksmchsiz), round(sum(ksmchsiz)/1024/1024) mb, count(*) from sys.X_ksmsp v 
                where ksmchcom = 'KGLH0^bd46458' group by ksmchcls;
	KSMCHCLS SUM(KSMCHSIZ)         MB   COUNT(*)
	-------- ------------- ---------- ----------
	recr              4096          0          1

12:21:00 SQL > select v.*, round(bytes/1024/1024) mb from v$sgastat v where pool = 'shared pool' and name in ('KGLH0', 'free memory');
	POOL           NAME                      BYTES     CON_ID         MB
	-------------- -------------------- ---------- ---------- ----------
	shared pool    free memory           857211040          0        818
	shared pool    KGLH0                  77214832          0         74

12:21:00 SQL > exec lb_mem_test_add_remove(3);
	--------------------RUN = 1 --------------------
	After Add: Subscriber Count = 1020, Library Cache Mem(KB) = 664
	After Remove: Subscriber Count = 0, Library Cache Mem(KB) = 406
	--------------------RUN = 2 --------------------
	After Add: Subscriber Count = 1020, Library Cache Mem(KB) = 1090
	After Remove: Subscriber Count = 0, Library Cache Mem(KB) = 807
	--------------------RUN = 3 --------------------
	After Add: Subscriber Count = 1020, Library Cache Mem(KB) = 1495
	After Remove: Subscriber Count = 0, Library Cache Mem(KB) = 1213

Elapsed: 00:00:30.93

12:21:31 SQL > select v.*, round(bytes/1024/1024) mb from v$sgastat v where pool = 'shared pool' and name in ('KGLH0', 'free memory');
	POOL           NAME                      BYTES     CON_ID         MB
	-------------- -------------------- ---------- ---------- ----------
	shared pool    free memory           852363192          0        813
	shared pool    KGLH0                  80141904          0         76

12:21:31 SQL > select ksmchcls, sum(ksmchsiz), round(sum(ksmchsiz)/1024/1024) mb, count(*) from sys.X_ksmsp v 
                where ksmchcom = 'KGLH0^bd46458' group by ksmchcls;
	KSMCHCLS SUM(KSMCHSIZ)         MB   COUNT(*)
	-------- ------------- ---------- ----------
	freeabl        1740800          2        425
	recr              4096          0          1

12:21:31 SQL > select hash_value, name, sharable_mem, round(sharable_mem/1024) KB from v$db_object_cache where name='MSG_QUEUE_MULTIPLE';
	HASH_VALUE NAME                 SHARABLE_MEM         KB
	---------- -------------------- ------------ ----------
	 198468696 MSG_QUEUE_MULTIPLE        1241960       1213
The output shows that after 3 RUNs, Library Cache Mem(KB) are 406, 807 and 1213 respectively, that means each RUN has about 400 KB memory not released.
v$sgastat showed that they are located in KGLH0 component of shared pool.
xksmsp listed that them as 425 "freeabl" chunks, each of time is 4096 bytes (total: 1740800).

(Note: MSG_QUEUE_MULTIPLE v$db_object_cache.hash_value = 198468696 = 0xbd46458)


3. ORA-00600: [KGL-heap-size-exceeded] Test


In the following procedure, we repeatedly add a set of the same subscribers (maximum 1024), and it will hit ORA-24034.

create or replace procedure lb_mem_test_add_error(p_loop_cnt number) as
   subscriber    sys.aq$_agent;
   l_output      varchar2(1000);
begin
  for i in 1 .. p_loop_cnt loop
    dbms_output.put_line('-------------------- RUN = '||i||' --------------------');
	  for j in 1..1020 loop  
	    begin
      	-- add same subscriber repeatedly to trigger error
      	-- Subscriber existed: ORA-24034: application SUBSCB_1020 is already a subscriber for queue MSG_QUEUE_MULTIPLE
		    subscriber := sys.aq$_agent('SUBSCB_'||j, null, null);
		    dbms_aqadm.add_subscriber(queue_name => 'msg_queue_multiple', subscriber => subscriber);
      	exception when others then
      	  l_output := 'Subscriber existed: '||SQLERRM;
      end;
		end loop;
		dbms_output.put_line(l_output);
  end loop;
end;
/
Run the test:

alter system flush shared_pool; 

col name for a20
select hash_value, name, sharable_mem, round(sharable_mem/1024) KB from  v$db_object_cache where name='MSG_QUEUE_MULTIPLE';
select ksmchcls, sum(ksmchsiz), round(sum(ksmchsiz)/1024/1024) mb, count(*) from  sys.X_ksmsp v where ksmchcom = 'KGLH0^bd46458' group by ksmchcls;
select v.*, round(bytes/1024/1024) mb from v$sgastat v where pool = 'shared pool' and name in ('KGLH0', 'free memory');

exec lb_mem_test_add_error(100);

select v.*, round(bytes/1024/1024) mb from v$sgastat v where pool = 'shared pool' and name in ('KGLH0', 'free memory');
select ksmchcls, sum(ksmchsiz), round(sum(ksmchsiz)/1024/1024) mb, count(*) from  sys.X_ksmsp v where ksmchcom = 'KGLH0^bd46458' group by ksmchcls;
select hash_value, name, sharable_mem, round(sharable_mem/1024) KB from v$db_object_cache where name='MSG_QUEUE_MULTIPLE';
Here the output:

12:24:41 SQL > select hash_value, name, sharable_mem, round(sharable_mem/1024) KB from  v$db_object_cache where name='MSG_QUEUE_MULTIPLE';
	HASH_VALUE NAME                 SHARABLE_MEM         KB
	---------- -------------------- ------------ ----------
	 198468696 MSG_QUEUE_MULTIPLE        1241960       1213

12:24:41 SQL > select ksmchcls, sum(ksmchsiz), round(sum(ksmchsiz)/1024/1024) mb, count(*) from sys.X_ksmsp v 
                where ksmchcom = 'KGLH0^bd46458' group by ksmchcls;
	KSMCHCLS SUM(KSMCHSIZ)         MB   COUNT(*)
	-------- ------------- ---------- ----------
	freeabl        1740800          2        425
	recr              4096          0          1

12:24:41 SQL > select v.*, round(bytes/1024/1024) mb from v$sgastat v where pool = 'shared pool' and name in ('KGLH0', 'free memory');
	POOL           NAME                      BYTES     CON_ID         MB
	-------------- -------------------- ---------- ---------- ----------
	shared pool    free memory           852037064          0        813
	shared pool    KGLH0                  80219104          0         77

12:24:42 SQL > exec lb_mem_test_add_error(100);
-------------------- RUN = 1 --------------------
-------------------- RUN = 2 --------------------
BEGIN lb_mem_test_add_error(100); END;
	*
	ERROR at line 1:
	ORA-00600: internal error code, arguments: [KGL-heap-size-exceeded], [0x08F4BEDC8], [0], [524288176], [], [], [], [], [], [], [], []
	ORA-06512: at "SYS.DBMS_AQADM_SYSCALLS", line 926
	ORA-06512: at "SYS.DBMS_AQADM_SYS", line 9809
	ORA-06512: at "SYS.DBMS_AQADM_SYS", line 9527
	ORA-06512: at "SYS.DBMS_AQADM", line 881
	ORA-06512: at "LB_MEM_TEST_ADD_ERROR", line 12
	ORA-06512: at line 1

	Elapsed: 00:00:22.12

12:25:04 SQL > select v.*, round(bytes/1024/1024) mb from v$sgastat v where pool = 'shared pool' and name in ('KGLH0', 'free memory');
	POOL           NAME                      BYTES     CON_ID         MB
	-------------- -------------------- ---------- ---------- ----------
	shared pool    free memory           326751160          0        312
	shared pool    KGLH0                 605291072          0        577

12:25:04 SQL > select ksmchcls, sum(ksmchsiz), round(sum(ksmchsiz)/1024/1024) mb, count(*) from sys.X_ksmsp v 
                where ksmchcom = 'KGLH0^bd46458' group by ksmchcls;
	KSMCHCLS SUM(KSMCHSIZ)         MB   COUNT(*)
	-------- ------------- ---------- ----------
	freeabl      529829888        505     129353
	recr              4096          0          1

12:25:04 SQL > select hash_value, name, sharable_mem, round(sharable_mem/1024) KB from v$db_object_cache where name='MSG_QUEUE_MULTIPLE';
	HASH_VALUE NAME                 SHARABLE_MEM         KB
	---------- -------------------- ------------ ----------
	 198468696 MSG_QUEUE_MULTIPLE              0          0
In the second RUN hit:

   ORA-00600: internal error code, arguments: [KGL-heap-size-exceeded],  [0x08F4BEDC8], [0], [524288176],

(The default of "_kgl_large_heap_assert_threshold" and "_kgl_large_heap_warning_threshold"  are 524288000 (500MB) since 12.1.0.2)
v$sgastat showed that KGLH0 increased 500 MB (577 - 77),
xksmsp listed 129353 "freeabl" chunks, each 4096 bytes, total 529829888 bytes
("freeabl" chunks increased from 425 to 129353. Memory increased from 2 MB to 505 MB).
However v$db_object_cache showed that sharable_mem is 0.

The user session incident file looks like:

incident/incdir_11641/testdb_ora_22948_i11641.trc

Unix process pid: 22948, image: oracle@testdb
*** SESSION ID:(191.4859) 2023-03-03T12:25:02.690695+01:00
*** SERVICE NAME:(SYS$USERS) 2023-03-03T12:25:02.690704+01:00
 
ORA-00600: internal error code, arguments: [KGL-heap-size-exceeded], [0x08F4BEDC8], [0], [524288176]

HEAP DUMP heap name="KGLH0^bd46458"  desc=0x8f436300
 dsx heap size=524659800
Summary of 2425232 chunks using 524655000 bytes in 129354 extents
from EXTENT 0 to EXTENT 129353 between 0x6b4b9000 and 0x8f436298
  freeable       sz= 248128024  chunks= 607686 "kwqiia         " 
                                              sz range 408 (597970) to 432 (7140) 
  freeable       sz= 184851000  chunks= 452647 "kwqicforqa: kwq" 
                                              sz range 408 (445507) to 432 (7119) 
  freeable       sz= 40152424   chunks= 151980 "kwqiie         " 
                                              sz range 264 (151196) to 304 (619) 
  freeable       sz= 25689816   chunks= 607686 "kwqiianame     " 
                                              sz range 40 (551031) to 80 (243) 
Total heap size    =524659800

LibraryHandle:  Address=0x8f4bedc8 Hash=bd46458 LockMode=N PinMode=S LoadLockMode=X Status=VALD 
  ObjectName:  Name=MSG_QUEUE_MULTIPLE   
    FullHashValue=7f06776610a79cd3e76b3b110bd46458 Namespace=QUEUE(10) Type=QUEUE(24)
  LibraryObject:  Address=0x8f435388 HeapMask=0000-0000-0000-0000 
    DataBlocks:  
      Block:  #='0' name=KGLH0^bd46458 pins=0 Change=NONE   
        FreedLocation=0 Alloc=512000.171875 Size=512002.304688

----- Current SQL Statement for this session (sql_id=bpy2c9r6bmkgp) -----
BEGIN lb_mem_test_add_error(100); END;
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0xa38a1068       926  package body SYS.DBMS_AQADM_SYSCALLS.KWQA_3GL_LOCKQUEUE
0x9fc8f450      9809  package body SYS.DBMS_AQADM_SYS.ADD_SUBSCRIBER_11G
0x9fc8f450      9527  package body SYS.DBMS_AQADM_SYS.ADD_SUBSCRIBER
0x9eba1040       881  package body SYS.DBMS_AQADM.ADD_SUBSCRIBER
0x9ea1a058        12  procedure LB_MEM_TEST_ADD_ERROR
0x8ea8f5a0         1  anonymous block

========== FRAME [8] (kglLargeHeapWarning()+1417 -> dbgeEndDDEInvocationImpl()) ==========
========== FRAME [9] (kglHeapAllocCbk()+418 -> kglLargeHeapWarning()) ==========
========== FRAME [10] (kghalo()+1736 -> kglHeapAllocCbk()) ==========
========== FRAME [11] (kwqicforqa()+363 -> kghalo()) ==========
========== FRAME [12] (kwqicaqa()+414 -> kwqicforqa()) ==========
========== FRAME [13] (kwqicdsubload()+6918 -> kwqicaqa()) ==========
========== FRAME [14] (kwqiclode()+5384 -> kwqicdsubload()) ==========
========== FRAME [15] (kwqiclod()+249 -> kwqiclode()) ==========
========== FRAME [16] (kqlobjlod()+1681 -> kwqiclod()) ==========
========== FRAME [17] (kqllod_new()+588 -> kqlobjlod()) ==========
========== FRAME [18] (kqlCallback()+67 -> kqllod_new()) ==========
========== FRAME [19] (kqllod()+1466 -> kqlCallback()) ==========
========== FRAME [20] (kglobld()+1051 -> kqllod()) ==========
========== FRAME [21] (kglobpn()+1649 -> kglobld()) ==========
========== FRAME [22] (kglpim()+410 -> kglobpn()) ==========
========== FRAME [23] (kglpin()+1677 -> kglpim()) ==========
========== FRAME [24] (kglgob()+472 -> kglpin()) ==========
========== FRAME [25] (kwqicgob()+381 -> kglgob()) ==========
========== FRAME [26] (kwqalqu()+2594 -> kwqicgob()) ==========
========== FRAME [27] (spefcmpa()+286 -> kwqalqu()) ==========
========== FRAME [28] (spefmccallstd()+251 -> spefcmpa()) ==========
========== FRAME [29] (peftrusted()+139 -> spefmccallstd()) ==========
========== FRAME [30] (psdexsp()+285 -> peftrusted()) ==========
========== FRAME [31] (rpiswu2()+2004 -> psdexsp()) ==========
========== FRAME [32] (kxe_push_env_internal_pp_()+362 -> rpiswu2()) ==========
========== FRAME [33] (kkx_push_env_for_ICD_for_new_session()+149 -> kxe_push_env_internal_pp_()) ==========
========== FRAME [34] (psdextp()+387 -> kkx_push_env_for_ICD_for_new_session()) ==========
========== FRAME [35] (pefccal()+663 -> psdextp()) ==========
========== FRAME [36] (pefcal()+223 -> pefccal()) ==========
========== FRAME [37] (pevm_FCAL()+171 -> pefcal()) ==========
========== FRAME [38] (pfrinstr_FCAL()+62 -> pevm_FCAL()) ==========
========== FRAME [39] (pfrrun_no_tool()+60 -> pfrinstr_FCAL()) ==========
========== FRAME [40] (pfrrun()+902 -> pfrrun_no_tool()) ==========
========== FRAME [41] (plsql_run()+747 -> pfrrun()) ==========
If we open a new Sqlplus session, and run a small test. It also hit again ORA-00600: [KGL-heap-size-exceeded]:

SQL > exec lb_mem_test_add_error(1);
-------------------- RUN = 1 --------------------
BEGIN lb_mem_test_add_error(1); END;
*
ERROR at line 1:
ORA-00600: internal error code, arguments: [KGL-heap-size-exceeded], [0x08F4BEDC8], [0], [524291360]
ORA-06512: at "SYS.DBMS_AQADM_SYSCALLS", line 926
ORA-06512: at "SYS.DBMS_AQADM_SYS", line 9809
ORA-06512: at "SYS.DBMS_AQADM_SYS", line 9527
ORA-06512: at "SYS.DBMS_AQADM", line 881
ORA-06512: at "LB_MEM_TEST_ADD_ERROR", line 12
ORA-06512: at line 1
At the same, we observed that one Oracle background Job session (Job: J000, QMON worker process) hit ORA-07445 and ORA-00600 in its incident file:

incident/incdir_11682/testdb_j000_23343_i11682.trc

Unix process pid: 23343, image: oracle@testdb (J000)
*** SESSION ID:(23.60276) 2023-03-03T12:30:10.177169+01:00
*** SERVICE NAME:(SYS$USERS) 2023-03-03T12:30:10.177177+01:00
*** MODULE NAME:(DBMS_SCHEDULER) 2023-03-03T12:30:10.177181+01:00
*** ACTION NAME:(KWQICPOSTMSGDEL_1_1677843007) 2023-03-03T12:30:10.177185+01:00
 
ORA-07445: exception encountered: core dump [__strnlen_sse2()+33] [SIGSEGV] [ADDR:0x0] [PC:0x7F28A91DBF91] [Address not mapped to object] []
ORA-00600: internal error code, arguments: [KGL-heap-size-exceeded], [0x08F4BEDC8], [0], [524289768], [], [], [], [], [], [], [], []

========= Dump for incident 11682 (ORA 7445 [__strnlen_sse2]) ========
Exception [type: SIGSEGV, Address not mapped to object] [ADDR:0x0] [PC:0x7F28A91DBF91, __strnlen_sse2()+33] [flags: 0x0, count: 1]
Registers:
%rax: 0x000000000000006c %rbx: 0x0000000000000000 %rcx: 0x0000000000000001
%rdx: 0x00007fff30753228 %rdi: 0x0000000000000000 %rsi: 0x000000000000006c
%rsp: 0x00007fff30751998 %rbp: 0x00007fff30751f90  %r8: 0x0000000000000001
 %r9: 0x0000000000000010 %r10: 0x00000000fffff000 %r11: 0x0000000000ddf0a6
%r12: 0x0000000000000001 %r13: 0x00007fff307531c0 %r14: 0x0000000013935c74
%r15: 0x00007fff30751fa0 %rip: 0x00007f28a91dbf91 %efl: 0x0000000000010246
  __strnlen_sse2()+15 (0x7f28a91dbf7f) mov %rdi,%r8
  __strnlen_sse2()+18 (0x7f28a91dbf82) mov $0x10,%r9
  __strnlen_sse2()+25 (0x7f28a91dbf89) and $-16,%rdi
  __strnlen_sse2()+29 (0x7f28a91dbf8d) movdqa %xmm2,%xmm1
> __strnlen_sse2()+33 (0x7f28a91dbf91) pcmpeqb (%rdi),%xmm2
  __strnlen_sse2()+37 (0x7f28a91dbf95) or $-1,%r10d
  __strnlen_sse2()+41 (0x7f28a91dbf99) sub %rdi,%rcx
  __strnlen_sse2()+44 (0x7f28a91dbf9c) shll %cl,%r10d
  __strnlen_sse2()+47 (0x7f28a91dbf9f) sub %rcx,%r9

----- Current SQL Statement for this session (sql_id=d66sha6y2v3g1) -----
call DBMS_AQADM_SYS.REMOVE_ORPHMSGS ( :0 )
----- PL/SQL Stack -----
----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
0xa38a1068       202  package body SYS.DBMS_AQADM_SYSCALLS.KWQA_3GL_PURGEREMSUBLIST
0x9fc8f450     10843  package body SYS.DBMS_AQADM_SYS.REMOVE_ORPHMSGS_INT
0x9fc8f450     10826  package body SYS.DBMS_AQADM_SYS.REMOVE_ORPHMSGS_NR
0x9fc8f450     10934  package body SYS.DBMS_AQADM_SYS.REMOVE_ORPHMSGS
0x8b1c3098         1  anonymous block
There are certain descriptions of this behaviour in Oracle MOS:

Why do automatically generated KWQICPOSTMSGDEL_* jobs invoke the procedure DBMS_AQADM_SYS.REMOVE_ORPHMSGS? (Doc ID 1115495.1)
  procedure DBMS_AQADM_SYS.REMOVE_ORPHMSGS
	  This job is scheduled by a QMON worker process, to check for and if necessary, 
	  remove potential orphan messages after dropping a propagation, 
	  so there are no orphan messages left for the subscriber. 
	 
MOS: ORA-600 [KGL-heap-size-exceeded] Reported During AQ Operations (Doc ID 2521247.1)

  -- subscriber details from queue subscriber table.   "SCHEMA".AQ$_"QTABLE"_S
  select * from aq$_MULTICONSUMERMSGS_QTAB_s;

  -- subscriber details from common subscriber table
  select * from sys.aq$_subscriber_table;

  select * from  system.aq$_queue_tables where name = 'MULTICONSUMERMSGS_QTAB';

  select * from  system.aq$_queues where name = 'MSG_QUEUE_MULTIPLE';

  select to_char (t.flags), t.objno, t.name, q.name, t.*, q.*
    from system.aq$_queue_tables t, system.aq$_queues q
   where t.schema = 'K' and q.name = 'MSG_QUEUE_MULTIPLE' and t.objno = q.table_objno;
 
  select * from v$channel_waits;

  select * from dba_hist_channel_waits;