Abnormally High CPU Utilization by Dequeueing Sessions when the Queue is Empty (Doc ID 729162.1)

Last updated on FEBRUARY 04, 2022

Applies to:

Symptoms

Intermittent cpu increases are observed for dequeueing sessions. Each individual session doubles its cpu consumption so that the total cpu consumed by all the dequeuing sessions is considerable.

This application previously worked in 9.2 without any issues and without this behaviour being observed.

The increased cpu consumption is observed when using single consumer queue tables, a dequeue condition in the dequeue code and multiple dequeue sessions and the queues are nearly empty or do not have any messages which satisfy the specified dequeue condition.

The short stack of the dequeue sessions is similar to the following

kwqidorefetch()<-kwqidexfcy()<-kwqidrdq()

10046 tracing of the dequeue sessions will show the cursors relating to  AQ$_<QUEUE_TABLE>_F view and the queue table being repeatedly executed as follows

PARSING IN CURSOR #3 len=703 dep=1 uid=329 oct=3 lid=329 tim=2974257917510 hv=3283260308 ad='88ff8f90'
select tab.row_id, tab.msgid, tab.corrid, tab.priority, tab.delay, tab.expiration, tab.retry_count, tab.exception_qschema, tab.exception_queue, tab.chain_no, tab.local_order_no, tab.enq_time, tab.time_manager_info, tab.state, tab.enq_tid, tab.step_no, tab.sender_name, tab.sender_address, tab.sender_protocol, tab.dequeue_msgid, tab.user_prop, tab.user_data from "<SCHEMA_NAME>"."AQ$_<QUEUE_TABLE>_F" tab where q_name = :1 and (state = :2 ) and (decode(dbms_aqjms.get_ptype('command', tab.user_data.header.properties), 100, dbms_aqjms.get_strval('command', tab.user_data.header.properties), 200, dbms_aqjms.get_numval('command', tab.user_data.header.properties), null) = 'article')
END OF STMT
PARSE #3:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=2974257917508
=====================
PARSING IN CURSOR #5 len=477 dep=1 uid=0 oct=3 lid=0 tim=2974257917692 hv=2730802776 ad='ac89ee90'
select tab.rowid, tab.msgid, tab.corrid, tab.priority, tab.delay, tab.expiration, tab.retry_count, tab.exception_qschema, tab.exception_queue, tab.chain_no, tab.local_order_no, tab.enq_time, tab.time_manager_info, tab.state, tab.enq_tid, tab.step_no, tab.sender_name, tab.sender_address, tab.sender_protocol, tab.dequeue_msgid, tab.user_prop, tab.user_data from "<SCHEMA_NAME>"."<QUEUE_TABLE>" tab where tab.msgid = :1 and tab.state = 0 for update skip locked
END OF STMT
PARSE #5:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2974257917690
EXEC #3:c=0,e=257,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=2974257918246
FETCH #3:c=0,e=3931,p=0,cr=64,cu=0,mis=0,r=1,dep=1,og=1,tim=2974257922208
EXEC #5:c=0,e=260,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2974257922735
FETCH #5:c=0,e=286,p=0,cr=54,cu=1,mis=0,r=0,dep=1,og=4,tim=2974257923053
FETCH #3:c=0,e=333,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,tim=2974257923591
EXEC #5:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2974257923705
FETCH #5:c=0,e=188,p=0,cr=54,cu=1,mis=0,r=0,dep=1,og=4,tim=2974257923911
FETCH #3:c=0,e=173,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,tim=2974257924145
EXEC #5:c=10000,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2974257924228
FETCH #5:c=0,e=173,p=0,cr=54,cu=1,mis=0,r=0,dep=1,og=4,tim=2974257924419
FETCH #3:c=0,e=174,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,tim=2974257924646
EXEC #5:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2974257924730
FETCH #5:c=0,e=178,p=0,cr=54,cu=1,mis=0,r=0,dep=1,og=4,tim=2974257924925
FETCH #3:c=0,e=175,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,tim=2974257925152
EXEC #5:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2974257925237
FETCH #5:c=0,e=180,p=0,cr=54,cu=1,mis=0,r=0,dep=1,og=4,tim=2974257925435
FETCH #3:c=0,e=235,p=0,cr=8,cu=0,mis=0,r=1,dep=1,og=1,tim=2974257925724
EXEC #5:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2974257925810
FETCH #5:c=0,e=169,p=0,cr=54,cu=1,mis=0,r=0,dep=1,og=4,tim=2974257925995
FETCH #3:c=0,e=176,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,tim=2974257926225
EXEC #5:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2974257926313
FETCH #5:c=0,e=168,p=0,cr=54,cu=1,mis=0,r=0,dep=1,og=4,tim=2974257926498
FETCH #3:c=0,e=160,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,tim=2974257926710
EXEC #5:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=2974257926792

In turn these statements will be associated with high CPU times in AWR reports.

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.