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;

Sunday, February 26, 2023

Oracle Scalar Subquery Caching and Non-deterministic Functions

This Blog will demonstrate that Non-deterministic Function call in Scalar Subquery returns different result with Caching.

Note: Tested on Oracle 19.17.


1. Test Setup



drop table test_tab; 

create table test_tab (x number, y number); 

create index test_tab_ind_x on test_tab(x);

create or replace package test_pack_nd as
  hit_cnt        number := 0;
  sign_threshold number := 50;
end;
/

-- Non-deterministic Function
create or replace function test_cond_nd (p_num number) return number as
  l_ret number;
begin
  test_pack_nd.hit_cnt := test_pack_nd.hit_cnt + 1;
  l_ret := p_num;
  if test_pack_nd.hit_cnt > test_pack_nd.sign_threshold then 
    l_ret := -p_num;
  end if;
    
  return l_ret;
end;
/

create or replace procedure test_proc_nd (p_rows number, p_x number := 1, p_y number := 5) as
  l_res number := 0;
begin
  execute immediate 'truncate table test_tab';
  insert into test_tab select mod(level, 2) x, mod(level, 100) y from dual connect by level <=p_rows;
  commit;
  dbms_stats.gather_table_stats(null, 'TEST_TAB', cascade=>true);
  
   dbms_output.put_line('---------- Compare test_proc_nd('||p_rows||', '||p_x||', '||p_y||') Function-Calls -------------');
  test_pack_nd.hit_cnt := 0;
  l_res             := 0;
  for c in (select * from test_tab where x = p_x and p_y = test_cond_nd(y)) loop
    l_res := l_res + 1;
  end loop;
  dbms_output.put_line('Direct   FuncCall Count = '||test_pack_nd.hit_cnt||', Found Rows# = '||l_res);
  
  test_pack_nd.hit_cnt := 0;
  l_res             := 0;
  for c in (select * from test_tab where x = p_x and (p_y = (select test_cond_nd(y) from dual))) loop
    l_res := l_res + 1;
  end loop;
  dbms_output.put_line('InDirect FuncCall Count = '||test_pack_nd.hit_cnt||', Found Rows# = '||l_res);
  
  test_pack_nd.hit_cnt := 0;
  l_res             := 0;
  for c in 
     (with sq as (select /*+ materialize */ * from test_tab where x = p_x order by y) 
      select * from sq where (p_y = (select test_cond_nd(y) from dual))) loop
    l_res := l_res + 1;
  end loop;
  dbms_output.put_line('InDirectOrdered FuncCall Count = '||test_pack_nd.hit_cnt||', Found Rows# = '||l_res);
end;
/


2. Test Run and Output


A simple run shows the different result with Scalar Subquery Caching and Non-deterministic Functions:

exec test_proc_nd(1000, 1, 5);

Direct   FuncCall Count = 500, Found Rows# = 1
InDirect FuncCall Count = 77, Found Rows# = 10
InDirectOrdered FuncCall Count = 50, Found Rows# = 10
The next test shows the threshold of different result also depending on the function's input parameters.

begin
  test_proc_nd(100, 0, 4);
  test_proc_nd(183, 0, 4);
  test_proc_nd(184, 0, 4);
  test_proc_nd(200, 0, 4);
  test_proc_nd(100, 1, 5);
  test_proc_nd(186, 1, 5);
  test_proc_nd(187, 1, 5);
  test_proc_nd(200, 1, 5);
end;
/

---------- Compare test_proc_nd(100, 0, 4) Function-Calls -------------
Direct   FuncCall Count = 50, Found Rows# = 1
InDirect FuncCall Count = 50, Found Rows# = 1
InDirectOrdered FuncCall Count = 50, Found Rows# = 1
---------- Compare test_proc_nd(183, 0, 4) Function-Calls -------------
Direct   FuncCall Count = 91, Found Rows# = 1
InDirect FuncCall Count = 50, Found Rows# = 2
InDirectOrdered FuncCall Count = 50, Found Rows# = 2
---------- Compare test_proc_nd(184, 0, 4) Function-Calls -------------
Direct   FuncCall Count = 92, Found Rows# = 1
InDirect FuncCall Count = 51, Found Rows# = 2
InDirectOrdered FuncCall Count = 50, Found Rows# = 2
---------- Compare test_proc_nd(200, 0, 4) Function-Calls -------------
Direct   FuncCall Count = 100, Found Rows# = 1
InDirect FuncCall Count = 52, Found Rows# = 2
InDirectOrdered FuncCall Count = 50, Found Rows# = 2
---------- Compare test_proc_nd(100, 1, 5) Function-Calls -------------
Direct   FuncCall Count = 50, Found Rows# = 1
InDirect FuncCall Count = 50, Found Rows# = 1
InDirectOrdered FuncCall Count = 50, Found Rows# = 1
---------- Compare test_proc_nd(186, 1, 5) Function-Calls -------------
Direct   FuncCall Count = 93, Found Rows# = 1
InDirect FuncCall Count = 50, Found Rows# = 2
InDirectOrdered FuncCall Count = 50, Found Rows# = 2
---------- Compare test_proc_nd(187, 1, 5) Function-Calls -------------
Direct   FuncCall Count = 94, Found Rows# = 1
InDirect FuncCall Count = 51, Found Rows# = 2
InDirectOrdered FuncCall Count = 50, Found Rows# = 2
---------- Compare test_proc_nd(200, 1, 5) Function-Calls -------------
Direct   FuncCall Count = 100, Found Rows# = 1
InDirect FuncCall Count = 53, Found Rows# = 2
InDirectOrdered FuncCall Count = 50, Found Rows# = 2
By the way, Filter Subqueries (November 6, 2006) demonstrated Scalar Subquery Caching and its impact on performance.

If the queried tables got updated, such Scalar Subquery Caching has a huge performance fluctuation (a sudden performance degradation).

As further tested in Oracle 19.17, even flush shared pool, flush buffer cache, dbms_session.reset_package are not able to remedy the fluctuation (If the update is in another session and never committed, there is no impact).

Monday, January 30, 2023

Oracle dbms_crypto.randombytes and Enhancement Suggestion

Oracle dbms_crypto provides three random functions: randombytes, randomnumber, randominteger. Internally they are subroutine kzstr called by dbms_crypto_ffi.random.
(randomnumber, randominteger are restricted cases of dbms_crypto_ffi.random(16) and dbms_crypto_ffi.random(4)).

dbms_crypto.randombytes function is based on the RSA X9.31 PRNG (Pseudo-Random Number Generator) ( DBMS_CRYPTO).

NIST wrote:
As of January 1, 2016, in accordance with the SP800-131A Revision 1 Transitions: Recommendation for
Transitioning the Use of Cryptographic Algorithms and Key Lengths, the use of RNGs specified 
in FIPS 186-2, [X9.31], and the 1998 version of [X9.62] is no longer approved. 
This list is provided for historical purposes only.
It is probably related to to: Practical State Recovery Attacks against Legacy RNG Implementations (Underlying cause: Seeding invertible PRNG with insufficient entropy).

In this Blog, we will give a dbms_crypto.randombytes Enhancement Suggestion with draft code. Then we take UUID generations as a use case of random functions, and compare Plsql vs. Java implementations.

