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

Last updated on AUGUST 31, 2015

Applies to:

Oracle Database - Enterprise Edition - Version 11.2.0.1 to 11.2.0.3 [Release 11.2]
Oracle SOA Suite - Version 11.1.1.5.0 and later
Information in this document applies to any platform.

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 proces 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 SEEDIFACT entry not found in cache <<<< Legitimate subscriber but not found
kwqmdac2dai - loop through all subscribers
kwqmdac2dai - loop through 'rule subscriber' list
kwqmdac2dai: Consumer SEEDIFACT entry not found in cache
kwqmad2api: Enter
kwqmad2api: loop through all address/proxy nodes
kwqmad2api: qa->lagno_kwqiia 2
kwqdlHandleDequeue: qtable=TST_SOAINFRA.IP_QTAB, qrcv=1, compat=1
kwqmdac2dai - loop through all subscribers
kwqmdac2dai - loop through 'rule subscriber' list
kwqmdac2dai: Consumer SEEDIFACT entry not found in cache
kwqmad2api: Enter
kwqmad2api: loop through all address/proxy nodes
kwqmad2api: qa->lagno_kwqiia 2
kwqdlIsMsgLckd...
mid=BBF8663E1C580128E043AC1951D361C8, snm=SEEDIFACT
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.

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms