Posted by: Pavel Ermakov | April 6, 2011

WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! DC_SEQUENCES

Hi there.

Little bit of row cache lock.

Potential reasons for “WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! ”

When Row cache contention occurs, if the enqueue cannot be gotten within a certain time period,
a trace file will be generated in the <> location with some trace details.

The trace file tends to contain the words:

  >>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! <<<

in it at the start.

This trace can provide some useful information for diagnosing the cause of the contention.
The trace will often contain a systemstate dump, although most useful information is in the header section. Typically a session holding the row cache resource will either be on cpu or blocked by another session. If it is on cpu then errorstacks are likely to be required to diagnose, unless tuning can be done to reduce the enqueue hold time. Remember that on a multi node system (RAC) the holder may be on another node and so multiple systemstates from each node will be required.

For each enqueue type, there are a limited number of operations that require each enqueue.

DC_TABLESPACES

Probably the most likely is allocation of new extents. If extent sizes are set low then the application may constantly be requesting new extents and causing contention. Do you have objects with small extent sizes that are rapidly growing? (You may be able to spot these by looking for objects with large numbers of extents). Check the trace for insert/update activity, check the objects inserted into for number of extents.

DC_SEQUENCES

Check for appropriate caching of sequences for the application requirements.

DC_USERS

Deadlock and resulting “WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK!” can occur if a session issues a GRANT to a user, and that user is in the process of logging on to the database.

DC_OBJECTS

Look for any object compilation activity which might require an exclusive lock and thus block online activity.

DC_SEGMENTS

This is likely to be down to segment allocation. Identify what the session holding the enqueue is doing and use errorstacks to diagnose.

DB_ROLLBACK_SEGMENTS

This is due to rollback segment allocation. Just like dc_segments,identify what is holding the enqueue and also generate errorstack.

Recently I face off whith this warning in alert log  from one of nodes RAC DB. In trace file I saw this:

*** 2011-04-06 10:48:25.163
*** SERVICE NAME:(SYS$BACKGROUND) 2011-04-06 10:48:25.148
*** SESSION ID:(534.1) 2011-04-06 10:48:25.148
ssd_unwind_bp: unhandled instruction at 0x240745f instr=f
ssd_unwind_bp: unhandled instruction at 0x229c294 instr=f
*** 2011-04-06 10:48:51.286
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! <<<
row cache enqueue: session: 0x3dfa79120, mode: N, request: X

I can’t login to this node through sqlplus “/ as sysdba”. Current connections still work fine. Then I connect through prelim connection and run this:

oradebug setmypid

oradebug hanganalyze 1

oradebug tracefilename

In trace file:

*** 2011-04-06 10:47:22.244
==============
HANG ANALYSIS:
==============

Cycle 1 : <cnode/sid/sess_srno/ospid/wait_event> :
<1/474/12697/19874/row cache lock>
Open chains found:
Chain 1 : <cnode/sid/sess_srno/ospid/wait_event> :
<1/458/18046/9313/gc buffer busy> — <1/534/1/8830/row cache lock>
— <1/535/1/8828/row cache lock> — <1/483/8648/31826/row cache lock>
— <1/530/23457/19872/row cache lock> — <1/486/7349/22877/row cache lock>
— <1/474/12697/19874/row cache lock>
Other chains found:
Chain 2 : <cnode/sid/sess_srno/ospid/wait_event> :
<1/426/7/17928/enq: SQ – contention>
Chain 3 : <cnode/sid/sess_srno/ospid/wait_event> :
<1/427/17/17393/enq: SQ – contention>
Chain 4 : <cnode/sid/sess_srno/ospid/wait_event> :

Necessary section of the trace file:

SO: 0x3b6fb71d0, type: 50, owner: 0x3cbf8be40, flag: INIT/-/-/0x00
row cache enqueue: count=1 session=0x3dfa7a698 object=0x39c268b98, request=X
savepoint=0x10d8c1e
row cache parent object: address=0x39c268b98 cid=13(dc_sequences)
hash=9649e7e typ=11 transaction=0x3cc5aab80 flags=0000012a
own=0x39c268c68[0x3b6fb70e0,0x3b6fb70e0] wat=0x39c268c78[0x3b6fb71a0,0x3b6fb6fc0] mode=X
status=VALID/UPDATE/-/-/IO/-/-/-/-
request=N release=FALSE flags=0
instance lock id=QN 09649e7e c64a76ad
data=
00000104 00020005 00050002 00050001 000002c1 00000000 00000000 00000000
02c10000 00000000 00000000 00000000 00000000 321e05c4 00000044 00000000
00000000 00800000 00000000 00000000 00000000 00000000 321403c4 00000027
00000000 00000000 2d2d0000 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d 2d2d2d2d
2d2d2d2d 2d2d2d2d 00002d2d 00000000
—————————————-
SO: 0x3b50ce8f8, type: 54, owner: 0x3940ec208, flag: INIT/-/-/0x00
LIBRARY OBJECT PIN: pin=0x3b50ce8f8 handle=0x3b25c7738 mode=S lock=3b510d818
user=3dfa7a698 session=3dfa58de0 count=1 mask=0001 savepoint=0x10d8c1d flags=[00]
LIBRARY OBJECT HANDLE: handle=3b25c7738 mtx=0x3b25c7868(0) lct=454 pct=4030 cdp=0
name=SYS.ORA_TQ_BASE$
hash=790a537aa0ad0ea96e414a3bb54eefcb timestamp=03-12-2008 00:39:54
namespace=TABL flags=KGHP/TIM/XLR/[00000020]
kkkk-dddd-llll=0000-0001-0001 lock=N pin=S latch#=3 hpc=0322 hlc=0322
lwt=0x3b25c77e0[0x3b25c77e0,0x3b25c77e0] ltm=0x3b25c77f0[0x3b25c77f0,0x3b25c77f0]
pwt=0x3b25c77a8[0x3b25c77a8,0x3b25c77a8] ptm=0x3b25c77b8[0x3b25c77b8,0x3b25c77b8]
ref=0x3b25c7810[0x3b25c7810,0x3b25c7810] lnd=0x3b25c7828[0x3b2679bb8,0x3de7c9000]
LOCK INSTANCE LOCK: id=LB790a537aa0ad0ea9
PIN INSTANCE LOCK: id=NB790a537aa0ad0ea9 mode=S release=F flags=[00]
INVALIDATION INSTANCE LOCK: id=IV000001040c012837 mode=S
LIBRARY OBJECT: object=3b4e211a0
type=SQNC flags=EXS/LOC[0005] pflags=[0000] status=VALD load=0
DATA BLOCKS:
data#     heap  pointer    status pins change whr alloc(K)  size(K)
—– ——– ——– ——— —- —— — ——– ——–
0 3b034a998 3b4e212b8 I/P/A/-/-    0 NONE   00      0.55     1.09
—————————————-
SO: 0x3cc750470, type: 48, owner: 0x3b50ce8f8, flag: INIT/-/-/0x00
Sequence State Object:
kdnssflg =
kdnsshiw = INACTIVE
kdnsssqn = 0x3b4e212f8
KGL Sequence Object #260:
kdnsqflg  =
kqdsnflg  = KQDSNCYC          KQDSNNOC
kdnsqcus  = 0
kdnsqisp  INACTIVE
Increment =                              +1
Minvalue  =                              +1
Maxvalue  =                        +4294967
Cachesize =                              +0
Highwater =                        +2194923
Nextvalue = ###############################

From the trace file, we see that many sessions are holding NULL mode row cache enqueue and requesting X mode.

cid=13(dc_sequences) indicating that it is sequence. (select PARAMETER from v$rowcache where cache#=13).

It is also visible that row cache enqueue is maped to instance lock with QN as instance lock id and managed by Global enqueue Services. Wait is for that row cache enqueue lock protecting dc_sequences. Now, we need to identify specific sequence though. \

First way:

name=SYS.ORA_TQ_BASE$, where SYS is owner and ORA_TQ_BASE$ is sequence name.

Second way:

select owner, object_name , object_type, created from dba_objects where object_id=260;

DDL of that sequence:

CREATE SEQUENCE “SYS”.”ORA_TQ_BASE$” MINVALUE 1 MAXVALUE 4294967 INCREMENT BY 1 START WITH 716015 NOCACHE NOORDER CYCLE ;

I think it’s not good idea to create nocache sequence in RAC that highly accessed.

I will create SR for this issue.

Sincerely, Pavel.

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Categories

%d bloggers like this: