Oracle Multi-Consumer AQ dequeue with dbms_aq.listen Performance Analysis and Workaround (III)

Wait Events (I)           Performance Model (II)           Performance Analysis and Workaround (III)     

---

In the first Blog (I), we made test to show Wait Events: "library cache: mutex X" on queue object and "latch free" on Latch "channel operations parent latch".

In the second Blog (II), we first performed dequeue trace by GDB. Based on test output, we built Latch and Mutex model, examined it against real DB stats and subsequently revealed implementation problems.

In this third Blog (III), we will trace dequeue operation with different number of parallel sessions in Dtrace, present the performance stats, and evaluate Blog (II) model against real DB stats.

We conclude the Blogs with workaround (fix) for identified "library cache: mutex X" and "latch free".

Note: tested on Oracle 19.7 in Solaris.

1. Single Message Dequeue Latch and Mutex

Same as Blog (II), we first get child latch and mutex addr as follows:

select addr from v$latch_children where latch#=98 and child#=144;
    -- D371C240

select kglhdmtx, kglhdadr, v.* from  sys.x_KGLOB v where kglnaobj = 'MSG_QUEUE_MULTIPLE';  
    -- 99CF9A20	 99CF98D0

Then we compose below Dtrace script:

sudo dtrace -n \
'
 BEGIN{
   LATCHCHD_ADDR = 0XD371C240;
   KGLHDMTX_ADDR = 0X99CF9A20;
   l_get_seq = 0; l_rel_seq = 0;
   m_get_seq = 0; m_rel_seq = 0}
   
 pid$target:oracle:ksl_get_shared_latch:entry /arg0 == LATCHCHD_ADDR/  
  {printf("Latch Get Seq: %d --- %s (Addr=>0x%X, Mode=>%d)", ++l_get_seq, probefunc, arg0, arg4)}
  
 pid$target:oracle:kslfre:entry /arg0 == LATCHCHD_ADDR/  
  {printf("Latch Fre Seq: %d-%d --- %s (Addr=>0x%X)", l_get_seq, ++l_rel_seq, probefunc, arg0)}

 pid$target:oracle:kglGetMutex:entry /arg1 == KGLHDMTX_ADDR/ 
  {printf("Mutex Get Seq: %d --- %s (KGLHDMTX_ADDR=>0x%X, Location=>%d, KGLLKHDL_ADDR=>0x%X)", ++m_get_seq, probefunc, arg1, arg4, arg5);}
 
 pid$target:oracle:kglReleaseMutex:entry /arg1 == KGLHDMTX_ADDR/ 
  {printf("Mutex Rel Seq: %d-%d --- %s (KGLHDMTX_ADDR=>0x%X)", m_get_seq, ++m_rel_seq, probefunc, arg1);}

 END{printf("Total Counters: Latch GETs: %d, Latch FREs: %d, Mutex GETs: %d, Mutex RELs: %d", l_get_seq, l_rel_seq, m_get_seq, m_rel_seq)}
' -p 7476

Open one Sqlplus session (UNIX process Pid: 7476), enqueue one message:

SQL > exec enq(1);

Then start above Dtrace script on process Pid: 7476.
On Sqlplus session, run:

SQL > exec listen_deq(1);

Here Dtrace output:

  Mutex Get Seq: 1 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>1, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 1-1 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Rel Seq: 1-2 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Rel Seq: 1-3 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 2 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>4, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 2-4 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 3 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>90, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Get Seq: 4 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>71, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 4-5 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Rel Seq: 4-6 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 5 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>95, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 5-7 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 6 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>85, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 6-8 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Latch Get Seq: 1 --- ksl_get_shared_latch (Addr=>0xD371C240, Mode=>16)
  Latch Fre Seq: 1-1 --- kslfre (Addr=>0xD371C240)
  Mutex Get Seq: 7 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>1, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 7-9 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Rel Seq: 7-10 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Rel Seq: 7-11 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 8 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>4, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 8-12 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 9 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>90, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Get Seq: 10 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>71, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 10-13 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Rel Seq: 10-14 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 11 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>95, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 11-15 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 12 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>85, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 12-16 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Latch Get Seq: 2 --- ksl_get_shared_latch (Addr=>0xD371C240, Mode=>16)
  Latch Fre Seq: 2-2 --- kslfre (Addr=>0xD371C240)
  Latch Get Seq: 3 --- ksl_get_shared_latch (Addr=>0xD371C240, Mode=>16)
  Latch Fre Seq: 3-3 --- kslfre (Addr=>0xD371C240)
  Mutex Get Seq: 13 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>1, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 13-17 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 14 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>4, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 14-18 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 15 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>90, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Get Seq: 16 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>71, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Get Seq: 17 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>72, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 17-19 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Rel Seq: 17-20 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Get Seq: 18 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>95, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 18-21 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  
  Total Counters: Latch GETs: 3, Latch FREs: 3, Mutex GETs: 18, Mutex RELs: 21

Above output shows the number of Latch and Mutex GET/FREE (RELEASE) for one message dequeue when it is running alone (without any interference):

  Latch GETs: 3
  Latch FREs: 3
  Mutex GETs: 18
  Mutex RELs: 21

We can see that for one single message dequeue, we need 3 Latch GETs and also 3 subsequent Latch FREEs (GET and FREE are matched pair).

But for Mutex, there are 18 GETS, but 21 RELs. These are due to consecutive Mutex GETs in different Locations, for example:

  Mutex Get Seq: 3 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>90, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Get Seq: 4 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>71, KGLLKHDL_ADDR=>0x99CF98D0)

and consecutive Mutex RELs in different Locations, for example:

  Mutex Get Seq: 1 --- kglGetMutex (KGLHDMTX_ADDR=>0x99CF9A20, Location=>1, KGLLKHDL_ADDR=>0x99CF98D0)
  Mutex Rel Seq: 1-1 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Rel Seq: 1-2 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)
  Mutex Rel Seq: 1-3 --- kglReleaseMutex (KGLHDMTX_ADDR=>0x99CF9A20)

Above Latch and Mutex Gets are the same as GDB test outcome in previous Blog (II) for one single message dequeue:

   3   Latch Gets         (ksl_get_shared_latch)
   18  Mutex Gets         (kglGetMutex)

Blog (II) gdb trace shows the same mutex behaviour (consecutive Mutex GETs/RELs):

===== Mutext Get Seq: 3 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>90) --
===== Mutext Get Seq: 4 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>71) --

===== Lock Get Seq: 1 -- kgllkal (kgllkhdl Addr(rdx)=>98417B58, Mode(rcx)=>2), kglnaobj_and_schema: MSG_QUEUE_MULTIPLEK --
===== Mutext Rel Seq: 1-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
===== Mutext Rel Seq: 1-2 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
===== Mutext Rel Seq: 1-3 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --

2. Parallel Session Test

Above test shows the minimum number of Latch and Mutex GET/FREE (RELEASE) for one single message dequeue. We will continue our dequeue test in parallel sessions and monitor Latch and Mutex behaviour.

At first, we compose a Dtrace to collect test stats (see Section 5. Dtrace Script).

Then start Dtrace on Sqlplus session (process Pid: 7476), and run following test:

----------------- Parallel Sessions = 4 -----------------
begin
  clearup_test;
  purge_queue_table;
  start_enq_jobs(4, 60);
  start_deq_jobs(3, 1, 60);
  sel_deq_loop(4, 1, 60);
end;
/

-- Output
--   Listener Deq Execs (SUC and Failed) = 9420, Duration (seconds) = 60

It starts 4 enqueue Job sessions, of which first 3 dequeue Jobs for first 3 enqueue sessions for 60 seconds, and this Sqlplus dequeue session for 4th enqueue session for 60 seconds.

After test run, we collect dequeue stats by query:

-- For each RUN, only select last corr_id, which is the traced session

select corr_id, count(*), min(enq_time), max(enq_time), min(deq_time), max(deq_time),
       (max(enq_time)- min(enq_time))*86400 enq_delta, (max(deq_time) - min(deq_time))*86400 deq_delta
from aq$MultiConsumerMsgs_qtab 
where corr_id = (select 'KSUB_'||count(distinct corr_id) from aq$MultiConsumerMsgs_qtab) 
  and deq_time is not null and msg_state = 'PROCESSED' 
