Systemstate dump analysis: Nocache on high intensive sequences in RAC

Sequence values are cached in instance memory and by default 20 values are cached. As instance cache is transient, loss of an instance can result in loss of cached sequence values. Permanent record of highest possible value from any instance is kept track in SEQ$ table.

SQLs accessing this sequence within an instance will access instance SGA. As each instance caches its own sequence values it is highly likely that SQLs accessing this sequence from different instance will create gaps in sequence values.

Common knee-jerk reaction to this issue is to set nocache or cache 1 for these sequences. In a single instance environment, this approach will backfire due to massive updates to SEQ$ tables, buffer busy waits, latch free waits etc. In a RAC environment, this issue is magnified and almost hangs the instance. I had the privilege of working with a client to resolve one of their performance issues.

Problem

Instances were hung. It was not possible to login to the database. Many existing connections are working fine though. We were lucky enough that one of the DBAs had active connection to the database. So, we took systemstate dump from that session to see whey there is an hang (or slowness).

Alert log was printing following lines at this time frame. So, we know that there is a problem with row cache enqueue.

Wed Feb 18 06:31:31 2008
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=45
Wed Feb 18 08:59:31 2008
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=44
Wed Feb 18 08:59:31 2008
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=43
Wed Feb 18 09:01:00 2008
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=46
Wed Feb 18 09:01:00 2008
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=27

systemstate dump

We took a systemstate dump with following command.

alter session set events 'immediate trace name systemstate level 4';

I won’t bore you with all the details. But let us review just necessary sections of the systemstate dump file. We know that processes were waiting for row cache enqueue and so I searched for row cache enqueue in the trace file. From the trace file, we see that many sessions are holding NULL mode row cache enqueue and requesting X mode.

row cache enqueue: session: 6126dfea0, mode: N, request: X
  row cache parent object: address=65f5a2ce8 cid=13(dc_sequences) <<<<<<
  hash=5a31f94b typ=9 transaction=0 flags=00000000
  own=65f5a2dc8[65f5a2dc8,65f5a2dc8] wat=65f5a2dd8[63c841c18,63c841e48] mode=N
  status=-/-/-/-/-/-/-/-/-
  request=X release=FALSE flags=2
  instance lock id=QN 0010b020 00000000 <<<<<<<
  data=
  0010b020 00000000 00000000 00000000 00000000 00000000 00000000 00000000
  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
  00000000 00000000 00000000 00000000

Of course, cid=13 indicating that it is for a sequence [ dc_sequence is the row cache area with cache_id=13]. It is also visible that row cache enqueue is maped to instance lock with QN as type and managed by Global enqueue Services. Wait is for that row cache enqueue lock protecting dc_sequences. We need to identify specific sequence though.

Looking for state objects in the same session shows one sequence.

owners:
       SO: 63e1d04b8, type: 46, owner: 63c29edb8, flag: INIT/-/-/0x00
          Sequence State Object:
          kdnssflg =
          kdnsshiw = INACTIVE
          kdnsssqn = 0x64cdeba58
          KGL Sequence Object #1093664: <<<<<<<<<
          kdnsqflg  =
          kqdsnflg  =                   KQDSNNOC
          kdnsqcus  = 0
          kdnsqisp  INACTIVE
          Increment =                              +1
          Minvalue  =                              +1
          Maxvalue  =    +999999999999999999999999999
          Cachesize =                              +0
          Highwater =                      +323649926
          Nextvalue = ###############################

Clearly above section shows that these lines are for sequence with object id 1093664. Querying dba_objects for that object_id shows sequence_name.

select owner, object_name , object_type, created from dba_objects where object_id=1093664
SQL> /

OWNER         OBJECT_NAME  OBJECT_TYPE        CREATED
------------- -----------  ------------       ----------
SCOTT         STG__SEQ     SEQUENCE           12-OCT-07

There is also library cache object accessing that sequence, confirming our analysis.

  SO: 640cc9230, type: 51, owner: 6136d45b8, flag: INIT/-/-/0x00
  LIBRARY OBJECT LOCK: lock=640cc9230 handle=64cdf5868 mode=N
  call pin=63c28f6f8 session pin=0
  htl=640cc92a0[643a01130,643a01130] htb=643a01130
  user=6136d45b8 session=6136d45b8 count=1 flags=[00] savepoint=58
  LIBRARY OBJECT HANDLE: handle=64cdf5868
  name=SELECT SCOTT.STG__SEQ.NEXTVAL FROM DUAL
  hash=5dbaf014 timestamp=02-18-2008 08:00:46
  namespace=CRSR flags=RON/KGHP/TIM/PN0/SML/[12010000]
  kkkk-dddd-llll=0000-0001-0001 lock=N pin=0 latch#=20
  lwt=64cdf5898[64cdf5898,64cdf5898] ltm=64cdf58a8[64cdf58a8,64cdf58a8]
  pwt=64cdf58c8[64cdf58c8,64cdf58c8] ptm=64cdf5958[64cdf5958,64cdf5958]
  ref=64cdf5878[64cdf5878, 64cdf5878] lnd=64cdf5970[64cdb02f8,64ce05748]
    LIBRARY OBJECT: object=64cdf4b40
    type=CRSR flags=EXS[0001] pflags= [00] status=VALD load=0

Sequence cache

In summary, we know that sessions were waiting for row cache enqueues with QN type. That row cache enqueue was protecting a parent row cache entry for dc_sequences. SO [State Objects] for both sequences and cursors accessing that sequence is also exists in the systemstate dump file.

Let’s query properties of that sequence.

SQL> select * from dba_sequences where sequence_name='STG__SEQ';

SEQUENCE_OWNER                 SEQUENCE_NAME                   MIN_VALUE
------------------------------ ------------------------------ ----------
 MAX_VALUE INCREMENT_BY C O CACHE_SIZE LAST_NUMBER
---------- ------------ - - ---------- -----------
SCOTT                         STG__SEQ                        1
1.0000E+27            1 N N          0   338585872

Evidently cache size is set to 0. High last_number also indicates that this is an heavily accessed sequence.

Summary

Essentially, keeping sequence with nocache in RAC for highly accessed sequences is pretty bad idea. Login to the database accesses sequences too, so if row cache enqueues are not available, then logins will hang. This is why existing connections were working fine, but new logins were simply hung. We are able to pinpoint all these using systemstate dump.