Oracle Multi-Consumer AQ dequeue with dbms_aq.listen Performance Model (II)

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 this second Blog (II), we will make dequeue test with GDB trace. Based on test outcome, we will build Latch and Mutex model, examine it against real DB stats and subsequently reveals implementation problems.

Note: tested on Oracle 19.17 in Linux

1. Library Cache Lock/Pin, Mutex Get, Latch Get

First we compose a GDB Script to trace dequeue stats (see Section 5 GDB Script).
Then we make tests with different scenarios.

1.1 Case-1: enqueue - dequeue

Open two Sqlplus sessions (SID-1 and SID-2). In SID-2, enqueue one message, execute gdb script on UNIX process of SID-1 (UNIX process pid: 27039), then on SID-1 make dequeue.

Here all output:

(SID-2) > exec enq(1);
  11:16:29 --- enqueue Message for KSUB_1, corr_id=KSUB_1, text=11:16:29.

$ > gdb -x gdb_cmd_lm_script1 -p 27039
	
(SID-1) > exec listen_deq(1, 60);
  11:17:10 >>> dequeue Message for KSUB_1, corr_id=KSUB_1, text=11:16:29.

$ > gdb -x gdb_cmd_lm_script1 -p 27039
  11:17:10
  ===== BreakPoint: 55-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 18 ] =====

GDB output shows that for one single message dequeue, it needs:

   2   Library Cache Lock (kgllkal)
   3   Library Cache Pin  (kgllkdl)
   3   Latch Gets         (ksl_get_shared_latch)
   18  Mutex Gets         (kglGetMutex)
   55  Breakooints        (55-Counter)

For all the output details, see Section 6. GDB Output of Case-1.

1.2 Case-2: dequeue - enqueue

We first start dequeue in SID-1 and gdb its process, then enqueue one message in SID-2. Since dequeue starts first, it is waiting for message in dbms_aq.listen (with timeout 60 seconds).

Here the test output:

$ > gdb -x gdb_cmd_lm_script1 -p 27039
  
(SID-1) > exec listen_deq(1, 60);
  
$ > gdb -x gdb_cmd_lm_script1 -p 27039
  11:26:18
  ===== BreakPoint: 38-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 12 ] =====

(SID-2) > exec enq(1);
	11:26:42 --- enqueue Message for KSUB_1, corr_id=KSUB_1, text=11:26:42.
	
(SID-1) > exec listen_deq(1, 60);
  11:26:42 >>> dequeue Message for KSUB_1, corr_id=KSUB_1, text=11:26:42.
  
$ > gdb -x gdb_cmd_lm_script1 -p 27039
  11:26:42
  ===== BreakPoint: 103-Counter: [ LOCK: 4, PIN: 5, LATCH: 9, MUTEX: 30 ] =====

gdb output shows stats at wait start:

   2   Library Cache Lock (kgllkal)
   2   Library Cache Pin  (kgllkdl)
   1   Latch Gets         (ksl_get_shared_latch)
   12  Mutex Gets         (kglGetMutex)
   38  Breakooints        (38-Counter)

gdb output shows stats after message dequeued:

   4   Library Cache Lock (kgllkal)
   5   Library Cache Pin  (kgllkdl)
   9   Latch Gets         (ksl_get_shared_latch)
   30  Mutex Gets         (kglGetMutex)
   103 Breakooints        (103-Counter)

1.3 Case-3: dequeue - enqueue other corr_id - enqueue

Similar to Case-2, but we make two enqueues, the first is enqueued to other corr_id (corr_id=KSUB_31), the second is enqueued for the waiting dequeue (corr_id=KSUB_1).

We can see that the first enqueue for corr_id=KSUB_31 also wakes up dequeue, and hence Latch and Mutex stats are increased:

$ > gdb -x gdb_cmd_lm_script1 -p 27039

(SID-1) > exec listen_deq(1, 60);

$ > gdb -x gdb_cmd_lm_script1 -p 27039
  11:36:19
  ===== BreakPoint: 38-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 12 ] =====

(SID-2) > exec enq(31);
  11:36:38 --- enqueue Message for KSUB_31, corr_id=KSUB_31, text=11:36:38.

$ > gdb -x gdb_cmd_lm_script1 -p 27039
  11:36:38
  ===== BreakPoint: 86-Counter: [ LOCK: 4, PIN: 4, LATCH: 7, MUTEX: 24 ] =====

(SID-2) > exec enq(1);
  11:37:12 --- enqueue Message for KSUB_1, corr_id=KSUB_1, text=11:37:12.

(SID-1) > exec listen_deq(1, 60);
  11:37:12 >>> dequeue Message for KSUB_1, corr_id=KSUB_1, text=11:37:12.

$ > gdb -x gdb_cmd_lm_script1 -p 27039
  11:37:12
  ===== BreakPoint: 151-Counter: [ LOCK: 6, PIN: 7, LATCH: 15, MUTEX: 42 ] =====