Note: Tested on Oracle 19.17.


1. Draft Implementation of dbms_crypto.randombytes Enhancement Suggestion


We can enhance dbms_crypto.randombytes to read /dev/random or urandom as something like following code:

create or replace directory DEV_RANDOM_DIR as '/dev';

create or replace function randombytes_new (p_mode varchar2, p_len number := 16) return raw as
  l_random_bytes    raw(30000);
  l_file            utl_file.file_type;
  l_line            varchar2(10000);
  not_implmentation exception; 
  pragma exception_init (not_implmentation, -20001); 
begin
  case p_mode
    when 'H' then
      l_file := utl_file.fopen('DEV_RANDOM_DIR', 'random', 'R');
      utl_file.get_line(l_file, l_line); 
      l_random_bytes := utl_raw.cast_to_raw(l_line);
    when 'M' then
      l_file := utl_file.fopen('DEV_RANDOM_DIR', 'urandom', 'R');
      utl_file.get_line(l_file, l_line);
      l_random_bytes := utl_raw.cast_to_raw(l_line);
    when 'L' then
      l_random_bytes := dbms_crypto.randombytes(p_len);     -- no read of /dev/random or urandom
    else raise_application_error(-20001,'no_implmentation');
  end case; 
  
  if p_mode in ('H', 'M') then 
     utl_file.fclose(l_file);  
  end if; 
 
  l_random_bytes := lower(substr(l_random_bytes, 1, p_len*2));
  dbms_output.put_line(l_random_bytes);
  return l_random_bytes;
end;
/

-- Test
SQL > select randombytes_new('H'), randombytes_new('M') , randombytes_new('L') from dual;

  67B9D40056FFF28D3FD625EF47E4FA97
  9D07ED5D1EB537757B354F71242F5816
  3B3567C46334C705030FA61A73DB921E


2. UUID Generation


Take UUID generations as a use case of random functions, we will compare Plsql vs. Java implementations.

Java java.util.UUID reads /dev/random (/dev/urandom) and provides a cryptographically strong random number generator (RNG) with high entropy, as described in RFC 1750: Randomness Recommendations for Security. (calls java.security.SecureRandom.nextBytes with selected security.provider)

sun Java security provider NativePRNG has 3 Variants: MIXED, BLOCKING, NONBLOCKING (default MIXED):
      BLOCKING:     seedFile = new File(NAME_RANDOM); nextFile = new File(NAME_RANDOM);
      MIXED:        seedFile = new File(NAME_RANDOM); nextFile = new File(NAME_URANDOM);
      NONBLOCKING:  seedFile = new File(NAME_URANDOM);nextFile = new File(NAME_URANDOM);
java.util.UUID.randomUUID() provides IETF RFC 4122 version 4 UUID

In internet, we can find different uuid implmentations with Oracle dbms_crypto and Java,
for example: How to generate a version 4 (random) UUID on Oracle?

Here our test code:

create or replace function dbms_crypto_uuid return varchar2 is
  /* UUID Version 4 must be formatted as xxxxxxxx-xxxx-4xxx-yxxx-xxxxxxxxxxxx 
     where x is any hexadecimal character (lower case only) and y is one of 8, 9, a, or b.*/
  v_uuid_raw raw(16);
  v_uuid     varchar2(36);
  v_y        varchar2(1);
begin
  v_uuid_raw := sys.dbms_crypto.randombytes(16);
  v_uuid_raw := utl_raw.overlay(utl_raw.bit_or(utl_raw.bit_and(utl_raw.substr(v_uuid_raw, 7, 1), '0F'), '40'), v_uuid_raw, 7);
  v_y := to_char(8 + round(dbms_random.value(0, 3)), 'fmx');
  v_uuid_raw := utl_raw.overlay(utl_raw.bit_or(utl_raw.bit_and(utl_raw.substr(v_uuid_raw, 9, 1), '0F'), v_y || '0'), v_uuid_raw, 9);
  v_uuid     := substr(v_uuid_raw,  1,  8)||'-'||
                substr(v_uuid_raw,  9,  4)||'-'||
                substr(v_uuid_raw, 13,  4)||'-'||
                substr(v_uuid_raw, 17,  4)||'-'||
                substr(v_uuid_raw, 21, 12);
  return v_uuid;
end;
/

--Java Variant-1
create or replace function java_uuid_v1 return varchar2 as language java
name 'java.util.UUID.randomUUID() return String'
;
/

--Java Variant-2
create or replace and compile java source named "RandomUUIDV2" as
import java.util.UUID;
public class RandomUUIDV2{
  public static String create() {
    return java.util.UUID.randomUUID().toString();
  }

  private static class Inner {
    //overwrite Object.toString()
	  public String toString()
	  {
	     System.out.println("Call Stack");
         StackTraceElement[] stackTraces = Thread.currentThread().getStackTrace();
	     for (int i = 1; i < stackTraces.length; i++) {
	       System.out.println("    " + (stackTraces.length - i) + " " + stackTraces[i]);
	    }
	    return "End";
	}
  }
  
  public static String ToStringCompare() {
    Inner inner = new Inner();
    System.out.println("\n---------- Object toString implicit ----------\n");
    System.out.println(inner);
    System.out.println("\n---------- Class  toString explicit ----------\n" );
    System.out.println(inner.toString());
    
    return "ToStringCompare";
  }
};
/

create or replace function java_uuid_v2 return varchar2 as language java
name 'RandomUUIDV2.create() return String';
/

create or replace function to_string_compare return varchar2 as language java
name 'RandomUUIDV2.ToStringCompare() return String';
/


create or replace procedure test_proc_uuid(p_cnt number, p_use_method varchar2 := 'dbms_crypto', p_gc_limit number := null) as
  l_uuid_str        varchar2(200);
  l_java_es_return  varchar2(50);
  l_gc_cnt_start    number;
  l_gc_cnt_end      number;
  l_heap_size_start number;
  l_heap_size_end   number;
  l_endsess_cnt     number := 0;
  l_start_time      number := dbms_utility.get_time;
begin
  dbms_output.put_line('============== test_proc_uuid('||p_cnt||', '||p_use_method||', '||p_gc_limit||') ===========');
  
  select s.value into l_gc_cnt_start from v$mystat s, v$statname n 
   where s.statistic#= n.statistic# and name in ('java call heap gc count');
  select s.value into l_heap_size_start from v$mystat s, v$statname n 
   where s.statistic#= n.statistic# and name in ('java call heap used size');
   
  for i in 1..p_cnt loop
    case p_use_method
      when 'dbms_crypto' then 
        l_uuid_str := dbms_crypto_uuid;     
      when 'java_v1' then
        l_uuid_str := java_uuid_v1;     
      when 'java_v2' then
        l_uuid_str := java_uuid_v2;      -- with randomUUID().toString()
      else raise_application_error(-20010, 'no implementation');
    end case;
    
    if mod(i, p_gc_limit)= 0 then
      l_java_es_return := dbms_java.endsession;
      l_endsess_cnt := l_endsess_cnt + 1;
    end if;
  end loop;
  
  select s.value into l_gc_cnt_end from v$mystat s, v$statname n 
   where s.statistic#= n.statistic# and name in ('java call heap gc count');
  select s.value into l_heap_size_end from v$mystat s, v$statname n 
   where s.statistic#= n.statistic# and name in ('java call heap used size');
   
  dbms_output.put_line('dbms_java.endsession count = '||l_endsess_cnt||', Elpased_CS = '||(dbms_utility.get_time-l_start_time));
  
  dbms_output.put_line('java call heap gc diff = '||(l_gc_cnt_end - l_gc_cnt_start)||' ('||l_gc_cnt_end||'-'||l_gc_cnt_start||')');
  dbms_output.put_line('java call heap used size diff = '||(l_heap_size_end - l_heap_size_start)||
                       ' ('||l_heap_size_end||'-'||l_heap_size_start||'), '||' End Size(KB) = '||(round(l_heap_size_end/1024)));
