Dequeue Session Consumes CPU or Causes Contention Issues or Generates Redo without Ever Dequeueing a Message (Doc ID 1451920.1)

Last updated on JULY 27, 2021

Applies to:

Symptoms

A session which is performing a dequeue operation loops apparently dequeuing the same msgid over and over again. No message is ever dequeued.

This can lead to a number of different symptoms including

1. Excessive redo generation on the database.

2. Hanging situations after a RAC instance failure due to the looping session never freeing locks on the affected queue.

3. Excessive CPU consumption by the looping session

Attaching to the affected process id and gathering the following diagnostic information

connect / as sysdba
oradebug setospid 30998710
oradebug unlimit
oradebug tracefile_name
oradebug event 10046 trace name context forever, level 12
oradebug event 10852 trace name context forever, level 9
oradebug event trace[AQ_DEQ] disk high
oradebug dump errorstack 3
--wait 1 minute
oradebug dump errorstack 3
--wait 1 minute
oradebug dump errorstack 3
oradebug event 10046 trace name context off
oradebug event 10852 trace name context off
oradebug event trace[AQ_DEQ] off

reveals the following

Bind#0
 oacdty=23 mxl=32(16) mxlc=00 mal=00 scl=00 pre=00
 oacflg=10 fl2=0000 frm=00 csi=00 siz=32 off=0
 kxsbbbfp=11093ac78  bln=32  avl=16  flg=05
 value=000000001093AC78  <<<<<<<<<<<<<<<<<<<< Incorrect msgid with half the elements set to 00000000
EXEC #4573111624:c=480,e=3027,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=401425464,tim=25669487263506
FETCH #4573111624:c=4,e=11,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,plh=401425464,tim=25669487263541
kwqdlCbkCcoDl: co=70000023d3077e8 cnt=1 action=2, ccoSav=38635509, curSav=38635507
kwqdlCbkCcoHt:cnt 0, txncmt=0, action=2, ccoSav=38635508, curSav=38635507
DEQ HASH TABLE Dump:
#elements in HT = 0
kwqmdac2dai - loop through all subscribers
kwqmdac2dai - loop through 'rule subscriber' list
kwqmdac2dai: Consumer <consumer_name> entry not found in cache <<<< Legitimate subscriber but not found
kwqmdac2dai - loop through all subscribers
kwqmdac2dai - loop through 'rule subscriber' list
kwqmdac2dai: Consumer <consumer_name> entry not found in cache
kwqmad2api: Enter
kwqmad2api: loop through all address/proxy nodes
kwqmad2api: qa->lagno_kwqiia 2
kwqdlHandleDequeue: qtable=<Schema>.<Queue_Table>, qrcv=1, compat=1
kwqmdac2dai - loop through all subscribers
kwqmdac2dai - loop through 'rule subscriber' list
kwqmdac2dai: Consumer <consumer_name> entry not found in cache
kwqmad2api: Enter
kwqmad2api: loop through all address/proxy nodes
kwqmad2api: qa->lagno_kwqiia 2
kwqdlIsMsgLckd...
mid=BBF8663E1C580128E043AC1951D361C8, snm=<consumer_name>
msgLckd=1, lckHt=0, lckDsk=0, delDsk=1, rac=0, lrgTxn=0, htFull=0,
dstTxn=1, deqImm=0, delMde=1, noHt=0, noHstScn=0, racOpt=0, newDeqOff=0,
lowMem=0, alocFail=0, outOrdDeq=0, dqMid=0, hiExFe=0, #elemsHt=0

kwqidrdq: tries>5000  <<<<<<<<<<<<<<<<< Indication of failing to dequeue the message after 5000 attempts

kwqidrdq:
DEQ HASH TABLE Dump:
#elements in HT = 0
Txn id , Step# 0
BINDS #4573111624:
Bind#0
 oacdty=23 mxl=32(16) mxlc=00 mal=00 scl=00 pre=00
 oacflg=10 fl2=0000 frm=00 csi=00 siz=32 off=0
 kxsbbbfp=11093ac78  bln=32  avl=16  flg=05
 value=000000001093AC78
EXEC #4573111624:c=63,e=135,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=401425464,tim=25669487266351
FETCH #4573111624:c=6,e=16,p=0,cr=1,cu=0,mis=0,r=0,dep=1,og=4,plh=401425464,tim=25669487266388
kwqdlCbkCcoDl: co=70000023d3077e8 cnt=1 action=2, ccoSav=38635518, curSav=38635516
kwqdlCbkCcoHt:cnt 0, txncmt=0, action=2, ccoSav=38635517, curSav=38635516

and this pattern repeats.

Changes

Cause

My Oracle Support provides customers with access to over a million knowledge articles and a vibrant support community of peers and Oracle experts.