gdb output shows stats at wait start:

   2   Library Cache Lock (kgllkal)
   2   Library Cache Pin  (kgllkdl)
   1   Latch Gets         (ksl_get_shared_latch)
   12  Mutex Gets         (kglGetMutex)
   38  Breakooints        (38-Counter)

gdb output shows the first wake-up (false wake-up) stats:

   4   Library Cache Lock (kgllkal)
   4   Library Cache Pin  (kgllkdl)
   7   Latch Gets         (ksl_get_shared_latch)
   24  Mutex Gets         (kglGetMutex)
   86  Breakooints        (86-Counter)

the second wake-up (true wake-up) stats:

   6   Library Cache Lock (kgllkal)
   7   Library Cache Pin  (kgllkdl)
   15  Latch Gets         (ksl_get_shared_latch)
   42  Mutex Gets         (kglGetMutex)
   151 Breakooints        (151-Counter)

1.4 Case-4: dequeue with timeout

We start a dequeue, but no enqueue, and then wait dequeue timeout:

$ > gdb -x gdb_cmd_lm_script1 -p 27039

(SID-1) > exec listen_deq(1, 60);

$ > gdb -x gdb_cmd_lm_script1 -p 27039
  11:42:30
  ===== BreakPoint: 38-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 12 ] =====

(SID-1) > exec listen_deq(1, 60);
  11:43:30 -- Error for KSUB_1, ORA-25254: time-out in LISTEN while waiting for a message

$ > gdb -x gdb_cmd_lm_script1 -p 27039
  11:43:30
  ===== BreakPoint: 42-Counter: [ LOCK: 2, PIN: 2, LATCH: 3, MUTEX: 12 ] =====

gdb output shows the stats at wait start:

   2   Library Cache Lock (kgllkal)
   2   Library Cache Pin  (kgllkdl)
   1   Latch Gets         (ksl_get_shared_latch)
   12  Mutex Gets         (kglGetMutex)
   38  Breakooints        (38-Counter)

gdb output shows the timeout stats:

   2   Library Cache Lock (kgllkal)
   2   Library Cache Pin  (kgllkdl)
   3   Latch Gets         (ksl_get_shared_latch)
   12  Mutex Gets         (kglGetMutex)
   42  Breakooints        (42-Counter)

2. Performance Model and Analysis

According to above test outcome, we can estimate number of Latch and Mutex Gets, and build a performance analysis model for concurrent parallel sessions.

The numbers used in model are approximative and are based on the observations of real DB stats.

We examine the model against real DB collected stats and show the deviations.

In next Blog (III), we will make tests with different number of parallel sessions, and collect exact DB Latch and Mutex stats.

2.1. Mutex and Latch Formulas

Assume N: number of Sessions
       M: number of dequeued messages
       no timeout in dequeue (no repeated get)
       each message is only dequeued once and by one specified target session
        
       MGets: Number of Mutex Gets on Queue Object
       LGets: Number of Latch Gets on LATCH#=98 (channel operations parent latch)

For one dequeue (M=1) and no concurrent session (N=1):
       MGets = 12
       LGets =  6
       
For one dequeue (M=1) and N concurrent sessions:
       MGets = 12 * N
       LGets =  6 * N

For M dequeues and N concurrent sessions:
       MGets = 12 * N * M
       LGets =  6 * N * M

2.2. Concurrency Contentions

When one Message is enqueued, all sessions waiting with dbms_aq.listen are waked up simultaneously. They are concurrently contending for the DB-wide single Mutex (on Queue Object), and single Child Latch (CHILD#=144 of LATCH#=98, LATCH#=98 has 173 Children, but only 144 is used for dbms_aq.listen on any Queues).

Hence, dbms_aq.listen artificially "synchronize" the DB-wide single resource contentions.

2.3. Examination of Latch Formula on Real DB

2.3.1 Pick following data from AWR:

		  dequeue SQL Query Executions = 96,508	
		  Enq Msgs                     = 94,551
		  Deq Msgs                     = 94,551
		          
      Latch Name                       Get Requests   Misses     Sleeps   Spin Gets
      -------------------------------  -------------  ---------	 -------  ---------
      channel operations parent latch  43,999,351     3,234,815  130,568  3,107,867

2.3.2 Compute and Compare:

      Real      LGets (rLGets) = 43,999,351	
		  Estimated LGets (eLGets) = 6 * N * M
		                           = 6 * 64 * 96,508	
		                           = 37,059,072

Due to Latch Misses and Sleeps, Estimated LGets can be adjusted as:

		  Adjusted Estimated LGets = eLGets     + Misses
		                           = 37,059,072 + 3,234,815
		                           = 40,293,887
		                           
		  Estimation Error = 43,999,351 - 40,293,887 
		                   = 3,705,464 (8.42%)

Note that Latch has recurrent_sleeps:

		
		  recurrent_sleeps = sleeps  + spin_gets ñ misses
		                   = 130,568 + 3,107,867 - 3,234,815
		                   = 3,620

Because of recurrent_sleeps, Estimated LGets can be less than Real LGets.

3. dbms_aq.listen dequeue - child latch 144

For dequeue with dbms_aq.listen, following test shows that only child# 144 of Latch "channel operations parent latch" (latch#=98) is used. Each RUN needs 3 latch GETs.

For dequeue with subscriber, no such latch is needed.

-----===== enqueue 20 messages for KSUB_1 
begin
  for i in 1..20 loop
    enq(1);
  end loop;
end;
/

-----===== dequeue 10 messages by dbms_aq.listen =====
column latch_gets new_value latch_gets_1
column latch_children_gets new_value latch_children_gets_1

select 
  (select gets from v$latch where latch#=98) latch_gets,
  (select gets from v$latch_children where latch#=98 and child# = 144) latch_children_gets
from dual;

begin
  for i in 1..10 loop
    begin
      listen_deq(1, 10); 
    EXCEPTION WHEN others THEN
	    null;  --DBMS_OUTPUT.PUT_LINE ('---------------- No more messages for KSUB_'||1);
	  end;
  end loop;
end;
/

select 
  (select gets - &latch_gets_1 from v$latch where latch#=98) latch_gets_delta,
  (select gets - &latch_children_gets_1 from v$latch_children where latch#=98 and child# = 144) latch_children_gets_delta
from dual;

LATCH_GETS_DELTA LATCH_CHILDREN_GETS_DELTA
---------------- -------------------------
              31                        30

-----===== dequeue 10 messages by subscriber =====

select 
  (select gets from v$latch where latch#=98) latch_gets,
  (select gets from v$latch_children where latch#=98 and child# = 144) latch_children_gets
from dual;


begin
  for i in 1..10 loop
    begin
      sub_deq(1, 10); 
    EXCEPTION WHEN others THEN
	    null;  --DBMS_OUTPUT.PUT_LINE ('---------------- No more messages for KSUB_'||1);
	  end;
  end loop;
end;
/

select 
  (select gets - &latch_gets_1 from v$latch where latch#=98) latch_gets_delta,
  (select gets - &latch_children_gets_1 from v$latch_children where latch#=98 and child# = 144) latch_children_gets_delta
from dual;

LATCH_GETS_DELTA LATCH_CHILDREN_GETS_DELTA
---------------- -------------------------
               1                         0

4. dequeue waiting semtimedop

If we use strace to display dequeue waiting with dbms_aq.listen, we can see that the internal timeout of 1 second ("{1, 0}"):

SQL > exec listen_deq(32, 120);

$ > strace -ttp 19009
  strace: Process 19009 attached
  15:29:36.161830 semtimedop(9928704, [{63, -1, 0}], 1, {1, 0}) = -1 EAGAIN (Resource temporarily unavailable)
  15:29:37.162159 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={2, 747478}, ru_stime={0, 322189}, ...}) = 0
  15:29:37.162333 semtimedop(9928704, [{63, -1, 0}], 1, {1, 0}) = -1 EAGAIN (Resource temporarily unavailable)
  15:29:38.162152 semtimedop(9928704, [{63, -1, 0}], 1, {1, 0}) = -1 EAGAIN (Resource temporarily unavailable)

If we use strace to display dequeue waiting with subscriber, we can see that the internal timeout of 1 second ("{3, 0}"):

SQL > exec sub_deq(32, 120);

$ > strace -ttp 19009

  strace: Process 19009 attached
  15:38:37.236174 semtimedop(9928704, [{63, -1, 0}], 1, {4, 641000}) = -1 EAGAIN (Resource temporarily unavailable)
  15:38:41.237194 getrusage(0x1 /* RUSAGE_??? */, {ru_utime={2, 764867}, ru_stime={0, 323688}, ...}) = 0
  15:38:41.237309 semtimedop(9928704, [{63, -1, 0}], 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable)
  15:38:44.237145 semtimedop(9928704, [{63, -1, 0}], 1, {3, 0}) = -1 EAGAIN (Resource temporarily unavailable)

For all 4 test cases in Section 1, we can also use strace to momitor semtimedop. In particular for Case-3 (dequeue - enqueue other corr_id - enqueue), we can see the inter-process communication between different sessions. More info about semaphores can be showed by:

$ > ipcs -s
  ------ Semaphore Arrays --------
  key        semid      owner      perms      nsems
  0xe4774fb0 9928704    oracle     600        250
  0xe4774fb1 9961473    oracle     600        250
  0xe4774fb2 9994242    oracle     600        250

$ > ipcs -s -i 9928704
$ > ipcs -l

5. GDB Script

To run appended GDB script, we first need to find following three address.

5.1 Get Queue Object Handlr Addr: KGLLKHDL_ADDR

select addr, hash_value idn,  v.* from v$db_object_cache v where name = 'MSG_QUEUE_MULTIPLE'; 
-- 98417B58  198468696

select kgllkhdl, kglhdpar, v.* from sys.x_kgllk v where kglnaobj = 'MSG_QUEUE_MULTIPLE'; 
-- 98417B58  98417B58

select object_handle, mode_held, mode_requested, v.* from v$libcache_locks v where object_handle like '%98417B58';
-- 98417B58

Lock/pin mode held in v$libcache_locks:
    0 - No lock/pin held
    1 - Null mode
    2 - Share mode
    3 - Exclusive mode

Note: we use Blog:      
  Tracing Library Cache Locks 3: Object Names (Nenad Noveljic, March 1, 2021)
    (https://nenadnoveljic.com/blog/library-cache-lock-object-name/)
to printout library object name and schema: MSG_QUEUE_MULTIPLEK 

5.2 Get Queue Object Mutex Addr: KGLHDMTX_ADDR

select kglhdmtx, kglhdadr, v.* from sys.x_kglob v where kglnaobj = 'MSG_QUEUE_MULTIPLE'; 
--KGLHDMTX=98417CA8, KGLHDADR=98417B58

-- Note: each Mutex has a number of different Locations

5.3 Get Latch 'channel operations parent latch' (Latch#=144) Top Child# Addr: LATCHCHD_ADDR

We can get Top Child# Addr by query:

select * from (
  select addr addr_144, child# child#_144, v.* from v$latch_children v 
   where latch#=98 or name = 'channel operations parent latch' order by gets desc
) where rownum = 1;  
-- B4C33CF8  144

It can also be found by following test and query:

Open two Sqlplus sessions.

-- In Session_1, run 

SQL (SID-1) > exec listen_deq(1, 120);

-- Note: For dbms_aq.listen wait, the session is waiting on event: 'wait for unread message on broadcast channel'.
--       For dbms_aq.dequeue wait, the session is waiting on event: 'Streams AQ: waiting for messages in the queue'.

-- In Session_2, run query below to display CHILD#=144:

SQL (SID-1) > with sq as (select program, event, sid, p1text, p1 from v$session where event = 'wait for unread message on broadcast channel')
              select l.addr, child#, s.program, s.sid, s.p1 p1_num, (s.p1+72) p1_num_72, to_number(l.addr, 'XXXXXXXXXXXXXXXX') child_addr_dec, l.* 
               from v$latch_children l, sq s
               where (latch#=98 or name = 'channel operations parent latch')
                 and to_number(l.addr, 'XXXXXXXXXXXXXXXX') = s.p1 + 72;
                               
-- B4C33CF8 144

-- Note: Above query shows that Oracle background SVCB is also waiting on Event "unread message on broadcast channel"
--       Probably it also dbms_aq.listen (Latch#=98,  CHILD#=36) 
--       (SVCB is supposed only for Oracle RAC, but we observed it also in non-RAC DB (Oracle Docu error)) 


-- For ksl_get_shared_latch, see Blog: 
--   Oracle 12 and latches (https://fritshoogland.wordpress.com/2015/07/17/oracle-12-and-latches/):

The kslgetl and ksl_get_shared_latch functions take the following arguments:
    1-latch address
    2-immediate get (0 means yes, 1 means no)
    3-where (X$KSLLW.INDX)
    4-why (X$KSLWSC.INDX)
    5-mode (8=shared,16=exclusive; only for ksl_get_shared_latch function)

5.4 Stats Counter

For each Get operation (kgllkal, kglpin, kglGetMutex, ksl_get_shared_latch), we increase its respective Counter by 1. For each Release operation (kgllkdl, kglpndl, kglReleaseMutex, kslfre), the respective current Counter value is used.

After each operation, we printout all 4 Counter values.

5.5 GDB Script Code

With three above addresses, we can compose following GDB script:

------------------------- gdb -x gdb_cmd_lm_script1 -p 3214 -------------------------

set pagination off
set logging file mutex-latch_test1.log
set logging overwrite on
set logging on
set $KGLLKHDL_ADDR=0X98417B58
set $KGLHDMTX_ADDR=0X98417CA8
set $LATCHCHD_ADDR=0XB4C33CF8
set $s = 0
set $k = 0, $kr = 0
set $p = 0, $pr = 0
set $l = 0, $lr = 0
set $m = 0, $mr = 0

define PrtCont
  bt $arg0
  shell date
  printf "===== BreakPoint: %i-Counter: [ LOCK: %i, PIN: %i, LATCH: %i, MUTEX: %i ] =====\n", ++$s, $k, $p, $l, $m
  continue
end

# kgllkal kglLock kglget
break *kgllkal if $rdx==$KGLLKHDL_ADDR
command
printf "===== Lock Get Seq: %i -- kgllkal (kgllkhdl Addr(rdx)=>%X, Mode(rcx)=>%X), kglnaobj_and_schema: %s --\n", ++$k, $rdx, $rcx, ($rdx+0x1c0)
set $kr = 0
PrtCont 10
end

# kgllkdl kglUnLock
break *kgllkdl if $r8==$KGLLKHDL_ADDR
command
printf "===== Lock Rel Seq: %i-%i -- kgllkdl (kgllkhdl Addr(r8)=>%X) ---\n", $k, ++$kr, $r8
PrtCont 3
end

break *kglpin if $rcx==$KGLLKHDL_ADDR
command
printf "===== Pin Get Seq: %i -- kglpin (kgllkhdl Addr(rcx)=>%X, Mode(r8)=>%X, mutex Addr(r11)=>%X)--\n", ++$p, $rcx, $r8, $r11
set $pr = 0
PrtCont 3
end

#kglUnPin
break *kglpndl if $r8==$KGLLKHDL_ADDR
command
printf "===== Pin Rel Seq: %i-%i -- kglpndl(kgllkhdl Addr(r8)=>%X) --\n", $p, ++$pr, $r8
PrtCont 3
end

break *kglGetMutex if $rsi==$KGLHDMTX_ADDR
command
printf "===== Mutext Get Seq: %i -- kglGetMutex(kglhdmtx Addr(rsi)=>%X, Location(r8)=>%i) --\n", ++$m, $rsi, $r8
set $mr = 0
PrtCont 3
end

break *kglReleaseMutex if $rsi==$KGLHDMTX_ADDR
command
printf "===== Mutext Rel Seq: %i-%i -- kglReleaseMutex(kglhdmtx Addr(rsi)=>%X, Location(r8)=>%i) --\n", $m, ++$mr, $rsi, $r8
PrtCont 3
end

break *ksl_get_shared_latch if $rdi==$LATCHCHD_ADDR
command
printf "===== Latch Get Seq: %i -- ksl_get_shared_latch Addr(Latch-98 Child-144 Addr(rdi)=>%X, Mode(r8)=>%i) --\n", ++$l, $rdi, $r8
set $lr = 0
PrtCont 3
end

# kslgetl not used

break *kslfre if $rdi==$LATCHCHD_ADDR
command
printf "===== Latch Fre Seq: %i-%i -- kslfre (Latch-98 Child-144 Addr(rdi)=>%X) --\n", $l, ++$lr, $rdi
PrtCont 3
end

6. GDB Output of Case-1

Note: "kwqilisten" is Oracle subroutine for dbms_aq.LISTEN.


===== Mutext Get Seq: 1 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>1) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130ac47e in kglLock ()
#2  0x00000000130a70c5 in kglget ()
===== BreakPoint: 1-Counter: [ LOCK: 0, PIN: 0, LATCH: 0, MUTEX: 1 ] =====

===== Lock Get Seq: 1 -- kgllkal (kgllkhdl Addr(rdx)=>98417B58, Mode(rcx)=>2), kglnaobj_and_schema: MSG_QUEUE_MULTIPLEK --
#0  0x00000000130b0b40 in kgllkal ()
#1  0x00000000130ac291 in kglLock ()
#2  0x00000000130a70c5 in kglget ()
#3  0x0000000004c04809 in kglgob ()
#4  0x0000000001b1c3ed in kwqicgob ()
#5  0x0000000001b1b7d8 in kwqicrqo0 ()
#6  0x000000000f70f1df in kwqidlqo ()
#7  0x00000000080594f7 in kwqiccllst ()
#8  0x000000000807351a in kwqilintl ()
#9  0x0000000008073c0a in kwqilisten ()
===== BreakPoint: 2-Counter: [ LOCK: 1, PIN: 0, LATCH: 0, MUTEX: 1 ] =====

===== Mutext Rel Seq: 1-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b21e7 in kglLoadOnLock ()
#2  0x00000000130b0e90 in kgllkal ()
===== BreakPoint: 3-Counter: [ LOCK: 1, PIN: 0, LATCH: 0, MUTEX: 1 ] =====

===== Mutext Rel Seq: 1-2 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b0ea0 in kgllkal ()
#2  0x00000000130ac291 in kglLock ()
===== BreakPoint: 4-Counter: [ LOCK: 1, PIN: 0, LATCH: 0, MUTEX: 1 ] =====

===== Mutext Rel Seq: 1-3 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130ac35c in kglLock ()
#2  0x00000000130a70c5 in kglget ()
===== BreakPoint: 5-Counter: [ LOCK: 1, PIN: 0, LATCH: 0, MUTEX: 1 ] =====

===== Pin Get Seq: 1 -- kglpin (kgllkhdl Addr(rcx)=>98417B58, Mode(r8)=>2, mutex Addr(r11)=>98417CA8)--
#0  0x00000000130a7e20 in kglpin ()
#1  0x0000000004c048c8 in kglgob ()
#2  0x0000000001b1c3ed in kwqicgob ()
===== BreakPoint: 6-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 1 ] =====

===== Mutext Get Seq: 2 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130a80dd in kglpin ()
#2  0x0000000004c048c8 in kglgob ()
===== BreakPoint: 7-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 2 ] =====

===== Mutext Rel Seq: 2-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>0) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130a817e in kglpin ()
#2  0x0000000004c048c8 in kglgob ()
===== BreakPoint: 8-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 2 ] =====

===== Mutext Get Seq: 3 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>90) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130b4c4f in kglpnal ()
#2  0x00000000130a82b9 in kglpin ()
===== BreakPoint: 9-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 3 ] =====

===== Mutext Get Seq: 4 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>71) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130afef5 in kglobpn ()
#2  0x00000000130aab2a in kglpim ()
===== BreakPoint: 10-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 4 ] =====

===== Mutext Rel Seq: 4-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>1) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b0200 in kglobpn ()
#2  0x00000000130aab2a in kglpim ()
===== BreakPoint: 11-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 4 ] =====

===== Mutext Rel Seq: 4-2 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>1) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130a858b in kglpin ()
#2  0x0000000004c048c8 in kglgob ()
===== BreakPoint: 12-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 4 ] =====

===== Pin Rel Seq: 1-1 -- kglpndl(kgllkhdl Addr(r8)=>98417B58) --
#0  0x00000000130b6100 in kglpndl ()
#1  0x00000000130a7756 in kglUnPin ()
#2  0x000000000f70f6bb in kwqidfqo ()
===== BreakPoint: 13-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 4 ] =====

===== Mutext Get Seq: 5 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>95) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130b63c7 in kglpndl ()
#2  0x00000000130a7756 in kglUnPin ()
===== BreakPoint: 14-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 5 ] =====

===== Mutext Rel Seq: 5-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>-2022442648) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b66c9 in kglpndl ()
#2  0x00000000130a7756 in kglUnPin ()
===== BreakPoint: 15-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 5 ] =====

===== Lock Rel Seq: 1-1 -- kgllkdl (kgllkhdl Addr(r8)=>98417B58) ---
#0  0x00000000130b34d0 in kgllkdl ()
#1  0x00000000130ae53c in kglUnLock ()
#2  0x000000000f70f6c6 in kwqidfqo ()
===== BreakPoint: 16-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 5 ] =====

===== Mutext Get Seq: 6 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>85) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130b36be in kgllkdl ()
#2  0x00000000130ae53c in kglUnLock ()
===== BreakPoint: 17-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 6 ] =====

===== Mutext Rel Seq: 6-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b39f1 in kgllkdl ()
#2  0x00000000130ae53c in kglUnLock ()
===== BreakPoint: 18-Counter: [ LOCK: 1, PIN: 1, LATCH: 0, MUTEX: 6 ] =====

===== Latch Get Seq: 1 -- ksl_get_shared_latch Addr(Latch-98 Child-144 Addr(rdi)=>B4C33CF8, Mode(r8)=>16) --
#0  0x00000000128a3a90 in ksl_get_shared_latch ()
#1  0x000000000128c4e3 in ksrsubscribe ()
#2  0x000000000f71e4fb in kwqidlisten ()
===== BreakPoint: 19-Counter: [ LOCK: 1, PIN: 1, LATCH: 1, MUTEX: 6 ] =====

===== Latch Fre Seq: 1-1 -- kslfre (Latch-98 Child-144 Addr(rdi)=>B4C33CF8) --
#0  0x00000000128aa290 in kslfre ()
#1  0x000000000128c5ae in ksrsubscribe ()
#2  0x000000000f71e4fb in kwqidlisten ()
===== BreakPoint: 20-Counter: [ LOCK: 1, PIN: 1, LATCH: 1, MUTEX: 6 ] =====

===== Mutext Get Seq: 7 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>1) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130ac47e in kglLock ()
#2  0x00000000130a70c5 in kglget ()
===== BreakPoint: 21-Counter: [ LOCK: 1, PIN: 1, LATCH: 1, MUTEX: 7 ] =====

===== Lock Get Seq: 2 -- kgllkal (kgllkhdl Addr(rdx)=>98417B58, Mode(rcx)=>2), kglnaobj_and_schema: MSG_QUEUE_MULTIPLEK --
#0  0x00000000130b0b40 in kgllkal ()
#1  0x00000000130ac291 in kglLock ()
#2  0x00000000130a70c5 in kglget ()
#3  0x0000000004c04809 in kglgob ()
#4  0x0000000001b1c3ed in kwqicgob ()
#5  0x0000000001b1b7d8 in kwqicrqo0 ()
#6  0x000000000f70f1df in kwqidlqo ()
#7  0x000000000f70f938 in kwqidlqowl ()
#8  0x0000000003f5b335 in kwqididqx ()
#9  0x000000000f705bba in kwqididq ()
===== BreakPoint: 22-Counter: [ LOCK: 2, PIN: 1, LATCH: 1, MUTEX: 7 ] =====

===== Mutext Rel Seq: 7-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b21e7 in kglLoadOnLock ()
#2  0x00000000130b0e90 in kgllkal ()
===== BreakPoint: 23-Counter: [ LOCK: 2, PIN: 1, LATCH: 1, MUTEX: 7 ] =====

===== Mutext Rel Seq: 7-2 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b0ea0 in kgllkal ()
#2  0x00000000130ac291 in kglLock ()
===== BreakPoint: 24-Counter: [ LOCK: 2, PIN: 1, LATCH: 1, MUTEX: 7 ] =====