end;
/
Here some test output:

SQL> set serveroutput on size 50000
SQL> exec dbms_java.set_output(50000); 

SQL> select dbms_crypto_uuid, java_uuid_v1, java_uuid_v2 from dual;

  DBMS_CRYPTO_UUID                     JAVA_UUID_V1                         JAVA_UUID_V2
  ------------------------------------ ------------------------------------ ------------------------------------
  F82C9C94-6BBA-47B0-AC1B-9593224FC974 4c5c9e82-4646-4f75-bf40-84f2c46479ab e85416af-3665-4053-96c2-b5b06aa7f6de

SQL> select to_string_compare from dual;

  ---------- Object toString implicit ----------
  Call Stack
      4 RandomUUIDV2$Inner.toString(RandomUUIDV2:12)
      3 java.lang.String.valueOf(String.java:2994)
      2 java.io.PrintStream.println(PrintStream.java:821)
      1 RandomUUIDV2.ToStringCompare(RandomUUIDV2:23)
  End
  
  ---------- Class  toString explicit ----------
  Call Stack
      2 RandomUUIDV2$Inner.toString(RandomUUIDV2:12)
      1 RandomUUIDV2.ToStringCompare(RandomUUIDV2:25)
  End

// java.lang.String.valueOf
//   public static String valueOf(Object obj) {
//         return (obj == null) ? "null" : obj.toString();
//     if the argument is null, then a string equal to "null"; otherwise, the value of obj.toString() is returned.
We can also make a small performance test (time and memory). Here the test and output on Linux:

begin
  test_proc_uuid(10000, 'dbms_crypto');
  test_proc_uuid(10000, 'java_v1');
  test_proc_uuid(10000, 'java_v2');

  test_proc_uuid(10000, 'dbms_crypto', 1000);
  test_proc_uuid(10000, 'java_v1',     1000);
  test_proc_uuid(10000, 'java_v2',     1000);
end;
/

============== test_proc_uuid(10000, dbms_crypto, ) ===========
dbms_java.endsession count = 0, Elpased_CS = 23
java call heap gc diff = 0 (90-90)
java call heap used size diff = 0 (136352-136352),  End Size(KB) = 133
============== test_proc_uuid(10000, java_v1, ) ===========
dbms_java.endsession count = 0, Elpased_CS = 112
java call heap gc diff = 1 (91-90)
java call heap used size diff = -61792 (74560-136352),  End Size(KB) = 73
============== test_proc_uuid(10000, java_v2, ) ===========
dbms_java.endsession count = 0, Elpased_CS = 86
java call heap gc diff = 1 (92-91)
java call heap used size diff = 3903360 (3977920-74560),  End Size(KB) = 3885
============== test_proc_uuid(10000, dbms_crypto, 1000) ===========
dbms_java.endsession count = 10, Elpased_CS = 18
java call heap gc diff = 0 (92-92)
java call heap used size diff = 0 (3977920-3977920),  End Size(KB) = 3885
============== test_proc_uuid(10000, java_v1, 1000) ===========
dbms_java.endsession count = 10, Elpased_CS = 245
java call heap gc diff = 10 (102-92)
java call heap used size diff = -3903360 (74560-3977920),  End Size(KB) = 73
============== test_proc_uuid(10000, java_v2, 1000) ===========
dbms_java.endsession count = 10, Elpased_CS = 114
java call heap gc diff = 10 (112-102)
java call heap used size diff = 61792 (136352-74560),  End Size(KB) = 133

Thursday, December 15, 2022

OracleJVM JAVA_JIT_ENABLED Linux /dev/shm mount noexec EPERM and Performance

In Linux, when JAVA_JIT_ENABLED is enabled, the native compiled Java code is stored in /dev/shm/JOEZSHM_*.
However, if tmpfs /dev/shm/ is mounted with "noexec" option as follows:

mount | grep shm
   tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev,noexec)
mmap of JOEZSHM_* gets error EPERM ("Operation not permitted"), and JAVA_JIT_ENABLED does not work.

In MZnn and session trace files, there are plenty of "Operation not permitted" (EPERM) for JOEZSHM_*.

As a consequence, Oracle falls back to JAVA_JIT_ENABLED=false and the performance is degraded upto 50 times slower than the functional case.

Note: Tested on Oracle 19.13.


1. Test-1 Simple Case


First we make a simple SQL Java call (dbms_java.getversion calls java.lang.System.getProperty via dbms_java.get_ojvm_property), and strace its Linux process:

SQL > select 'JServer version: '||dbms_java.getversion, 'JDK version:'||dbms_java.get_jdk_version from dual;  

$> strace -tT -o mmap_strace.log -p 16637
After the call, we can see the new created memory files: /dev/shm/JOEZSHM_*:

$> ls -l /dev/shm
  total 32768
  -rwxrwx--- 1 oracle dba 16777216 Dec 13 07:36 JOEZSHM_testdb_1_0_0_0_0_2084322508
  -rwxrwx--- 1 oracle dba 16777216 Dec 13 07:36 JOEZSHM_testdb_1_0_1_0_0_749348400
  
-- no entry found, no JOEZSHM_* mapped to process address space
$> pmap -X -p 16637 |grep -i JOEZSHM
mmap_strace.log shows:

  07:36:23 open("/dev/shm/JOEZSHM_testdb_1_0_0_0_0_2084322508", O_RDWR|O_CREAT|O_NOFOLLOW|O_CLOEXEC, 0770) = 7 <0.000456>
  07:36:23 lseek(7, 0, SEEK_CUR)          = 0 <0.000018>
  07:36:23 lseek(7, 0, SEEK_END)          = 16777216 <0.000023>
  07:36:23 lseek(7, 0, SEEK_SET)          = 0 <0.000030>
  07:36:23 mmap(NULL, 16777216, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_SHARED, 7, 0) = -1 EPERM (Operation not permitted) <0.000022>
MZ00 and session trace files are filled with:

sjoezshm_map_obj mmap failed for /JOEZSHM_testdb_1_0_0_0_0_2084322508: Operation not permitted
size  = 16777216, prot_mode  = 7, map_flag = 1
joez_shm_open_object failed: size = 16777216, extnam = /JOEZSHM_testdb_1_0_0_0_0_2084322508  flags = 0x34 
joez: Failed loading machine code: Unable to allocate code space

