Multiple instance crashes due to deadlock between RMV an LMS process (Doc ID 2697015.1)

2020-07-22T00:04:28.557191+00:00
Process RSM0, PID = 876391848, will be killed
2020-07-22T00:04:30.077955+00:00
Starting background process RSM0
2020-07-22T00:04:30.094815+00:00
RSM0 started with pid=98, OS id=329435 , bound to OS numa node 0
2020-07-22T00:04:39.448007+00:00
LMS1 (ospid: 238314) waits for event 'latch: gcs resource hash' for 79 secs.
LMS1 (ospid: 238314) waits for latch 'gcs resource hash' for 79 secs.
2020-07-22T00:05:00.401976+00:00
LMS3 (ospid: 238318) waits for event 'latch: gcs resource hash' for 100 secs.
LMS3 (ospid: 238318) waits for latch 'gcs resource hash' for 100 secs.
2020-07-22T00:05:28.321130+00:00
Errors in file
/u01/app/oracle/diag/rdbms/cxcxxzx05/cxcxxzx053/trace/cxcxxzx053_lmhb_238335.trc
(incident=3328341) (PDBNAME=CDB$ROOT):
ORA-29770: global enqueue process LMS1 (OSID 238314) is hung for more than 70
seconds
Incident details in:
/u01/app/oracle/diag/rdbms/cxcxxzx05/cxcxxzx053/incident/incdir_3328341/cxcxxzx05
3_lmhb_238335_i3328341.trc
2020-07-22T00:05:56.313480+00:00
Errors in file
/u01/app/oracle/diag/rdbms/cxcxxzx05/cxcxxzx053/trace/cxcxxzx053_lmhb_238335.trc
(incident=3328342) (PDBNAME=CDB$ROOT):
ORA-29770: global enqueue process LMS3 (OSID 238318) is hung for more than 70
seconds
Incident details in:
/u01/app/oracle/diag/rdbms/cxcxxzx05/cxcxxzx053/incident/incdir_3328342/cxcxxzx05
3_lmhb_238335_i3328342.trc
2020-07-22T00:06:24.460093+00:00
LOCK_DBGRP: GCR_SYSTEST debug event locked group GR+DB_cxcxxzx05 by memno 0
ERROR: Some process(s) is not making progress.
LMHB (ospid: 238335) is terminating the instance.
Please check LMHB trace file for more details.
Please also check the CPU load, I/O load and other system properties for
anomalous behavior
ERROR: Some process(s) is not making progress.
LMHB (ospid: 238335): terminating the instance due to error 29770
2020-07-22T00:06:24.861286+00:00
System state dump requested by (instance=3, osid=238335 (LMHB)),
summary=[abnormal instance termination].
System State dumped to trace file
/u01/app/oracle/diag/rdbms/cxcxxzx05/cxcxxzx053/trace/cxcxxzx053_diag_238276_2020
0722000624.trc
2020-07-22T00:06:26.424104+00:00
ORA-1092 : opitsk aborting process
2020-07-22T00:06:27.483098+00:00
License high water mark = 2011
2020-07-22T00:06:29.834882+00:00
ORA-29770: global enqueue process (OSID ) is hung for more than seconds
2020-07-22T00:06:29.834986+00:00
Errors in file
/u01/app/oracle/diag/rdbms/cxcxxzx05/cxcxxzx053/trace/cxcxxzx053_diag_238276_2020
0722000624.trc:
ORA-29770: global enqueue process (OSID ) is hung for more than seconds
2020-07-22T00:06:29.835067+00:00
Dumping diagnostic data in directory=[cdmp_20200722000624], requested by
(instance=3, osid=238335 (LMHB)), summary=[abnormal instance termination].
2020-07-22T00:06:31.925789+00:00
Instance terminated by LMHB, pid = 238335
2020-07-22T00:06:32.549430+00:00

File_name:: alert_cxcxxzx053.log

*** 2020-07-22T00:03:37.419237+00:00 (CDB$ROOT(1))
kjgcr_DoAction: KJGCR_ACTION? - id 36

*** 2020-07-22T00:03:37.419252+00:00 (CDB$ROOT(1))
kjgcr_DoAction: KJGCR_ACTION - id 36 ran with status:0 clr:1