===== Mutext Rel Seq: 7-3 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130ac35c in kglLock ()
#2  0x00000000130a70c5 in kglget ()
===== BreakPoint: 25-Counter: [ LOCK: 2, PIN: 1, LATCH: 1, MUTEX: 7 ] =====

===== Pin Get Seq: 2 -- kglpin (kgllkhdl Addr(rcx)=>98417B58, Mode(r8)=>2, mutex Addr(r11)=>98417CA8)--
#0  0x00000000130a7e20 in kglpin ()
#1  0x0000000004c048c8 in kglgob ()
#2  0x0000000001b1c3ed in kwqicgob ()
===== BreakPoint: 26-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 7 ] =====

===== Mutext Get Seq: 8 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130a80dd in kglpin ()
#2  0x0000000004c048c8 in kglgob ()
===== BreakPoint: 27-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 8 ] =====

===== Mutext Rel Seq: 8-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>0) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130a817e in kglpin ()
#2  0x0000000004c048c8 in kglgob ()
===== BreakPoint: 28-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 8 ] =====

===== Mutext Get Seq: 9 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>90) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130b4c4f in kglpnal ()
#2  0x00000000130a82b9 in kglpin ()
===== BreakPoint: 29-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 9 ] =====

===== Mutext Get Seq: 10 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>71) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130afef5 in kglobpn ()
#2  0x00000000130aab2a in kglpim ()
===== BreakPoint: 30-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 10 ] =====

===== Mutext Rel Seq: 10-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>1) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b0200 in kglobpn ()
#2  0x00000000130aab2a in kglpim ()
===== BreakPoint: 31-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 10 ] =====

===== Mutext Rel Seq: 10-2 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>1) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130a858b in kglpin ()
#2  0x0000000004c048c8 in kglgob ()
===== BreakPoint: 32-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 10 ] =====

===== Pin Rel Seq: 2-1 -- kglpndl(kgllkhdl Addr(r8)=>98417B58) --
#0  0x00000000130b6100 in kglpndl ()
#1  0x00000000130a7756 in kglUnPin ()
#2  0x000000000f70f6bb in kwqidfqo ()
===== BreakPoint: 33-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 10 ] =====

===== Mutext Get Seq: 11 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>95) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130b63c7 in kglpndl ()
#2  0x00000000130a7756 in kglUnPin ()
===== BreakPoint: 34-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 11 ] =====

===== Mutext Rel Seq: 11-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>-2022442648) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b66c9 in kglpndl ()
#2  0x00000000130a7756 in kglUnPin ()
===== BreakPoint: 35-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 11 ] =====

===== Lock Rel Seq: 2-1 -- kgllkdl (kgllkhdl Addr(r8)=>98417B58) ---
#0  0x00000000130b34d0 in kgllkdl ()
#1  0x00000000130ae53c in kglUnLock ()
#2  0x000000000f70f6c6 in kwqidfqo ()
===== BreakPoint: 36-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 11 ] =====

===== Mutext Get Seq: 12 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>85) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130b36be in kgllkdl ()
#2  0x00000000130ae53c in kglUnLock ()
===== BreakPoint: 37-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 12 ] =====

===== Mutext Rel Seq: 12-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b39f1 in kgllkdl ()
#2  0x00000000130ae53c in kglUnLock ()
===== BreakPoint: 38-Counter: [ LOCK: 2, PIN: 2, LATCH: 1, MUTEX: 12 ] =====

===== Latch Get Seq: 2 -- ksl_get_shared_latch Addr(Latch-98 Child-144 Addr(rdi)=>B4C33CF8, Mode(r8)=>16) --
#0  0x00000000128a3a90 in ksl_get_shared_latch ()
#1  0x000000000128dc58 in ksrchreset ()
#2  0x000000000f71eae7 in kwqidlisten ()
===== BreakPoint: 39-Counter: [ LOCK: 2, PIN: 2, LATCH: 2, MUTEX: 12 ] =====