sjoezshm_map_obj mmap failed for /JOEZSHM_testdb_1_0_1_0_0_749348400: Operation not permitted
size  = 16777216, prot_mode  = 7, map_flag = 1
joez_shm_open_object failed: size = 16777216, extnam = /JOEZSHM_testdb_1_0_1_0_0_749348400  flags = 0x34 
joez: Failed loading machine code: Unable to allocate code space


2. Test-2 Complex Case


Use the same test code in Blog: Oracle 19.4 OracleJVM JAVA_JIT_ENABLED Not Working on AIX to read a 27MB signed JAR file testJar.jar (security signatures under META-INF directory).

$> ls -l /tmp/testJar.jar
  -rw-r--r-- 1 oracle dba 28944084 Dec  6 17:39 /tmp/testJar.jar

$> unzip -l /tmp/testJar.jar
  Archive:  /tmp/testJar.jar
    Length      Date    Time    Name
  ---------  ---------- -----   ----
        144  12-05-2019 08:27   META-INF/MANIFEST.MF
        306  12-05-2019 08:27   META-INF/KUNALIAS.SF
       1471  12-05-2019 08:27   META-INF/KUNALIAS.DSA
          0  12-05-2019 08:26   META-INF/
  110947240  12-05-2019 08:23   test1.txt
  ---------                     -------
  110949161                     5 files
First we invoke OracleJVMJarInputStream without signature verify, it takes 3 seconds:

Sql > set serveroutput on size 50000
Sql > exec dbms_java.set_output(50000); 

SQL > exec OracleJVMJarInputStream(p_verify => 'false', p_info => 'no');

********* getNextJarEntry *********
------ NextJarEntry: 1, Name: META-INF/KUNALIAS.SF ------
         getNextEntry ElapsedMills: 31, at: 1670863088140
         Insert DB 1 row, blob size 0 at Mon Dec 12 17:38:08 CET 2022
         readContent ElapsedMills: 5, at: 1670863088145
------ NextJarEntry: 2, Name: META-INF/KUNALIAS.DSA ------
         getNextEntry ElapsedMills: 0, at: 1670863088145
         Insert DB 1 row, blob size 0 at Mon Dec 12 17:38:08 CET 2022
         readContent ElapsedMills: 2, at: 1670863088147
------ NextJarEntry: 3, Name: META-INF/ ------
         getNextEntry ElapsedMills: 0, at: 1670863088148
         Insert DB 1 row, blob size 0 at Mon Dec 12 17:38:08 CET 2022
         readContent ElapsedMills: 2, at: 1670863088150
------ NextJarEntry: 4, Name: test1.txt ------
         getNextEntry ElapsedMills: 0, at: 1670863088150
         Insert DB 1 row, blob size 110920480 at Mon Dec 12 17:38:11 CET 2022
         readContent ElapsedMills: 3125, at: 1670863091275

PL/SQL procedure successfully completed.
Elapsed: 00:00:03.20
Then we invoke OracleJVMJarInputStream with signature verify, it takes 3 minutes:

Sql > exec OracleJVMJarInputStream(p_verify => 'true', p_info => 'no');

********* getNextJarEntry *********
------ NextJarEntry: 1, Name: META-INF/KUNALIAS.SF ------
         getNextEntry ElapsedMills: 1, at: 1670863115333
         Insert DB 1 row, blob size 0 at Mon Dec 12 17:38:35 CET 2022
         readContent ElapsedMills: 6, at: 1670863115339
------ NextJarEntry: 2, Name: META-INF/KUNALIAS.DSA ------
         getNextEntry ElapsedMills: 0, at: 1670863115339
         Insert DB 1 row, blob size 0 at Mon Dec 12 17:38:35 CET 2022
         readContent ElapsedMills: 423, at: 1670863115762
------ NextJarEntry: 3, Name: META-INF/ ------
         getNextEntry ElapsedMills: 0, at: 1670863115762
         Insert DB 1 row, blob size 0 at Mon Dec 12 17:38:35 CET 2022
         readContent ElapsedMills: 3, at: 1670863115765
------ NextJarEntry: 4, Name: test1.txt ------
         getNextEntry ElapsedMills: 0, at: 1670863115765
         Insert DB 1 row, blob size 110920480 at Mon Dec 12 17:41:35 CET 2022
         readContent ElapsedMills: 179651, at: 1670863295417

PL/SQL procedure successfully completed.
Elapsed: 00:03:00.12
If JAVA_JIT_ENABLED works (/dev/shm is mounted without "noexec"), the execution with signature verify is completed in 5 seconds (instead of 3 minutes).


3. Test-3 Standalone mmap.c Test


Web Page: mmap() fails on tmpfs (operation not permitted) #2974 provided a mmap.c test code and showed "mmap() failed: : Operation not permitted".

We can use the same code to simulate Oracle JIT /dev/shm/JOEZSHM_* test.
(with small adaptations of open and mmap arguments to Oracle parameters according to strace output in above Test-1 Simple Case).

// mmap-fail.cpp
#include <stdint.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <sys/mman.h>
#include <fcntl.h>
#include <stdio.h>
#include <unistd.h>

// $ g++ mmap-fail.cpp -o mmap-fail
// $ sudo ./mmap-fail
// mmap() failed: : Operation not permitted

int main(int argc, const char* argv[])
{
    //const char* path = "./eightbytes.bin"; // okay on lxfs
    //const char* path = "/run/eightbytes.bin";
    //int fd = open(path, O_RDWR|O_CREAT|O_CLOEXEC|O_NOCTTY|O_NOFOLLOW, 0644);
    int fd = open("/dev/shm/JOEZSHM_testdb_1_0_0_0_0_2084322508", O_RDWR|O_CREAT|O_NOFOLLOW|O_CLOEXEC, 0770);
    if (fd < 0) {
        perror("open() failed: ");
        return 1;
    }
    int r = posix_fallocate(fd, 0, sizeof(uint64_t));
    if (r < 0) {
        perror("posix_fallocate() failed: ");
        return 1;
    }
    //uint64_t *p = (uint64_t*)mmap(NULL, sizeof(uint64_t), PROT_READ|PROT_WRITE, MAP_SHARED, fd, 0);
    uint64_t *p = (uint64_t*)mmap(NULL, sizeof(uint64_t), PROT_READ|PROT_WRITE|PROT_EXEC, MAP_SHARED, fd, 0);
    if (p == MAP_FAILED) {
        perror("mmap() failed: ");
        return 1;
    }
    int r2 = close(fd);

    printf("Whee! mmap SUC\n");
    return 0;
}
Run the test with strace:

$> strace -tT -o mmap-fail_strace.log ./mmap-fail
  mmap() failed: : Operation not permitted
mmap-fail_strace.log shows:

  07:42:37 open("/dev/shm/JOEZSHM_testdb_1_0_0_0_0_2084322508", O_RDWR|O_CREAT|O_NOFOLLOW|O_CLOEXEC, 0770) = 3 <0.000022>
  07:42:37 fallocate(3, 0, 0, 8)          = 0 <0.000018>
  07:42:37 mmap(NULL, 8, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_SHARED, 3, 0) = -1 EPERM (Operation not permitted) <0.000017>