*** 2020-07-22T00:03:39.408364+00:00 (CDB$ROOT(1))
==============================
LMS1 (ospid: 238314) has not moved for 20 sec (1595376219.1595376199)
: heartbeat check status 2 (acceptable) (threshold 70 sec)
: heartbeat state 0x5.ffff (inwait|latch-get) pso-flag 0x100
: waiting for event 'latch: gcs resource hash' for 19 secs with wait_id
3442606239.
: waiting for latch 'gcs resource hash'.
===[ Wait Chain ]===
LMS1 (ospid: 238314) waits for event 'latch: gcs resource hash'.
RMV1 (ospid: 238644) waits for event 'KJC: Wait for msg sends to complete'.
==============================
Dumping PROCESS LMS1 (ospid: 238314) States
==============================
===[ Callstack ]===

*** 2020-07-22T00:03:39.408486+00:00 (CDB$ROOT(1))
Process diagnostic dump for oracle@ssssss.ccc.ddd.cc.nnn, OS
id=238314,
pid: 23, proc_ser: 1, sid: 12816, sess_ser: 5214
------------------------------------------------------------------------------
-
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 00:03:39 ]
NOTE: scheduling delay has not been sampled for 0.069160 secs
0.000000 secs from [ 00:03:35 - 00:03:40 ], 5 sec avg
0.000000 secs from [ 00:02:39 - 00:03:40 ], 1 min avg
0.000000 secs from [ 23:58:39 - 00:03:40 ], 5 min avg

*** 2020-07-22T00:03:41.701754+00:00 (CDB$ROOT(1))
loadavg : 25.22 17.69 9.26
System user time: 0.00 sys time: 0.00 context switch: 59260
Memory (Avail / Total) = 57137.34M / 772301.10M
Swap (Avail / Total) = 24576.00M / 24576.00M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME
CMD
0 S oracle 238314 1 20 58 - - 51434178 do_sem Jun21 ?
6-08:02:30 ora_lms1_cxcxxzx053
Name: ora_lms1_cxcxxzx
Umask: 0022
State: S (sleeping)
Tgid: 238314
Ngid: 0
Pid: 238314
PPid: 1
TracerPid: 0
Uid: 25265 25265 25265 25265
Gid: 112 112 112 112
FDSize: 128
Groups: 112
NStgid: 238314
NSpid: 238314
NSpgid: 238314
NSsid: 238314
VmPeak: 206457608 kB
VmSize: 205736712 kB
VmLck: 0 kB
VmPin: 924 kB
VmHWM: 1350592 kB
VmRSS: 881552 kB
RssAnon: 320836 kB
RssFile: 80860 kB
RssShmem: 479856 kB
VmData: 422144 kB
VmStk: 340 kB
VmExe: 347776 kB
VmLib: 35452 kB
VmPTE: 4436 kB
VmPMD: 780 kB
VmSwap: 0 kB
HugetlbPages: 3792896 kB
Threads: 1
SigQ: 1/3088187
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000004
SigIgn: 0000000016400207
SigCgt: 00000003c9887cf8
CapInh: 0000000000000000
CapPrm: 0000000000000000
CapEff: 0000000000000000
CapBnd: 0000003fffffffff
CapAmb: 0000000000000000
NoNewPrivs: 0
Seccomp: 0
Speculation_Store_Bypass: thread vulnerable
Cpus_allowed: ffffff00,0000ffff,ff000000
Cpus_allowed_list: 24-47,72-95
Mems_allowed: 00000000,00000000,00000000,00000000,00000000,00000000,00000000,0
0000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,0000000
0,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,0000
0000,00000000,00000000,00000000,00000000,00000000,00000000,00000003
Mems_allowed_list: 0-1
voluntary_ctxt_switches: 7896374857
nonvoluntary_ctxt_switches: 2144788
Short stack dump:
ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-sem
op()+7<-skgpwwait()+200
<-kslges()+1540<-kslgetl()+2129<-kjbmmsg2res()+2567<-kjbmpclose()+1822<-kjmxmp
m()+12374
<-kjmpbmsg()+6420<-kjmsm()+26650<-ksbdispatch()+152<-opirip()+530<-opidrv()+60
2<-sou2o()+145
<-opimai_real()+202<-ssthrdmain()+417<-main()+262<-__libc_start_main()+245

------------------------------------------------------------------------------
-
Process diagnostic dump actual duration=2.298000 sec
(max dump time=5.000000 sec)

*** 2020-07-22T00:04:31.753821+00:00 (CDB$ROOT(1))
===[ Latch Chain ]===
DIA0 (ospid: 238305) waits for latch 'gc element'.
DBW6 (ospid: 238358) waits for latch 'gcs resource hash'.
RMV3 (ospid: 238665) is not waiting for any latch.