===== Latch Fre Seq: 2-1 -- kslfre (Latch-98 Child-144 Addr(rdi)=>B4C33CF8) --
#0  0x00000000128aa290 in kslfre ()
#1  0x000000000128dd92 in ksrchreset ()
#2  0x000000000f71eae7 in kwqidlisten ()
===== BreakPoint: 40-Counter: [ LOCK: 2, PIN: 2, LATCH: 2, MUTEX: 12 ] =====

===== Latch Get Seq: 3 -- ksl_get_shared_latch Addr(Latch-98 Child-144 Addr(rdi)=>B4C33CF8, Mode(r8)=>16) --
#0  0x00000000128a3a90 in ksl_get_shared_latch ()
#1  0x000000000128ddc5 in ksrchreset ()
#2  0x000000000f71eae7 in kwqidlisten ()
===== BreakPoint: 41-Counter: [ LOCK: 2, PIN: 2, LATCH: 3, MUTEX: 12 ] =====

===== Latch Fre Seq: 3-1 -- kslfre (Latch-98 Child-144 Addr(rdi)=>B4C33CF8) --
#0  0x00000000128aa290 in kslfre ()
#1  0x000000000128de19 in ksrchreset ()
#2  0x000000000f71eae7 in kwqidlisten ()
===== BreakPoint: 42-Counter: [ LOCK: 2, PIN: 2, LATCH: 3, MUTEX: 12 ] =====

===== Mutext Get Seq: 13 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>1) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130ac47e in kglLock ()
#2  0x00000000130a70c5 in kglget ()
===== BreakPoint: 43-Counter: [ LOCK: 2, PIN: 2, LATCH: 3, MUTEX: 13 ] =====

===== Mutext Rel Seq: 13-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>626987360) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130ac35c in kglLock ()
#2  0x00000000130a70c5 in kglget ()
===== BreakPoint: 44-Counter: [ LOCK: 2, PIN: 2, LATCH: 3, MUTEX: 13 ] =====

===== Pin Get Seq: 3 -- kglpin (kgllkhdl Addr(rcx)=>98417B58, Mode(r8)=>2, mutex Addr(r11)=>98417B58)--
#0  0x00000000130a7e20 in kglpin ()
#1  0x00000000130a7af7 in kglpnp ()
#2  0x0000000004c062fb in kglgpr ()
===== BreakPoint: 45-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 13 ] =====

===== Mutext Get Seq: 14 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>4) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130a80dd in kglpin ()
#2  0x00000000130a7af7 in kglpnp ()
===== BreakPoint: 46-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 14 ] =====

===== Mutext Rel Seq: 14-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>0) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130a817e in kglpin ()
#2  0x00000000130a7af7 in kglpnp ()
===== BreakPoint: 47-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 14 ] =====

===== Mutext Get Seq: 15 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>90) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130b4c4f in kglpnal ()
#2  0x00000000130a82b9 in kglpin ()
===== BreakPoint: 48-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 15 ] =====

===== Mutext Get Seq: 16 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>71) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130afef5 in kglobpn ()
#2  0x00000000130aab2a in kglpim ()
===== BreakPoint: 49-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 16 ] =====

===== Mutext Get Seq: 17 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>72) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130b0033 in kglobpn ()
#2  0x00000000130aab2a in kglpim ()
===== BreakPoint: 50-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 17 ] =====

===== Mutext Rel Seq: 17-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>17) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b0200 in kglobpn ()
#2  0x00000000130aab2a in kglpim ()
===== BreakPoint: 51-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 17 ] =====

===== Mutext Rel Seq: 17-2 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>17) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130a858b in kglpin ()
#2  0x00000000130a7af7 in kglpnp ()
===== BreakPoint: 52-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 17 ] =====

===== Pin Rel Seq: 3-1 -- kglpndl(kgllkhdl Addr(r8)=>98417B58) --
#0  0x00000000130b6100 in kglpndl ()
#1  0x00000000130a7756 in kglUnPin ()
#2  0x0000000008066b4d in kwqidxdeq0 ()
===== BreakPoint: 53-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 17 ] =====

===== Mutext Get Seq: 18 -- kglGetMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>95) --
#0  0x00000000130b9c20 in kglGetMutex ()
#1  0x00000000130b63c7 in kglpndl ()
#2  0x00000000130a7756 in kglUnPin ()
===== BreakPoint: 54-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 18 ] =====

===== Mutext Rel Seq: 18-1 -- kglReleaseMutex(kglhdmtx Addr(rsi)=>98417CA8, Location(r8)=>-2022442648) --
#0  0x00000000130b9430 in kglReleaseMutex ()
#1  0x00000000130b66c9 in kglpndl ()
#2  0x00000000130a7756 in kglUnPin ()
===== BreakPoint: 55-Counter: [ LOCK: 2, PIN: 3, LATCH: 3, MUTEX: 18 ] =====

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