4. mmap.c EPERM Operation not permitted


From source mm/mmap.c, we can see that EPERM (Operation not permitted) is thrown in do_mmap
(case MAP_SHARED fallthrough to case MAP_PRIVATE).

// mm/mmap.c
unsigned long do_mmap(struct file *file, unsigned long addr,
  ...
	if (file) {
		...
		switch (flags & MAP_TYPE) {
		case MAP_SHARED:
      ...
			fallthrough;
		case MAP_SHARED_VALIDATE:
      ...
			fallthrough;
		case MAP_PRIVATE:
			if (!(file->f_mode & FMODE_READ))
				return -EACCES;
			if (path_noexec(&file->f_path)) {
				if (vm_flags & VM_EXEC)
					return -EPERM;
				vm_flags &= ~VM_MAYEXEC;
			}
			
			
include/uapi/asm-generic/errno-base.h
  #define	EPERM		 1	/* Operation not permitted */


5. Fix


To fix EPERM problem on Linux for JAVA_JIT_ENABLED, remove noexec option for tmpfs /dev/shm and make it permanent in /etc/fstab:

$> mount -o remount,exec /dev/shm
So that it looks like:

$> mount |grep shm
     tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev)

$> cat /etc/fstab |grep shm
     tmpfs /dev/shm tmpfs nosuid,nodev 0 0


6. Related Work and Other Observations


For further discussions on OracleJVM JAVA_JIT_ENABLED, see:
     What the heck are the /dev/shm/JOXSHM_EXT_x files on Linux?
     Oracle 19.4 OracleJVM JAVA_JIT_ENABLED Not Working on AIX

There is also contre-proposition:
     The Oracle Linux operating system must mount /dev/shm with the noexec option.

When JAVA_JIT_ENABLED works, and we strace MZ00 session for a while.
Trace file shows that MZ00 is continuously compiling Java, each time, only one method (not entire class).
The timestamp of /dev/shm/JOEZSHM_* shows that those memory files are also updated.

$> strace -tT -s 128 -o mz00_strace.txt -p 23037

-- (fd 6 is testdb_mz00_23037.trc)
$> grep "Done compiling.*locale*" mz00_strace.txt
  15:48:11 write(6, "Done compiling sun/util/locale/provider/TimeZoneNameUtility$TimeZoneNameGetter.getObject", 88) = 88 <0.000026>
  15:50:44 write(6, "Done compiling sun/util/locale/provider/TimeZoneNameUtility$TimeZoneNameGetter.getObject", 88) = 88 <0.000019>
  15:50:44 write(6, "Done compiling sun/util/locale/provider/TimeZoneNameProviderImpl.getDisplayNameArray", 84) = 84 <0.000025>
  15:50:44 write(6, "Done compiling sun/util/locale/provider/TimeZoneNameUtility$TimeZoneNameGetter.getName", 86) = 86 <0.000046>
  15:50:44 write(6, "Done compiling sun/util/locale/provider/LocaleResources.removeEmptyReferences", 77) = 77 <0.000035>
  15:50:45 write(6, "Done compiling sun/util/locale/provider/LocaleResources.getTimeZoneNames", 72) = 72 <0.000039>
  15:50:46 write(6, "Done compiling sun/util/locale/BaseLocale$Key.normalize", 55) = 55 <0.000030>
  15:50:47 write(6, "Done compiling sun/util/locale/provider/TimeZoneNameProviderImpl.getDisplayName", 79) = 79 <0.000057>
By the way, in the old Oracle release, there are many JIT compiled small files (KB) with name pattern like JOXSHM_EXT_*,
In Oracle 19c, there are only a few big files (16MB) with name pattern like JOEZSHM_*.

Update (2023-02-26)Oracle 19c Java Developer's Guide: 9.1 Oracle JVM Just-in-Time Compiler (JIT) documented this behaviour:
Note:
 
On Linux, Oracle JVM JIT uses POSIX shared memory that requires access to the /dev/shm directory.
The /dev/shm directory should be of type tmpfs and you must mount this directory as follows:
  -. With rw and execute permissions set on it
  -. Without noexec or nosuid set on it
If the correct mount options are not used, then the following failure may occur during installation of the database:
  ORA-29516: Aurora assertion failure: Assertion failure at joez.c:
             Bulk load of method java/lang/Object. failed; insufficient shm- object space

Sunday, December 4, 2022

One Test of Oracle too many parse errors with ORA-12850 and ORA-12872

In this Blog, we first make a test to demonstrate Oracle "too many parse errors" associated with ORA-12850 and ORA-12872.
Then we reveal both errors in Oracle trace files. It looks like a limitation of materialized WITH subquery in parallel statements.

Update (2024-Dec-07)
The problem seems due to Multiple Parallelizers (more than one "PX COORDINATOR" in Xplan, or more than one "Parallel Group" in SQL Monitor).
Here two Oracle provided workarounds to turn off in_memory Cursor Duration Temp tables (CDT)
(trade-off between elapsed time (parsing errors, CPU usage) and Temporary Temp Space)

================================== Workaround-1 ==================================
--  _in_memory_cdt(In Memory CDT) 
--  OFF | LIMITED | ON (default LIMITED)

-- system level
alter system set "_in_memory_cdt"=off;
-- session level
alter session set "_in_memory_cdt"=off;
-- Statement level
opt_param('_in_memory_cdt', 'off')

================================== Workaround-2 ==================================
-- _px_reuse_server_groups (enable/disable reusing of server groups that are already acquired)
-- SINGLE, MULTI (default), OFF

alter session set "_px_reuse_server_groups" = off;  

Note: Reproduced in Oracle 19.9, 19.10, 19.11, 19.13, 19.25. All are non RAC DB.


1. Test Setup



create table test_tab as select level x from dual connect by level <= 10; 

create or replace procedure test_proc (p_cnt number, p_limit pls_integer, p_sleeps number) as
  type t_num_tab      is table of number;
  l_num_tab           t_num_tab := new t_num_tab();
begin
  for i in 1..p_cnt loop 
    dbms_session.sleep(p_sleeps);
    with sq as (select /*+ materialize  */ x from test_tab)
    select /*+ parallel(2) */ t.x  
      bulk collect into l_num_tab
      from test_tab t, sq 
     where rownum <= p_limit;
   end loop; 
   
   dbms_output.put_line('Selected Rows = '||l_num_tab.count);
end;
/


2. Test Run


(Step-1) Open a new Sqlplus session

(Step-2) Flush Shared Pool
            alter system flush shared_pool; 

(Step-3) Run test procedure
            exec test_proc(1000, 3, 0.1);

(Step-4) Check DB alert.log if there is message:
            WARNING: too many parse errors
   
(Step-5) If no such message, repeat Step-1 to Step-5.
         That means opening next new Sqlplus session to do the same test.
         Most of tests showed that one or two Sqlplus sessions are sufficient to reproduce the problem.
Here the message in DB alert.log. PARSE ERROR are signalled with error=12850 or error=12872.
Note that the message is only written for each 100 such errors (count=13300 jump to count=13400).

2022-12-01T20:01:08.221827+01:00
WARNING: too many parse errors, count=13300 SQL hash=0x49952973
PARSE ERROR: ospid=31115, error=12850 for statement: 
2022-12-01T20:01:08.221953+01:00
WITH SQ AS (SELECT /*+ materialize  */ X FROM TEST_TAB) SELECT /*+ parallel(2) */ T.X FROM TEST_TAB T, SQ WHERE ROWNUM <= :B1
Additional information: hd=0x97efe2e0 phd=0x9437c118 flg=0x110676 cisid=86 sid=86 ciuid=86 uid=86 sqlid=3z4qz1d4taabm
...Current username=K
...Application:  Action: 
2022-12-01T20:01:09.170414+01:00
WARNING: too many parse errors, count=13400 SQL hash=0x49952973
PARSE ERROR: ospid=31117, error=12872 for statement: 
2022-12-01T20:01:09.170531+01:00
WITH SQ AS (SELECT /*+ materialize  */ X FROM TEST_TAB) SELECT /*+ parallel(2) */ T.X FROM TEST_TAB T, SQ WHERE ROWNUM <= :B1
Additional information: hd=0x97efe2e0 phd=0x9437c118 flg=0x110676 cisid=86 sid=86 ciuid=86 uid=86 sqlid=3z4qz1d4taabm
...Current username=K
...Application: SQL*Plus Action:  
Appendix-1 lists a few related Oracle Error Documents.

Appendix-2 shows parallel xplan.


3. ORA-10388 Trace


Oracle (Doc ID 2180844.1) has a description of ORA-12850 (PX QC and worker signature-plan mismatch) and documents Troubleshooting Steps.

How to get plan signature tracing for ORA-12850 (Doc ID 2180844.1)
  Purpose
      ORA-12850 errors are usually caused by the worker getting a plan signature different from that of the QC.  
      These are typically, although not always, QRY OPTIMIZER bugs. This note provides the recommended tracing needed 
      in order to see if there is a signature-plan mismatch and diagnose the cause of ORA-12850.†

  Troubleshooting Steps
      alter system set†"_parallel_blackbox_size" =†524288;†
      -- prevents traces from being truncated
      alter session set max_dump_file_size = unlimited;                         
      -- customer will be prompted for a string that will appear in the tracefile name
      alter session set tracefile_identifier = '&TRACEFILE_IDENTIFIER';         
      alter session set events 'trace[SQL_Compiler.*] disk highest';
      alter session set events 'trace[Parallel_Execution.*] disk highest';
      
      --run test code, for example, in this Blog:
      exec test_proc(10, 3, 0.1);
      
      -- turn tracing off
      alter session set events 'trace[SQL_Compiler.*] off';
      alter session set events 'trace[Parallel_Execution.*] off';
    
    Look for the plan signatures in the QC vs. worker traces.  
    The worker that will have the mismatch should be the one with the 10388 error in it.  
    Notice that the plan signatures do NOT match, which causes the ORA-12850.
	
  3. Look for the plan signatures in the QC vs. worker traces.  
     The worker that will have the mismatch should be the one with the 10388 error in it.  
     Notice that the plan signatures do NOT match, which causes the ORA-12850.
     
        QC Plan Signature from Parse Msg:  SQL Plan Signature
        Slave Plan Signature:  SQL Plan Signature
Following above Oracle instructions, we get Plan Signature in worker (pnnn) traces like:

  Slave Plan Signature:  SQL Plan Signature (0x93838ff0):
  QC Plan Signature from Parse Msg:  SQL Plan Signature (0x7f0fed684134):
In Oracle Document, ORA-10388 Comment said: commands a slave to leave the server group (query failed).
So we will look for 10388 error in the trace files.

In worker (pnnn) trace files, internal oracle error=10388 (message to terminate a parallel query) is precised by "In signal-handler after catching 12850", and finalized by "Exiting parallel client parallel query execution(6) on error=10388".

====================== error 12850 ======================
2022-12-01 11:28:29.288*:PX_Control:kxfx.c@4849:kxfxsp1(begin): 
	Open & parse cursor(EXPRESS/-): 
	[123:WITH SQ AS (SELECT /*+ materialize  */ X FROM TEST_TAB) SELECT /*+ parallel(2) */ T.X FROM TEST_TAB T, SQ WHERE ROWNUM <= :B1 ]
2022-12-01 11:28:29.288*:PX_Control:kxfx.c@4853:kxfxsp1(end): 
2022-12-01 11:28:29.288*:PX_Control:kxfx.c@5885:kxfxsp(end): 
2022-12-01 11:28:29.327*:PX_Control:kxfx.c@6114:kxfxsStatus(): 
	joining FALSE ParseState KXFXUPARSE2 (3)
2022-12-01 11:28:29.331*:PX_Control:kxfx.c@10728:kxfxmai(): 
	In signal-handler after catching 12850
2022-12-01 11:28:29.333*:PX_Control:kxfx.c@10728:kxfxmai(): 
	In signal-handler after catching 10388
2022-12-01 11:28:29.333*:PX_Control:kxfx.c@5678:kxfxsuf(): 
	kxfx slave finish
2022-12-01 11:28:29.333*:PX_Messaging:kxfp.c@14665:kxfprdp_int(): 
	Exiting parallel client parallel query execution(6) on error=10388
In the same trace files, "Received error 12872" is noted with "First parse failed" during Semantic Analysis:

====================== error 12872 ======================
2022-12-01 11:29:30.411*:PX_Control:kxfx.c@6829:kxfxsExecute(): 
	Received error 12872 from first slave parse.
	First parse failed. On to outlined parse 
2022-12-01 11:29:30.411*:PX_Control:kxfx.c@13917:kxfxsStmtDump(): 
	kxfxsSmtExecute stmt:0x7f0fed69ff50
	 UGA: InUse:255KB Alloc:255KB
	 PGA: InUse:1665KB Alloc:1835KB
Enabling tracing for cur#=1 sqlid=3z4qz1d4taabm top-level
Parsing cur#=1 sqlid=3z4qz1d4taabm len=123 
sql=WITH SQ AS (SELECT /*+ materialize  */ X FROM TEST_TAB) SELECT /*+ parallel(2) */ T.X FROM TEST_TAB T, SQ WHERE ROWNUM <= :B1 
End parsing of cur#=1 sqlid=3z4qz1d4taabm
Semantic Analysis cur#=1 sqlid=3z4qz1d4taabm
OPTIMIZER INFORMATION


4. Performance Impacts


When multiple sessions frequently run such statement, especially with high degree of parallelism (DOP), DB performance degradation is often caused by following heavy wait events:

  cursor: pin S wait on X
  library cache lock
  kksfbc child completion
  PX Deq: Parse Reply
  PX Deq: Execution Msg
When looking the wait chains, often one PX particular worker is the blocker of QC or other workers. We also noticed that V$SQL.child_number can go over 1000 ("_cursor_obsolete_threshold" default 1024).

A quick workaround is to remove parallel hint to make serial execution.

Blog: 12c Parse listed a few activity stats to monitor:
  opened cursors cumulative         
  enqueue requests                  
  enqueue releases                  
  sql area purged                   
  sql area evicted                  
  parse count (total)               
  parse count (hard)                
  parse count (failures)            
Tests showed that the call (1000 executions of query):

  exec test_proc(1000, 3, 0.1); 
generated 6000 lines of "too many parse errors" in DB alert.log:
(the count seems reading from V$SQLAREA.invalidations for each sql_id)

  WARNING: too many parse errors, count=53700 SQL hash=0x49952973 ... sqlid=3z4qz1d4taabm
  ...
  WARNING: too many parse errors, count=59700 SQL hash=0x49952973 ... sqlid=3z4qz1d4taabm
v$sysstat query:

select v.value, v.* from v$sysstat v
where name in ('parse count (failures)', 'sql area purged', 'sql area evicted', 
               'parse count (hard)', 'parse count (total)', 
               'opened cursors cumulative', 'enqueue releases', 'enqueue requests') 
order by v.value;
shwed that:
   the value of 'parse count (failures)', 'sql area purged', 'sql area evicted' increased 6000
   the value of 'parse count (hard)', 'parse count (total)' increased a little more than 6000 (if no other DB activities)
So each test query execution created 6 "too many parse errors" related to 6 'parse count (failures)'.

Often in AWR, we can see high hard parse elapsed time and SQL high %CPU:
  
hard parse elapsed time   35.64 % of DB Time

%CPU  %IO  SQL Id        SQL Text
61.20 3.28 3z4qz1d4taabm WITH SQ AS (SELECT /*+ materia...
ADDM Findings shows:
   
Finding 1: Top SQL Statements

SQL statement with SQL_ID 3z4qz1d4taabm.
WITH SQ AS (SELECT /*+ materialize  */ X FROM TEST_TAB) SELECT /*+
parallel(2) */ T.X FROM TEST_TAB T, SQ WHERE ROWNUM <= :B1

Rationale
The SQL spent only 20% of its database time on CPU, I/O and Cluster waits. 
Therefore, the SQL Tuning Advisor is not applicable in this case.
Look at performance data for the SQL to find potential improvements.

Rationale
Database time for this SQL was divided as follows: 25% for SQL
execution, 75% for parsing, 0% for PL/SQL execution and 0% for Java execution.


5. ORA-00600 [xplUnCompact:magic]


In very rare case, QC session throws ORA-00600 as follows. It looks like that the error occurs when optimizer automatic sql reoptimisation (kkoarSalvageStats, COMPONENT: SQL_Costing) checks cardinality feedback (kkocfbCheckCardEstRws, COMPONENT: SQL_Costing) in xplan (xplUnCompact, COMPONENT: explain).

ORA-00600: internal error code, arguments: [xplUnCompact:magic], [0], [0x7FFE5C370D98]

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

[12] (kgeasnmierr()+146 -> kgerinv())
[13] (xplUnCompact()+1320 -> kgeasnmierr())
[14] (kkocfbCheckCardEstRws()+815 -> xplUnCompact())
[15] (kkocfbCheckCardEstRws()+259 -> kkocfbCheckCardEstRws())
[16] (kkocfbCheckCardEstRws()+259 -> kkocfbCheckCardEstRws())
     -- a couple of same calling lines
[35] (kkocfbCheckCardEstRws()+259 -> kkocfbCheckCardEstRws())
[36] (kkocfbCheckCardEst()+571 -> kkocfbCheckCardEstRws())
[37] (kkoarSalvageStats()+910 -> kkocfbCheckCardEst())
[38] (kxsFreeWorkArea()+149 -> kkoarSalvageStats())
[39] (kxsFreeExecutionHeap()+60 -> kxsFreeWorkArea())
[40] (kksumc()+631 -> kxsFreeExecutionHeap())
[41] (opiexe()+10228 -> kksumc())

Session Wait History:
    elapsed time of 0.993485 sec since last wait
 0: waited for 'enq: PS - contention'


6. Related Oracle BUGs and Related Work


There are a few related BUGs in Oracle MOS, we tested them (patch installed or hidden parameter set. Test DB are not RAC).
All have no effect, and DB still throws the same "too many parse errors":

Bug 31602782 ††Contention on "CURSOR: PIN S WAIT ON X" when PQ slave's execution plan does not match with QC       
   Versions confirmed as being affected: 12.2.0.1 (Base Release) - 19.13.0
   Description
     When a parallel query is executed, QC sends parse message to all workers in all  
     instances. In a instance one worker tries to parse the cursor and other workers 
     waits (cursor pin s wait for x) for that cursor to parsed and built. 
      
     If this worker could not build the cursor with the same plan as QC and could not  
     join, another worker tries the same and so on until all workers get exhausted 
     and query runs in serial or without workers from that instance. 
      
     This can cause a huge contention on CURSOR: PIN S WAIT ON X .
      
     After this bug fix, if a worker on one instance fails to produce same plan as QC, 
     other workers on the same instance do not retry the parse and workers from 
     that instance are not allocted.
    
Bug 32121673††A Process May Crash With Ora-600 [xpluncompact:magic]
 
Warning: Too Many Parse Errors With ORA-12850/ORA-12872 (Doc ID 2816169.1)
  Cause
     It appears that this is due to Bug 31877812 : WHEN HIGH CONCURRENCY TOO MUCH CPU UTILIZATION AND PARALLEL 
     QUERY IS FAILING WITH ORA-12872, this bug is currently waiting on two other bugs to be resolved first. 
  Solution
    †Bug is not resolved as of yet but what has been able to get by the issue is setting the following parameter:
       alter system set "_nlj_batching_enabled"=0;
  
RAC: ORA-12801 and ORA-12850: Could Not Allocate Slaves On All Specified Instances: 2 Needed, 1 (Doc ID 1503358.1)
Blog: ORA-12850: Could not allocate slaves on all specified instances error and a workaround for my scripts talked about GV$ views for reading cluster-wide ASH data and PX slaves used for fetching remote data due to Xplan temp table transformations of materialized WITH subqueries, and provided workaround of "INLINE" hint in some TPT scripts.

The ORA-12850 indicates the limitation of materialized WITH subquery in Oracle 19c RAC installations because of GV$ view access.
This Blog test shows the limitation of materialized WITH subquery in parallel statements (non RAC).

Blog: Oracle WITH subquery_factoring_clause TEMP TABLE TRANSFORMATION and log file sync talked about "INLINE" hint in materialized WITH subqueries and log file sync.


Appendix-1. Oracle Error Document


ORA-12850, "Could not allocate slaves on all specified instances: %s needed, %s allocate d"
  *Cause: When executing a query on a gv$ fixed view, one or more                                                  
          instances failed to allocate a slave to process query.                                                   
  *Action:Check trace output for instances on which slaves failed to start.                                        
          GV$ query can only proceed if slaves can be allocated on all                                             
          instances.  
          
ORA-12872, "First slave parse gave different plan"                                                               
  *Cause: First hard parse on slave given QC-supplied environment and                                              
          parameters gave different plan from QC. Try again with outline.                                          
  *Action: No external action. Internally used for outline-based reparse.                                          

ORA-12842, "Cursor invalidated during parallel execution"
  *Cause:  The cursor was invalidated during the parse phase of deferred
           parallel processing, e.g. when set operands are parallelized.
  *Action: Depends on why the cursor was invalidated. Possible causes include
           DDL on a schema object and shared pool being flushed.

ORA-10388, "parallel query server interrupt (failure)"
  *Cause: internal use only
  *Action: this event should never be set externally
  *Comment: commands a slave to leave the server group (query failed)

  The ORA-10388 is an internal oracle message to terminate a parallel query when the operation is failed.
  This message should not be visible in alert.log

ORA-10387, "parallel query server interrupt (normal)"
  *Cause: internal use only
  *Action: this event should never be set externally
  *Comment: commands a slave to leave the server group normally

ORA-10382,  "parallel query server interrupt (reset)"            
  *Cause: internal use only                                       
  *Action: this event should never be set externally              
  *Comment: commands a slave to clear its buffers and reset itself


Appendix-2. Xplan



SQL_ID  3z4qz1d4taabm, child number 0
-------------------------------------
WITH SQ AS (SELECT /*+ materialize  */ X FROM TEST_TAB) SELECT /*+ 
parallel(2) */ T.X FROM TEST_TAB T, SQ WHERE ROWNUM <= :B1
 
Plan hash value: 1215440870
 
---------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                              | Name                        | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
---------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                       |                             |       |       |   170 (100)|          |        |      |            |
|   1 |  TEMP TABLE TRANSFORMATION             |                             |       |       |            |          |        |      |            |
|   2 |   PX COORDINATOR                       |                             |       |       |            |          |        |      |            |
|   3 |    PX SEND QC (RANDOM)                 | :TQ10000                    |   327 |  4251 |     2   (0)| 00:00:01 |  Q1,00 | P->S | QC (RAND)  |
|   4 |     LOAD AS SELECT (TEMP SEGMENT MERGE)| SYS_TEMP_0FD9D664E_DBF2D292 |       |       |            |          |  Q1,00 | PCWP |            |
|   5 |      PX BLOCK ITERATOR                 |                             |   327 |  4251 |     2   (0)| 00:00:01 |  Q1,00 | PCWC |            |
|*  6 |       TABLE ACCESS FULL                | TEST_TAB                    |   327 |  4251 |     2   (0)| 00:00:01 |  Q1,00 | PCWP |            |
|*  7 |   COUNT STOPKEY                        |                             |       |       |            |          |        |      |            |
|   8 |    PX COORDINATOR                      |                             |       |       |            |          |        |      |            |
|   9 |     PX SEND QC (RANDOM)                | :TQ20001                    |   106K|  1357K|   168   (0)| 00:00:01 |  Q2,01 | P->S | QC (RAND)  |
|* 10 |      COUNT STOPKEY                     |                             |       |       |            |          |  Q2,01 | PCWC |            |
|  11 |       MERGE JOIN CARTESIAN             |                             |   106K|  1357K|   168   (0)| 00:00:01 |  Q2,01 | PCWP |            |
|  12 |        PX BLOCK ITERATOR               |                             |   327 |  4251 |     2   (0)| 00:00:01 |  Q2,01 | PCWC |            |
|* 13 |         TABLE ACCESS FULL              | TEST_TAB                    |   327 |  4251 |     2   (0)| 00:00:01 |  Q2,01 | PCWP |            |
|  14 |        BUFFER SORT                     |                             |   327 |       |   166   (0)| 00:00:01 |  Q2,01 | PCWP |            |
|  15 |         PX RECEIVE                     |                             |   327 |       |            |          |  Q2,01 | PCWP |            |
|  16 |          PX SEND BROADCAST             | :TQ20000                    |   327 |       |            |          |  Q2,00 | P->P | BROADCAST  |
|  17 |           VIEW                         |                             |   327 |       |            |          |  Q2,00 | PCWP |            |
|  18 |            PX BLOCK ITERATOR           |                             |   327 |  4251 |     2   (0)| 00:00:01 |  Q2,00 | PCWC |            |
|* 19 |             TABLE ACCESS FULL          | SYS_TEMP_0FD9D664E_DBF2D292 |   327 |  4251 |     2   (0)| 00:00:01 |  Q2,00 | PCWP |            |
---------------------------------------------------------------------------------------------------------------------------------------------------
 
Query Block Name / Object Alias (identified by operation id):
-------------------------------------------------------------
 
   1 - SEL$2       
   2 - SEL$1       
   6 - SEL$1        / TEST_TAB@SEL$1
  13 - SEL$2        / T@SEL$2
  17 - SEL$D67CB2D2 / SQ@SEL$2
  19 - SEL$D67CB2D2 / T1@SEL$D67CB2D2
 
Outline Data
-------------
  /*+
      BEGIN_OUTLINE_DATA
      IGNORE_OPTIM_EMBEDDED_HINTS
      OPTIMIZER_FEATURES_ENABLE('19.1.0')
      DB_VERSION('19.1.0')
      OPT_PARAM('optimizer_dynamic_sampling' 1)
      OPT_PARAM('_optimizer_use_feedback' 'false')
      OPT_PARAM('_optimizer_gather_stats_on_load' 'false')
      OPT_PARAM('_px_adaptive_dist_method' 'off')
      OPT_PARAM('_optimizer_strans_adaptive_pruning' 'false')
      OPT_PARAM('_optimizer_nlj_hj_adaptive_join' 'false')
      OPT_PARAM('optimizer_index_cost_adj' 50)
      OPT_PARAM('optimizer_index_caching' 95)
      OPT_PARAM('_fix_control' '23473108:0 20424684:0 22582700:0')
      ALL_ROWS
      OUTLINE_LEAF(@"SEL$1")
      OUTLINE_LEAF(@"SEL$D67CB2D2")
      MATERIALIZE(@"SEL$1")
      OUTLINE_LEAF(@"SEL$2")
      FULL(@"SEL$2" "T"@"SEL$2")
      NO_ACCESS(@"SEL$2" "SQ"@"SEL$2")
      LEADING(@"SEL$2" "T"@"SEL$2" "SQ"@"SEL$2")
      USE_MERGE_CARTESIAN(@"SEL$2" "SQ"@"SEL$2")
      PQ_DISTRIBUTE(@"SEL$2" "SQ"@"SEL$2" NONE BROADCAST)
      FULL(@"SEL$D67CB2D2" "T1"@"SEL$D67CB2D2")
      FULL(@"SEL$1" "TEST_TAB"@"SEL$1")
      END_OUTLINE_DATA
  */
Peeked Binds (identified by position):
--------------------------------------
   1 - :B1 (NUMBER): 3
 
Predicate Information (identified by operation id):
---------------------------------------------------
   6 - access(:Z>=:Z AND :Z<=:Z)
   7 - filter(ROWNUM<=:B1)
  10 - filter(ROWNUM<=:B1)
  13 - access(:Z>=:Z AND :Z<=:Z)
  19 - access(:Z>=:Z AND :Z<=:Z)
 
Hint Report (identified by operation id / Query Block Name / Object Alias):
Total hints for statement: 2
---------------------------------------------------------------------------
   0 -  STATEMENT
           -  parallel(2)
 
   2 -  SEL$1
           -  materialize
Note
-----
   - Degree of Parallelism is 2 because of hint