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 ] =====
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)
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 ] =====
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)
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 ] =====
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)
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)
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 ] =====
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)
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
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%)
recurrent_sleeps = sleeps + spin_gets ñ misses
= 130,568 + 3,107,867 - 3,234,815
= 3,620
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)
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)
$ > 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
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 ] =====
