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

lgang403

Wed Jan 16 00:29:47 2013
Thread 2 advanced to log sequence 7703 (LGWR switch)
  Current log# 6 seq# 7703 mem# 0: /dev/rredo2_3a
  Current log# 6 seq# 7703 mem# 1: /dev/rredo2_3b
Wed Jan 16 10:54:57 2013
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=134
System State dumped to trace file /oracle/admin/test/udump/test2_ora_672766.trc
Wed Jan 16 11:03:51 2013
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=58
System State dumped to trace file /oracle/admin/test/udump/test2_ora_701944.trc
Wed Jan 16 11:07:51 2013
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=85
System State dumped to trace file /oracle/admin/test/udump/test2_ora_725140.trc
Wed Jan 16 11:20:07 2013
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=288
System State dumped to trace file /oracle/admin/test/udump/test2_ora_484056.trc
Wed Jan 16 11:20:15 2013
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=571
Wed Jan 16 11:22:47 2013
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=667
System State dumped to trace file /oracle/admin/test/udump/test2_ora_500202.trc
Wed Jan 16 11:24:53 2013
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=675
System State dumped to trace file /oracle/admin/test/udump/test2_ora_652472.trc
Wed Jan 16 11:25:13 2013
>>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=125

数据库拒绝服务半小时。


自己分析的问题原因是由一个object id 为385715的索引导致的。

lgang403

是否是bug正在查

Maclean Liu(刘相兵

大量的

enq: SQ - contention 等待  以及cursor: pin S wait on X、latch: row cache objects等

Maclean Liu(刘相兵

        (enqueue) SQ-00000090-00000000  DID: 0002-0037-00003DA4

0x90=>144



SQL> select object_name,object_type from dba_objects where object_id=144;

OBJECT_NAME
--------------------------------------------------------------------------------
OBJECT_TYPE
-------------------
AUDSES$
SEQUENCE

Maclean Liu(刘相兵

给出一个 问题发生时段的AWR

Maclean Liu(刘相兵

Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production + RAC + AIX 5.3

RAC hang enq: SQ - contention AUDSES$

related issue;
RAC Hangs due to small cache size on SYS.AUDSES$ [ID 395314.1]

The default setting for the SYS.AUDSES$ sequence is 20, this is too low for a RAC system
where logins can occur concurrently from multiple nodes.  During high login rate
such low value can cause slowness and even hangs. Some of the symptoms are:
- Checkpoint not completing on all RAC nodes
- Waits expire on row cache enqueue lock dc_sequences
- RAC hangs due to QMON deadlocking

During those hangs session login is not possible (or *extremely* slow) due
to extremely high contention on the above sequence.

SOLUTION:
---------

Manually increase that sequence cache on each affected database:

alter sequence sys.audses$ cache 10000;

This is fixed in 10.2.0.3 patchset. (Affected releases 9i to 10.2.0.2)






select sequence_name,cache_size,order_flag from dba_sequences where sequence_name='AUDSES$';

查一下， 感觉可能和 logon storm有关系 ， 你的应用是否采用短链接方式？

10:54:57
2229145 logons cumulative
998 logons current

11:03:51 2013
2229269 logons cumulative
952 logons current


10:54:57-11:03:51 共 9分钟左右 累计登录数 2229269 -2229145 =124

Maclean Liu(刘相兵

create sequence audses$                               /* auditing session id */
  start with 1
  increment by 1
  minvalue 1
  maxvalue 2E9                                     /* maxvalue fits in a ub4 */
  cycle
  cache 10000
  noorder
/


该 audses$         用来审计登陆session

ricky

求教：刘大。你从trace里面怎么找到
(enqueue) SQ-00000090-00000000  DID: 0002-0037-00003DA4
怎么会怀疑这里有问题呢？

0x90=>144

lgang403

Maclean Liu(刘相兵 发表于 2013-1-16 14:45
大量的

enq: SQ - contention 等待  以及cursor: pin S wait on X、latch: row cache objects等

刘大真神速，MOS都还没响应呢

lgang403

Maclean Liu(刘相兵 发表于 2013-1-16 15:22
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production + RAC + AIX 5.3

RAC ha ...

select sequence_name,cache_size,order_flag from dba_sequences where sequence_name='AUDSES$';

SEQUENCE_NAME                        CACHE_SIZE             O
------------------------------------          --------------------------      ------
AUDSES$                                       10000                  N

lgang403

抱歉，环境：aix 5.3+rac+10.2.0.4.0

Maclean Liu(刘相兵

shared pool        kghfrunp: clatch: wait        0        5,053,004        5,993,734
shared pool        kghfrunp: alloc: wait        0        1,845,816        1,811,691
shared pool        kghfrunp: clatch: nowait        0        1,093,322        0
shared pool        kghalo        0        3,094        15,296
shared pool        kghfre        0        2,187        15,053
shared pool        kghupr1        0        1,921        10,002
shared pool        kghalp        0        294        1,034



shared        KGLS heap        153.60        130.07        -15.32
shared        KQR L PO        649.64        405.37        -37.60


row cache所在KQR L PO 出现过较大幅度的SHRINK

而AUDSES$ 的cachesize为10000， 且实际观察AWR  未发现大量解析和登陆操作


shared pool        10,978,549        10,400,865        1,853,429        8,577,818        0        0        0
cache buffers chains        176,684,102        105,702        351        105,359        0        0        0
shared pool simulator        7,262,768,840        30,586        10        30,576        0        0        0


大量的shared pool simulator latch activity


就AWR看 sga_target        =25165824000，但是没有发生shared pool shrink/grow操作

考虑设置_LIBRARY_CACHE_ADVICE=false  避免该问题的发生


类似案例：
Bug 8408436 : CURSOR: PIN S WAIT ON X, LATCH: ROW CACHE OBJECTS, LCK0 WAITING

Maclean Liu(刘相兵

上传 当时lck0进程的trace看下

lgang403

oracle给的建议是参考LCK temporarily stuck waiting for latch 'Child row cache objects' [ID 843638.1]，先打上补丁，跟刘大http://t.askmaclean.com/thread-423-1-1.html中的建议一致。

lgang403

没有发现LCK0进程的trace文件