group by corr_id order by 1;

  CORR_ID    COUNT(*)   MIN(ENQ_TIM  MAX(ENQ_TIM  MIN(DEQ_TIM  MAX(DEQ_TIM  ENQ_DELTA   DEQ_DELTA
  ---------- ---------- -----------  -----------  -----------  -----------  ----------  ----------
  KSUB_4     9420       10:56:41     10:57:41     10:56:41     10:57:41     60          60

and extract Latch and Mutex stats from Dtrace output:

  L_CNTGET   ksl_get_shared_latch =       155,862
  L_AVG                average_ns =         2,834
  ALL_MUTEX_GETs      kglGetMutex =       415,825
  ALL_MUTEX_FREs  kglReleaseMutex =       533,074
  M_AVG                average_ns =         4,306

Above output shows that during 60 seconds, one session (KSUB_4) dequeued 9420 messages.

  There are 155,862 Latch GETs, which is much higher than (9420 * 3 = 28,260) if they were dequeued without parallel sessions.
  There are 415,825 Mutex GETs, which is much higher than (9420 * 18 = 169,560) if they were dequeued without parallel sessions.
  Latch Average GET takes 2,834 ns, which is varied between 1,024 and 524,288 ns (see L_QUANT in Section 5.1 Dtrace Output).
  Mutex Average GET takes 4,306 ns, which is varied between 2,048 and 8,388,608 ns (see M_QUANT in Section 5.1 Dtrace Output).

We run one more test with 64 parallel Sessions and compare the performance:

----------------- Parallel Sessions = 64-----------------
begin
  clearup_test;
  purge_queue_table;
  start_enq_jobs(64, 60);
  start_deq_jobs(63, 1, 60);
  sel_deq_loop(64, 1, 60);
end;
/

  CORR_ID    COUNT(*)   MIN(ENQ_TIM  MAX(ENQ_TIM  MIN(DEQ_TIM  MAX(DEQ_TIM  ENQ_DELTA   DEQ_DELTA
  ---------- ---------- -----------  -----------  -----------  -----------  ----------  ----------
  KSUB_64    667        11:18:41     11:19:41     11:18:48     11:19:41     60          53

  L_CNTGET  ksl_get_shared_latch =        93,584
  L_AVG               average_ns =        29,496
  ALL_MUTEX_GETs     kglGetMutex =       258,710
  ALL_MUTEX_FREs kglReleaseMutex =       343,015
  M_AVG               average_ns =        40,750  

Above output shows that during 60 seconds, one session (KSUB_64) dequeued 667 messages.

  There are 93,584 Latch GETs, which is much higher than (667 * 3 = 2,001) if they were dequeued without parallel sessions.
  There are 258,710 Mutex GETs, which is much higher than (667 * 18 = 12,006) if they were dequeued without parallel sessions.
  Latch Average GET takes 29,496 ns, which is varied between 1,024 and 268,435,456 ns (see L_QUANT in Section 5.2 Dtrace Output).
  Mutex Average GET takes 40,750 ns, which is varied between 2,048 and 536,870,912 ns (see M_QUANT in Section 5.2 Dtrace Output).

For full Dtrace output, see Section 5.1 Dtrace Output for 4-Parallel Sessions. and Section 5.2 for 64-Parallel Sessions.

3. Test Stats for different number of Parallel Sessions

We run the same test for 1, 2, 4. 8, 16, 32, 64 Parallel Sessions. Here the performance stats.

Dequeue Stats

Dequeue Stats

RUN PX  CORR_ID  COUNT(*)  MIN(ENQ_TIM)  MAX(ENQ_TIM)  MIN(DEQ_TIM)  MAX(DEQ_TIM)  ENQ_DELTA  DEQ_DELTA
--- --  -------  --------  ------------  ------------  ------------  ------------  ---------  ---------
1   1   KSUB_1   11,884    10:49:17      10:50:17      10:49:17      10:50:16       60        59
2   2   KSUB_2   11,640    10:53:24      10:54:24      10:53:24      10:54:24       60        60
3   4   KSUB_4    9,420    10:56:41      10:57:41      10:56:41      10:57:41       60        60
4   8   KSUB_8    6,519    10:59:02      11:00:02      10:59:02      11:00:01       60        59
5   16  KSUB_16   3,181    11:02:08      11:03:08      11:02:08      11:03:07       60        59
6   32  KSUB_32   1,441    11:04:38      11:05:38      11:04:39      11:05:37       60        58
7   64  KSUB_64     667    11:18:41      11:19:41      11:18:48      11:19:41       60        53

Note: PX column: number of parallel sessions

Latch Stats (ns_Per_Latch_Get is Dtrace L_AVG (nanosecond))

RUN PX  MSGs    Total_MSGs  Latch_Gets  Total_Latch_Gets  ns_Per_Latch_Get  Latch_Gets_per_deq  Latch_ns_per_Deq
--- --  ------  ----------  ----------  ----------------  ----------------  ------------------  ----------------
1   1   11,884  11,884      108,318     108,318           2,497             9                   22,759   
2   2   11,640  23,280      148,303     296,606           2,562             13                  32,642   
3   4    9,420  37,680      155,862     623,448           2,834             17                  46,891   
4   8    6,519  52,152      243,571     1,948,568         3,969             37                  148,295  
5   16   3,181  50,896      187,259     2,996,144         6,699             59                  394,357  
6   32   1,441  46,112      138,192     4,422,144         10,954            96                  1,050,489
7   64     667  42,688      93,584      5,989,376         29,496            140                 4,138,461

(Latch_ns_per_Deq = ns_Per_Latch_Get * Latch_Gets_per_deq)

Muext Stats (ns_Per_Mutex_Get is Dtrace M_AVG (nanosecond))

RUN PX  MSGs    Total_MSGs  Mutex_Gets  Total_Mutex_Gets  ns_Per_Mutex_Get  Mutex_Gets_per_deq  Mutex_ns_per_Deq     
--- --  ------  ----------  ----------  ----------------  ----------------  ------------------  ----------------
1   1   11,884  11,884      361,105     361,105           3,438             30                  104,466   
2   2   11,640  23,280      429,493     858,986           3,629             37                  133,903   
3   4    9,420  37,680      415,825     1,663,300         4,306             44                  190,079   
4   8    6,519  52,152      630,757     5,046,056         5,337             97                  516,391   
5   16   3,181  50,896      497,035     7,952,560         9,033             156                 1,411,417 
6   32   1,441  46,112      380,492     12,175,744        17,947            264                 4,738,855 
7   64     667  42,688      258,710     16,557,440        40,750            388                 15,805,746

(Mutex_ns_per_Deq = ns_Per_Mutex_Get * Mutex_Gets_per_deq)

We can see that total dequeue throughput (Total_MSGs) is linearly increased with number of Parallel Sessions till 8 Parallel Sessions with maximum reached (Total_MSGs = 52,152).

Total number of Latch GETS (Total_Latch_Gets) and Mutex GETs (Total_Mutex_Gets) per dequeue are almost linearly increased with number of Parallel Sessions.

Latch and Mutex GET time per dequeue (Latch_ns_per_Deq and Mutex_ns_per_Deq, in nanosecond) are increased much faster when number of Parallel Sessions is more than 8.

For example, compare Mutex_ns_per_Deq for Parallel 32 vs. 16, number of Parallel Sessions increased 2 times, but duration increased more than 3 times (4,738,855/1,411,417 = 3.36).

Comparing above DB stats with Blog (II) model, we can see the model are approximative, but closed to real DB stats.

If we draw a graphic chart with test stats, we can see the similar trend as model formulas.

3.1 Test Outputs

Here all the parallel tests and stats details.

----------------- 1 Session -----------------
begin
  clearup_test;
  purge_queue_table;
  start_enq_jobs(1, 60);
  sel_deq_loop(1, 1, 60);
end;
/

L_CNTGET   ksl_get_shared_latch =       108318
L_AVG                average_ns =         2497
ALL_MUTEX_GETs      kglGetMutex =       361105
ALL_MUTEX_FREs  kglReleaseMutex =       445357
M_AVG                average_ns =         3438

KSUB_1	11884	10:49:17	10:50:17	10:49:17	10:50:16	60	59

----------------- 2 Parallel Sessions -----------------
begin
  clearup_test;
  purge_queue_table;
  start_enq_jobs(2, 60);
  start_deq_jobs(1, 1, 60);
  sel_deq_loop(2, 1, 60);
end;
/

L_CNTGET  ksl_get_shared_latch =       148303
L_AVG               average_ns =         2562
ALL_MUTEX_GETs     kglGetMutex =       429493
ALL_MUTEX_FREs kglReleaseMutex =       539133
M_AVG               average_ns =         3629

KSUB_2	11640	10:53:24	10:54:24	10:53:24	10:54:24	60	60

----------------- 4 Parallel Sessions -----------------
begin
  clearup_test;
  purge_queue_table;
  start_enq_jobs(4, 60);
  start_deq_jobs(3, 1, 60);
  sel_deq_loop(4, 1, 60);
end;
/

L_CNTGET  ksl_get_shared_latch =       155862
L_AVG               average_ns =         2834
ALL_MUTEX_GETs     kglGetMutex =       415825
ALL_MUTEX_FREs kglReleaseMutex =       533074
M_AVG               average_ns =         4306

KSUB_4	9420	10:56:41	10:57:41	10:56:41	10:57:41	60	60

----------------- Parallel Sessions = 8 -----------------
begin
  clearup_test;
  purge_queue_table;
  start_enq_jobs(8, 60);
  start_deq_jobs(7, 1, 60);
  sel_deq_loop(8, 1, 60);
end;
/

L_CNTGET  ksl_get_shared_latch =       243571
L_AVG               average_ns =         3969
ALL_MUTEX_GETs     kglGetMutex =       630757
ALL_MUTEX_FREs kglReleaseMutex =       822641
M_AVG               average_ns =         5337

KSUB_8	6519	10:59:02	11:00:02	10:59:02	11:00:01	60	59

----------------- 16 Parallel Sessions -----------------
begin
  clearup_test;
  purge_queue_table;
  start_enq_jobs(16, 60);
  start_deq_jobs(15, 1, 60);
  sel_deq_loop(16, 1, 60);
end;
/

L_CNTGET  ksl_get_shared_latch =       187259
L_AVG               average_ns =         6699
ALL_MUTEX_GETs     kglGetMutex =       497035
ALL_MUTEX_FREs kglReleaseMutex =       653138
M_AVG               average_ns =         9033

KSUB_16	3181	11:02:08	11:03:08	11:02:08	11:03:07	60	59

----------------- 32 Parallel Sessions -----------------
begin
  clearup_test;
  purge_queue_table;
  start_enq_jobs(32, 60);
  start_deq_jobs(31, 1, 60);
  sel_deq_loop(32, 1, 60);
end;
/

L_CNTGET  ksl_get_shared_latch =       138192
L_AVG               average_ns =        10954
ALL_MUTEX_GETs     kglGetMutex =       380492
ALL_MUTEX_FREs kglReleaseMutex =       503141
M_AVG               average_ns =        17947

KSUB_32	1426	11:04:38	11:05:38	11:04:39	11:05:37	60	58

----------------- Parallel Sessions = 64-----------------
begin
  clearup_test;
  purge_queue_table;
  start_enq_jobs(64, 60);
  start_deq_jobs(63, 1, 60);
  sel_deq_loop(64, 1, 60);
end;
/

L_CNTGET  ksl_get_shared_latch =        93584
L_AVG               average_ns =        29496
ALL_MUTEX_GETs     kglGetMutex =       258710
ALL_MUTEX_FREs kglReleaseMutex =       343015
M_AVG               average_ns =        40750

KSUB_63	667	11:18:41	11:19:41	11:18:48	11:19:41	60	53

4. Workaround

To mitigate "library cache: mutex X" on queue object, we can mark hot object as follows:

select object_name, namespace from dba_objects where object_name = 'MSG_QUEUE_MULTIPLE';
  -- MSG_QUEUE_MULTIPLE	10

alter system set "_kgl_hot_object_copies"= 254 scope=spfile;

alter system set "_kgl_debug"= "name='MSG_QUEUE_MULTIPLE' schema='K' namespace=10 debug=33554432" scope=spfile;

  -- See Blog: "library cache: mutex X" and Application Context 
  --           (http://ksun-oracle.blogspot.com/2016/11/library-cache-mutex-x-and-application.html)

To workaround "latch free" on Latch "channel operations parent latch", we use subscriber instead of dbms_aq.listen. See Blog (I) - procedure subscr_deq

In Blog (I), we created 100 subscribers by "create_subscribers('msg_queue_multiple', 100)". If a subscriber does not exist, Oracle temporarily creates one and use it for enqueue and dequeue, for example:

begin
  for i in 1..1035 loop
    enq(9990000+i);
    listen_deq(9990000+i, 10); 
  end loop;
end;
/

-- only 1024 rows are listed, not all of 1035 rows are exposed v$persistent_subscribers.
select count(*) from v$persistent_subscribers where queue_name = 'MSG_QUEUE_MULTIPLE' and subscriber_name like 'KSUB_999%';
  -- 1024

select count(*) from v$persistent_subscribers where queue_name = 'MSG_QUEUE_MULTIPLE' and subscriber_name NOT like 'KSUB_999%';
  -- 100
  
select count(*) from dba_queue_subscribers where queue_name = 'MSG_QUEUE_MULTIPLE' and consumer_name like 'KSUB_999%';
  -- 0

select count(*) from dba_queue_subscribers where queue_name = 'MSG_QUEUE_MULTIPLE' and consumer_name NOT like 'KSUB_999%';
  -- 100
  
-- all messages are stored in queue table
select * from multiconsumermsgs_qtab where corrid like 'KSUB_999%' order by corrid;

Then we can see 1024 new subscribers with name like 'KSUB_999%' (maximum 1024 kept even 1035 created).

The temporarily created subscribers are visible in v$persistent_subscribers (not all of them are exposed v$persistent_subscribers), but not stored in dba_queue_subscribers.

dba_queue_subscribers contains list of subscribers on all queues. They are created by dbms_aqadm add_subscriber and can be removed by dbms_aqadm.remove_subscriber. They are persistent after DB restart.

The maximum number of subscribers per queue is 1024, and error is:

  maximum 1024:  ORA-24067: exceeded maximum number of subscribers for queue MSG_QUEUE_MULTIPLE

     See Blog: One Test of ORA-00600: [KGL-heap-size-exceeded] With AQ Subscriber 
        (http://ksun-oracle.blogspot.com/2023/03/one-test-of-ora-00600-kgl-heap-size.html)

According to Oracle Docu, v$persistent_subscribers displays information about all active subscribers of the persistent queues in the database
(above test shows that is not the case, only 1024 0f 1035 active subscribers are exposed in v$persistent_subscribers).
There is one row per instance per queue per subscriber. The rows are deleted when the database restarts.

So it is better to use pre-defined and limited number of subscribers to improved performance.

5. Dtrace Output for Parallel Sessions

5.1 4-Parallel Sessions

----------------- 4 Parallel Sessions -----------------

BEGIN at 10:56:31
END   at 10:57:49

ELAPSED_Seconds = 77
------------------ Latch Child Stats ------------------
L_GET_CNT  = 155862
L_TOTAL_NS = 441736077
L_CNTGET ksl_get_shared_latch =       155862
L_CNTFRE               kslfre =       155862
L_AVG              average_ns =         2834
L_QUANT          quantize_ns  =
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@@@@@@@@@@@@@@@                 94257
            2048 |@@@@@@@@@@@                              42290
            4096 |@@@@                                     17383
            8192 |                                         1127
           16384 |                                         287
           32768 |                                         158
           65536 |                                         337
          131072 |                                         17
          262144 |                                         2
          524288 |                                         4
         1048576 |                                         0

------------------ Mutex Stats ------------------
ALL_MUTEX_GETs      kglGetMutex =       415825
ALL_MUTEX_FREs      kglReleaseMutex =       533074

M_GET_CNT  = 339405
M_TOTAL_NS = 1461574177
M_CNTGET          kglGetMutex,   21 (Mode) =            1
M_CNTGET          kglGetMutex,  109 (Mode) =            1
M_CNTGET          kglGetMutex,  112 (Mode) =            1
M_CNTGET          kglGetMutex,    6 (Mode) =            2
M_CNTGET          kglGetMutex,   28 (Mode) =            2
M_CNTGET          kglGetMutex,   75 (Mode) =            2
M_CNTGET          kglGetMutex,  106 (Mode) =            2
M_CNTGET          kglGetMutex,  157 (Mode) =            2
M_CNTGET          kglGetMutex,   85 (Mode) =        62185
M_CNTGET          kglGetMutex,    1 (Mode) =        69301
M_CNTGET          kglGetMutex,    4 (Mode) =        69302
M_CNTGET          kglGetMutex,   90 (Mode) =        69302
M_CNTGET          kglGetMutex,   95 (Mode) =        69302
M_CNTFRE      kglReleaseMutex =       339405
M_AVG              average_ns =         4306
M_QUANT           quantize_ns =
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@             235503
            4096 |@@@@@@@@@@@@                             98902
            8192 |                                         3262
           16384 |                                         947
           32768 |                                         568
           65536 |                                         119
          131072 |                                         44
          262144 |                                         14
          524288 |                                         12
         1048576 |                                         9
         2097152 |                                         6
         4194304 |                                         5
         8388608 |                                         14
        16777216 |                                         0

5.2 64-Parallel Sessions

---------- Parallel Sessions = 64 ----------

BEGIN at 11:18:35
END   at 11:19:53

ELAPSED_Seconds = 77
------------------ Latch Child Stats ------------------
L_GET_CNT  = 93584
L_TOTAL_NS = -1534546885
L_CNTGET ksl_get_shared_latch =        93584
L_CNTFRE               kslfre =        93584
L_AVG              average_ns =        29496
L_QUANT          quantize_ns  =
           value  ------------- Distribution ------------- count
             512 |                                         0
            1024 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@             64970
            2048 |@@@@@@@@@                                21078
            4096 |@@                                       5382
            8192 |                                         459
           16384 |                                         680
           32768 |                                         483
           65536 |                                         302
          131072 |                                         114
          262144 |                                         26
          524288 |                                         26
         1048576 |                                         11
         2097152 |                                         9
         4194304 |                                         17
         8388608 |                                         10
        16777216 |                                         4
        33554432 |                                         4
        67108864 |                                         4
       134217728 |                                         3
       268435456 |                                         2
       536870912 |                                         0

------------------ Mutex Stats ------------------
ALL_MUTEX_GETs      kglGetMutex =       258710
ALL_MUTEX_FREs      kglReleaseMutex =       343015

M_GET_CNT  = 214951
M_TOTAL_NS = 169358324
M_CNTGET          kglGetMutex,   21 (Mode) =            1
M_CNTGET          kglGetMutex,   75 (Mode) =            1
M_CNTGET          kglGetMutex,  157 (Mode) =            1
M_CNTGET          kglGetMutex,    6 (Mode) =            2
M_CNTGET          kglGetMutex,   28 (Mode) =            2
M_CNTGET          kglGetMutex,  106 (Mode) =            2
M_CNTGET          kglGetMutex,   85 (Mode) =        42475
M_CNTGET          kglGetMutex,    1 (Mode) =        43116
M_CNTGET          kglGetMutex,    4 (Mode) =        43117
M_CNTGET          kglGetMutex,   90 (Mode) =        43117
M_CNTGET          kglGetMutex,   95 (Mode) =        43117
M_CNTFRE      kglReleaseMutex =       214951
M_AVG              average_ns =        40750
M_QUANT           quantize_ns =
           value  ------------- Distribution ------------- count
            1024 |                                         0
            2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@          166007
            4096 |@@@@@@@@                                 40643
            8192 |@                                        2751
           16384 |                                         1731
           32768 |                                         1890
           65536 |                                         891
          131072 |                                         405
          262144 |                                         211
          524288 |                                         158
         1048576 |                                         73
         2097152 |                                         31
         4194304 |                                         59
         8388608 |                                         47
        16777216 |                                         17
        33554432 |                                         18
        67108864 |                                         7
       134217728 |                                         5
       268435456 |                                         5
       536870912 |                                         2
      1073741824 |                                         0

6. Dtrace Script: Latch and Mutex Stats

--------- Latch and Mutex (not consider Mutex consecutive Gets and Release) ---------

sudo dtrace -n \
'
BEGIN{
   START_TS = timestamp;
   LATCHCHD_ADDR = 0XD371C240;
   L_GET_CNT  = 0; L_TOTAL_NS = 0;
   KGLHDMTX_ADDR = 0X99CF9A20;
   M_GET_CNT  = 0; M_TOTAL_NS = 0;
   m_get = 0; m_rel = 1;       /* exclude Mutex consecutive Gets and Release */
   printf("\nBEGIN at %Y ", walltimestamp);}

 pid$target:oracle:ksl_get_shared_latch:entry /arg0 == LATCHCHD_ADDR/  
  {self->L_ts = timestamp; L_GET_CNT = L_GET_CNT + 1;
   @L_CNTGET[probefunc] = count()}
  
 pid$target:oracle:kslfre:entry /arg0 == LATCHCHD_ADDR/  
  {L_TOTAL_NS = L_TOTAL_NS + (timestamp - self->L_ts);
   @L_AVG["average_ns"]    = avg(timestamp - self->L_ts);
   @L_QUANT["quantize_ns"] = quantize(timestamp - self->L_ts);
   @L_CNTFRE[probefunc]    = count()} 

 pid$target:oracle:kglGetMutex:entry /arg1 == KGLHDMTX_ADDR/
  {@M_ALL_CNTGET[probefunc] = count();} 

 pid$target:oracle:kglReleaseMutex:entry /arg1 == KGLHDMTX_ADDR/    
  {@M_ALL_CNTFRE[probefunc] = count();}
  
 pid$target:oracle:kglGetMutex:entry /arg1 == KGLHDMTX_ADDR && m_get == 0 && m_rel == 1/
  {self->M_ts = timestamp; M_GET_CNT = M_GET_CNT + 1;
   @M_CNTGET[probefunc, arg4]        = count();
   m_get = 1; m_rel = 0}
  
 pid$target:oracle:kglReleaseMutex:entry /arg1 == KGLHDMTX_ADDR && m_get == 1 && m_rel == 0/    
  {M_TOTAL_NS = M_TOTAL_NS + (timestamp - self->M_ts); 
   @M_CNTFRE[probefunc]    = count();
   @M_AVG["average_ns"]    = avg(timestamp - self->M_ts);
   @M_QUANT["quantize_ns"] = quantize(timestamp - self->M_ts);
   m_get = 0; m_rel = 1} 
   
END{printf("\nEND at %Y\n", walltimestamp);
    printf("\nELAPSED_Seconds = %i",     (timestamp - START_TS)/1000/1000/1000);
    printf("\n------------------ Latch Child Stats ------------------");
    printf("\nL_GET_CNT  = %i",         L_GET_CNT);
    printf("\nL_TOTAL_NS = %i",         L_TOTAL_NS);
    /* printf("\nL_AVG_GET_NS = %i",       L_TOTAL_NS/L_GET_CNT);  same as L_AVG */
    printa("\nL_CNTGET %20s = %12@d",   @L_CNTGET);
    printa("\nL_CNTFRE %20s = %12@d",   @L_CNTFRE);
    printa("\nL_AVG    %20s = %12@d",       @L_AVG);
    printa("\nL_QUANT %20s  = %12@d",   @L_QUANT);
    
    printf("\n------------------ Mutex Stats ------------------");
    printa("\nALL_MUTEX_GETs %20s = %12@d",       @M_ALL_CNTGET);
    printa("\nALL_MUTEX_FREs %20s = %12@d\n",     @M_ALL_CNTFRE);
    printf("\nM_GET_CNT  = %i",                   M_GET_CNT);
    printf("\nM_TOTAL_NS = %i",                   M_TOTAL_NS);
    /* printf("\nM_AVG_GET_NS = %i",                 M_TOTAL_NS/M_GET_CNT);  same as M_AVG */
    printa("\nM_CNTGET %20s, %4d (Mode) = %12@d", @M_CNTGET);
    printa("\nM_CNTFRE %20s = %12@d",             @M_CNTFRE);
    printa("\nM_AVG    %20s = %12@d",                @M_AVG);
    printa("\nM_QUANT  %20s = %12@d",             @M_QUANT);}
' -p 7476


-- // -p $1
-- ksh ./aq_latch_mutex_dtrace 7476

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())             

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;

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).

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

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