*** 2020-07-22T00:04:31.761435+00:00 (CDB$ROOT(1))
==============================
LMS1 (ospid: 238314) has not moved for 72 sec (1595376271.1595376199)

*** 2020-07-22T00:04:31.765761+00:00 (CDB$ROOT(1))
==============================
LMS3 (ospid: 238318) has not moved for 72 sec (1595376271.1595376199)
kjgcr_ServiceGCR: KJGCR_METRICS: Local metric check lms heartbeat, id 5
failed
kjgcr_ServiceGCR: KJGCR_METRICS: Local metric drm checks, id 9 failed

*** 2020-07-22T00:04:39.447823+00:00 (CDB$ROOT(1))
==============================
LMS1 (ospid: 238314) has not moved for 80 sec (1595376279.1595376199)
: heartbeat check status 6 (no-heartbeat) (threshold 70 sec)
==================================================
=== LMS1 (ospid: 238314) Heartbeat Report
==================================================
LMS1 (ospid: 238314) has no heartbeats for 80 sec. (threshold 70)
: heartbeat state 0x5.ffff (inwait|latch-get) pso-flag 0x100
: waiting for event 'latch: gcs resource hash' for 79 secs with wait_id
3442606239.
: waiting for latch 'gcs resource hash'.
===[ Wait Chain ]===
LMS1 (ospid: 238314) waits for event 'latch: gcs resource hash'.
RMV1 (ospid: 238644) waits for event 'KJC: Wait for msg sends to complete'.
===[ Latch Chain ]===
LMS1 (ospid: 238314) waits for latch 'gcs resource hash'.
RMV1 (ospid: 238644) is not waiting for any latch.
===[ Process State in Latch Chain ]===
Process LMS1 (ospid: 238314): latch state and session wait history
----------------------------------------
SO: 0x188000b0d0, type: 2, owner: (nil), flag: INIT/-/-/-/0x00 if: 0x3 c: 0x3
proc=0x188000b0d0, name=process, file=ksu.h LINE:15729, pg=1, conuid=0
SGA version=(0,0)
(process) Oracle pid:23, ser:1, calls cur/top: 0x1740800238/0x18858aff20
flags : (0x6) SYSTEM icon_uid:0 logon_pdbid=0
flags2: (0x100), flags3: (0x10)
call error: 0, sess error: 0, txn error 0
intr queue: empty
(post info) last post received: 0 0 175
last post received-location: kjc.h LINE:2308 ID:KJCS Post snd
proxy to flush msg
last process to post me: 0x18800145e0 1 6
last post sent: 0 0 257
last post sent-location: kcl2.h LINE:5406 ID:kclcget
last process posted by me: 0x188006f760 1 0
waiter on post event: 0
(latch info) hold_bits=0x0 ud_influx=0xbad6a24
Waiting For:
0x166a102450 Child 'gcs resource hash' (level=4, SGA latch, child#=1240)
Holder Location: kjbr.h LINE:2193 ID:kjbclose:
Holder Context: 0
Waiter Location: kjbr.h LINE:2289 ID:kjbmpclose:
Latch State:
state=busy [value=0x41]
holder orapid=65, ospid=238644
wlstate=free [value=0]
waiters [orapid (seconds since: put on list, posted, alive check)]:
23 (78, *, 0)
146 (80, *, 47)
36 (77, *, 45)
waiter count=3
gotten 756474539 times wait, failed first 2999595, sleeps 2004230
gotten 84610 times nowait, failed 250299, consecutive readers 0
On Wait List For: 0x166a102450
Waiter Link: [0x30004b760,0x166a1024a8]
Process Group: DEFAULT, pseudo proc: 0x2e83bd1298
O/S info: user: oracle, term: UNKNOWN, ospid: 238314
OSD pid info:

PdbInfo: Id=1 Name=CDB$ROOT Uid=1 DBid=140428049
Guid=6BE00A3FE5B67087E05324BB85ABEAF7 State=OPEN Flags=BPC/[00000004]
Closing=0 CloseAborting=0 OfflineSCN=0x0000000000000000
CreateSCN=0x0000000000000000 RDBA=520 DictState=ACTIVE DictFlags=[00000000]
BlockSize=8192 SpaceUsage=0 MaxSpaceUsage=0 MaxDiagUsage=0 MaxAuditUsage=0
FedRootId=0 UndoSwitchoverSCN=0x0000000000000000 SrcPDB= DBLink= PDBCount=1
SgaVersion=(1,0) DropTime=0
RcvState=(Needed=0,State=0,OLog=0x0,CLog=0x0,DLog=0x0,OnlyPmon=0)
PostPlugCompletionSCN=0x0000000000000000 KGL-UOL (Process state object)
KGX Atomic Operation Log 0x188000bd98
Mutex (nil)(0, 0) idn 0 oper NONE(0)
FSO mutex uid 65534 efd 0 whr 0 slp 0

Repeat 31 times
Current Wait Stack:
0: waiting for 'latch: gcs resource hash'
address=0x166a102450, number=0xdf, why=0x0
wait_id=3442606239 seq_num=52755 snap_id=1
wait times: snap=1 min 19 sec, exc=1 min 19 sec, total=1 min 19 sec
wait times: max=infinite, heur=1 min 19 sec
wait counts: calls=0 os=0
in_wait=1 iflags=0x2520
There is at least one session blocking this session.
Dumping 1 direct blocker(s):
inst: 3, sid: 7691, ser: 46398
Dumping final blocker:
inst: 3, sid: 7691, ser: 46398
Wait State:
fixed_waits=0 flags=0x20 boundary=(nil)/-1
Session Wait History:
elapsed time of 0.021921 sec since current wait
0: waited for 'latch: gcs resource hash'
address=0x166a101a30, number=0xdf, why=0x0
wait_id=3442606238 seq_num=52754 snap_id=1
wait times: snap=0.000029 sec, exc=0.000029 sec, total=0.000029 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.004653 sec of elapsed time
1: waited for 'kjctssqmg: quick message send wait'
=0x0, =0x0, =0x0
wait_id=3442606237 seq_num=52753 snap_id=1
wait times: snap=0.003564 sec, exc=0.003564 sec, total=0.003564 sec
wait times: max=0.000000 sec
wait counts: calls=1 os=1
occurred after 0.000287 sec of elapsed time

idle wait at each sample
---------------------------------------------------
Sampled Session History Summary:
longest_non_idle_wait: 'latch: gcs resource hash'
[78 samples, 00:03:20 - 00:04:39]
time_waited: >= 78 sec (still in wait)
---------------------------------------------------
----------------------------------------
kpoxc: mode=0 static=0 inReq=0 pendErrInRep=0 callUseSCN=0 nonReq=0
kpoxc: trace=0 roundTrip=0 errCode=0 ctl=0 eocs=0 disErr=0 dscnEnabled=0
temporary object counter: 0
last pdbid to increment: 0, last function to increment: (null)
BPS: empty
----------------------------------------
Virtual Thread:

*** 2020-07-22T00:05:25.959444+00:00 (CDB$ROOT(1))
Process diagnostic dump for oracle@ssssss.ccc.ddd.cc.nnn, OS
id=238665,
pid: 67, proc_ser: 1, sid: 8158, sess_ser: 58529
------------------------------------------------------------------------------
-
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 00:05:25 ]
NOTE: scheduling delay has not been sampled for 0.124106 secs
0.000000 secs from [ 00:05:21 - 00:05:26 ], 5 sec avg
0.000000 secs from [ 00:04:26 - 00:05:26 ], 1 min avg
0.000000 secs from [ 00:00:26 - 00:05:26 ], 5 min avg

*** 2020-07-22T00:05:28.253569+00:00 (CDB$ROOT(1))
loadavg : 5.77 12.91 8.43
System user time: 0.02 sys time: 0.01 context switch: 136969
Memory (Avail / Total) = 56832.39M / 772301.10M
Swap (Avail / Total) = 24576.00M / 24576.00M
F S UID PID PPID C PRI NI ADDR SZ WCHAN STIME TTY TIME
CMD
0 S oracle 238665 1 1 80 0 - 51344161 poll_s Jun21 ? 13:03:32
ora_rmv3_cxcxxzx053
Name: ora_rmv3_cxcxxzx
Umask: 0022
State: S (sleeping)
Tgid: 238665
Ngid: 0
Pid: 238665
PPid: 1
TracerPid: 0
Uid: 25265 25265 25265 25265
Gid: 112 112 112 112
FDSize: 128
Groups: 112
NStgid: 238665
NSpid: 238665
NSpgid: 238665
NSsid: 238665
VmPeak: 205401140 kB
VmSize: 205376644 kB
VmLck: 0 kB
VmPin: 0 kB
VmHWM: 166552 kB
VmRSS: 104668 kB
RssAnon: 25300 kB
RssFile: 76844 kB
RssShmem: 2524 kB
VmData: 41584 kB
VmStk: 344 kB
VmExe: 347776 kB
VmLib: 34288 kB
VmPTE: 840 kB
VmPMD: 764 kB
VmSwap: 0 kB
HugetlbPages: 634880 kB
Threads: 1
SigQ: 1/3088187
SigPnd: 0000000000000000
ShdPnd: 0000000000000000
SigBlk: 0000000000000004
SigIgn: 0000000016400207
SigCgt: 00000003c9887cf8
CapInh: 0000000000000000
CapPrm: 0000000000000000
CapEff: 0000000000000000
CapBnd: 0000003fffffffff
CapAmb: 0000000000000000
NoNewPrivs: 0
Seccomp: 0
Speculation_Store_Bypass: thread vulnerable
Cpus_allowed: ffffff00,0000ffff,ff000000
Cpus_allowed_list: 24-47,72-95
Mems_allowed: 00000000,00000000,00000000,00000000,00000000,00000000,00000000,0
0000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,0000000
0,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,0000
0000,00000000,00000000,00000000,00000000,00000000,00000000,00000003
Mems_allowed_list: 0-1
voluntary_ctxt_switches: 127257565
nonvoluntary_ctxt_switches: 2623631
Short stack dump:
ksedsts()+346<-ksdxfstk()+71<-ksdxcb()+912<-sspuser()+217<-__sighandler()<-__p
oll()+16
<-ipcgxp_selectex()+409<-ipclw_wait()+1045<-ksxpwait_ipclw()+3844<-ksxpwait_in
t()+22103
<-ksxpwait()+845<-ksliwat()+10777<-kslwaitctx()+197<-kjctcwcrm()+587<-kjctcisnd()+978<-kjccbatchflush()+3243

<-kjcsmba()+4163<-kjccgmbi()+235<-kjccgmb_pbatch()+2085

<-kjxmgmb_breq_header()+612<-kjbmsrmexp()+480<-kjbmbexpandrm()+902<-kjbrgoread
mostly()+741
<-kjbrclose()+1856<-kjbclose()+19083<-kclplz()+2305<-kclpbi()+899<-kjmrmslmain
()+4889
<-ksvrdp_int()+2010<-ksvrdp_cbk()+13<-ksbdispatch()+152<-opirip()+530<-opidrv(
)+602
<-sou2o()+145<-opimai_real()+202<-ssthrdmain()+417<-main()+262<-__libc_start_m
ain()+245

------------------------------------------------------------------------------
-
Process diagnostic dump actual duration=2.300000 sec
(max dump time=30.000000 sec)

*** 2020-07-22T00:05:28.259515+00:00 (CDB$ROOT(1))
----------------------------------------
SO: 0x1880021d30, type: 2, owner: (nil), flag: INIT/-/-/-/0x00 if: 0x3 c: 0x3
proc=0x1880021d30, name=process, file=ksu.h LINE:15729, pg=1, conuid=0
SGA version=(0,0)
(process) Oracle pid:67, ser:1, calls cur/top: 0x1687018a80/0x1687018a80
flags : (0x6) SYSTEM icon_uid:1 logon_pdbid=0
flags2: (0x100), flags3: (0x10)
call error: 0, sess error: 0, txn error 0
intr queue: empty
(post info) last post received: 0 0 186
last post received-location: kjm.h LINE:1909 ID:KJMUNLPOSTSF:
post send proxies
last process to post me: 0x188000c160 1 6
last post sent: 2147483647 0 3
last post sent-location: ksl2.h LINE:4497 ID:kslpsr
last process posted by me: 0x1880059b90 1 0
waiter on post event: 0
(latch info) hold_bits=0x10 ud_influx=0xe8172b
Holding:
0x166a0f7ff8 Child 'gcs resource hash' (level=4, SGA latch, child#=1478)
Holder Location: kjbr.h LINE:2193 ID:kjbclose:
Holder Slot: slot=4, efd=5, pdb=1
Holder Context: 0
Latch State:
state=busy [value=0x43]
holder orapid=67, ospid=238665
wlstate=free [value=0]
waiters [orapid (seconds since: put on list, posted, alive check)]:
25 (126, *, 25)
42 (119, *, 4)
waiter count=2
gotten 759748764 times wait, failed first 2978453, sleeps 1989551
gotten 82964 times nowait, failed 241935, consecutive readers 0
Process Group: DEFAULT, pseudo proc: 0x2e83bd1298
O/S info: user: oracle, term: UNKNOWN, ospid: 238665
OSD pid info:

----------------------------------------
SO: 0x1881c930b8, type: 4, owner: 0x1880021d30, flag: INIT/-/-/-/0x00 if: 0x3
c: 0x3
proc=0x1880021d30, name=session, file=ksu.h LINE:15737, pg=1, conuid=1
SGA version=(1,0)
(session) sid: 8158 ser: 58529 trans: (nil), creator: 0x1880021d30
flags: (0x51) USR/- flags2: (0x80409) -/-/INC
flags_idl: (0x1) status: BSY/-/-/- kill: -/-/-/-
DID: 0003-0043-000000020000-0000-00000000, short-term DID:
txn branch: (nil)
con_id/con_uid/con_name: 1/1/CDB$ROOT
con_logonuid: 1 con_logonid: 1
con_scuid: 1 con_scid: 1
edition#: 0 user#/name: 0/SYS
oct: 0, prv: 0, sql: (nil), psql: (nil)
stats: 0x16bfff8f18, PX stats: 0x114e4944
service name: SYS$BACKGROUND
Current Wait Stack:
1: waiting for 'KJC: Wait for msg sends to complete'
msg=0x2e6e37d560, dest|rcvr=0x10004, mtype=0xfff1
wait_id=288507077 seq_num=22010 snap_id=1
wait times: snap=2 min 8 sec, exc=2 min 8 sec, total=2 min 8 sec
wait times: max=infinite, heur=2 min 8 sec
wait counts: calls=430 os=430
in_wait=1 iflags=0x1520
0: waiting for 'ges message buffer allocation'
pool=0x1, request=0x1, allocated=0x0
wait_id=288507076 seq_num=22009 snap_id=1
wait times: snap=0.000000 sec, exc=0.000001 sec, total=2 min 8 sec
wait times: max=infinite, heur=2 min 8 sec
wait counts: calls=0 os=0
in_wait=1 iflags=0x15a0
There are 2 sessions blocked by this session.
Dumping one waiter:
inst: 3, sid: 13282, ser: 55138
wait event: 'latch: gcs resource hash'
p1: 'address'=0x166a0f7ff8
p2: 'number'=0xdf
p3: 'why'=0x0
row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
min_blocked_time: 25 secs, waiter_cache_ver: 30130
Wait State:
fixed_waits=0 flags=0x22 boundary=(nil)/-1
Session Wait History:
elapsed time of 0.000000 sec since current wait
0: waited for 'ges message buffer allocation'
pool=0x1, request=0x1, allocated=0x0
wait_id=288507076 seq_num=22009 snap_id=1
wait times: snap=0.000001 sec, exc=0.000001 sec, total=0.000001 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000843 sec of elapsed time

The history is displayed in reverse chronological order.

sample interval: 1 sec, max history 120 sec
---------------------------------------------------
[118 samples, 00:03:27 -
00:05:27]
waited for 'KJC: Wait for msg sends to complete', seq_num: 22010
p1: 'msg'=0x2e6e37d560
p2: 'dest|rcvr'=0x10004
p3: 'mtype'=0xfff1
time_waited: >= 119 sec (still in wait)
[3 samples, 00:03:28 -
00:03:26]
idle wait at each sample
---------------------------------------------------
Sampled Session History Summary:
longest_non_idle_wait: 'KJC: Wait for msg sends to complete'
[118 samples, 00:03:27 - 00:05:27]
time_waited: >= 119 sec (still in wait)
---------------------------------------------------
----------------------------------------

*** 2020-07-22T00:06:24.778900+00:00 (CDB$ROOT(1))
==============================
LMS1 (ospid: 238314) has not moved for 185 sec (1595376384.1595376199)

*** 2020-07-22T00:06:24.783291+00:00 (CDB$ROOT(1))
==============================
LMS3 (ospid: 238318) has not moved for 185 sec (1595376384.1595376199)

*** 2020-07-22T00:06:24.783882+00:00 (CDB$ROOT(1))
Forcibly terminated 'oracle@ssssss.ccc.ddd.cc.nnn' process
Forcibly terminated 2 out of 2 LGWR worker processes

File_name:: /cxcxxzx053_lmhb_238335.trc