hanganalyze 解决数据库row cache lock

hanganalyze解决row cache lock(ZT)

上一篇 / 下一篇 2011-04-05 15:46:00 / 个人分类：Oracle
查看( 2 ) / 评论( 0 ) / 评分( 0 / 0 )
执行一个split分区的脚本时长时间没有响应。登录上去查看，手工执行了split脚本，发现确实会hang住：

SQL>ALTERTABLEA_PDA_SP_STATSPLITPARTITIONP_MAXAT(20090609)
INTO(PARTITIONP_20090608TABLESPACETS_DATA_A,PARTITIONP_MAXTABLESPACETS_DATA_A)
SQL>

检查该session的等待事件：

EVENT P1 P2 P3
------------------------------ ---------- ---------- ----------
rowcachelock 8 0 5

查了网上的一些资料，说和sga的shared pool大小不足有关，或者和sequence的cache不大有关。经过分析，这2个原因应该都不是。因为1、如果是shared pool不足，这样的现象一般是某个sql执行的比较慢，但是还是会执行完，而不是像现在这样的挂住；2，只是执行split分区，并没有和 sequence相关。

在这里，我们用hanganalyze来进行分析。

hanganalyze用法：

(在这里我们用oradebug来用做hanganalyze)
1.oradebug setospid
2.oradebug analyze<level>
然后观察出来的trace文件。

这里的level有如下几级：

Dump Level Dump Contains
----------------------------------------
1-2 Only HANGANALYZE output, no process dump at all
3 Level 2 + Dump only processes thought to be in a hang (IN_HANG state)
4 Level 3 + Dump leaf nodes (blockers) in wait chains (LEAF,LEAF_NW,IGN_DMP state)
5 Level 4 + Dump all processes involved in wait chains (NLEAF state)
10 Dump all processes (IGN state)

我们现在来看看出来的trace文件：

SQL> select spid from v$session a,v$process b where a.paddr=b.addr and a.sid=295;
SPID
------------
19237
SQL> oradebug SETOSPID 19237
Oracle pid: 235, Unix process pid: 19237, image: oracle@hl_rdb01 (TNS V1-V3)
SQL>
SQL> oradebug hanganalyze 3;
Cycle 1: (0/295)
Cycle 2: (0/254)--(0/239)
Hang Analysis in /oracle/app/oracle/admin/hlreport/udump/hlreport_ora_25247.trc
SQL> !
$ more /oracle/app/oracle/admin/hlreport/udump/hlreport_ora_25247.trc
Dump file /oracle/app/oracle/admin/hlreport/udump/hlreport_ora_25247.trc
Oracle9i Enterprise Edition Release 9.2.0.6.0 - 64bit Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.6.0 - Production
ORACLE_HOME = /oracle/app/oracle/product/9.2.0
System name: HP-UX
Node name: hl_rdb01
Release: B.11.11
Version: U
Machine: 9000/800
Instance name: hlreport
Redo thread mounted by this instance: 1
Oracle process number: 157
Unix process pid: 25247, image: oracle@hl_rdb01 (TNS V1-V3)

*** SESSION ID:(312.10459) 2009-05-20 16:21:58.423
*** 2009-05-20 16:21:58.423
==============
HANG ANALYSIS:
==============
Cycle 1 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/329/43816/0x4d6b5638/23487/rowcachelock>
--<0/254/19761/0x4d687438/23307/librarycachelock>
Cycle 2 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/295/57125/0x4d6b8978/19237/rowcachelock>
Cycle 3 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/295/57125/0x4d6b8978/19237/rowcachelock>
Open chains found:
Other chains found:
Chain 1 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/312/10459/0x4d69f9b8/25247/NoWait>
Extra information that will be dumped at higher levels:
[level 3] : 4 node dumps -- [IN_HANG]
[level 5] : 1 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]
[level 10] : 223 node dumps -- [IGN]

State of nodes

([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[0]/0/1/1/0x4d7146c0/5132/IGN/1/2//none

……………………………………………………

[238]/0/239/57618/0x4d7b18a0/13476/IN_HANG/395/402/[294][238][328][253]/none
……………………………………………………

[253]/0/254/19761/0x4d7bb710/23307/IN_HANG/397/400/[328][238][294]/294

………………………………………………………………

[294]/0/295/57125/0x4d7d6820/19237/IN_HANG/396/401/[294][238][253]/238
[328]/0/329/43816/0x4d7ecf40/23487/IN_HANG/398/399/[253]/253
………………………………………………………………

Dumping System_State and Fixed_SGA in process with ospid 13476
Dumping Process information for process with ospid 13476
Dumping Process information for process with ospid 23307
Dumping Process information for process with ospid 19237
Dumping Process information for process with ospid 23487

====================
END OF HANG ANALYSIS
====================
*** 2009-05-20 16:48:20.686

我们来看看([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor)部分：
nodenum是hanganalyze自己为了记录这些会话而定制的编号，从0开始排起。
cnode是Node Id
sid是 Session ID
sess_srno是serial#
proc_ptr是Process Pointer
ospid 是OS Process ID
state 是node的状态
adjlist是临近的node(通常代表一个blocker node)
predecessor是Predecessor node ,通常代表一个 waiter node

state部分有几个比较重要的状态：
1.IN_HANG：这表示该node处于死锁状态，通常还有其他node（blocker）也处于该状态
2.LEAF/LEAF_NW：该node通常是blocker。通过条目的”predecessor”列可以判断这个node是否是blocker。LEAF说明该NODE没有等待其他资源，而LEAF_NW则可能是没有等待其他资源或者是在使用CPU.
3.NLEAF：通常可以看作这些会话是被阻塞的资源。发生这种情况一般说明数据库发生性能问题而不是数据库hang
4.IGN/IGN_DMP：这类会话通常被认为是空闲会话，除非其adjlist列里存在node。如果是非空闲会话则说明其adjlist里的node正在等待其他node释放资源。
5.SINGLE_NODE/SINGLE_NODE_NW：近似于空闲会话

现在我们来看看我们的trace出来的文件：
Cycle 1 ::
<0/329/43816/0x4d6b5638/23487/row cache lock>
— <0/254/19761/0x4d687438/23307/library cache lock>
Cycle 2 ::
<0/295/57125/0x4d6b8978/19237/row cache lock>
Cycle 3 ::
<0/295/57125/0x4d6b8978/19237/row cache lock>

cycle表示oracle内部确定的死锁。其中我们的当前手工执行split的295进程也在里面。
我们观察其他的进程在做什么，如329：

SQL>l
1 selectmachine,status,program,sql_textfromv$sessiona,v$sqlareab
2*wherea.sql_address=b.addressanda.sid=329
SQL> /

MACHINE STATUS
---------------------------------------------------------------- --------
PROGRAM
------------------------------------------------
SQL_TEXT
--------------------------------------------------------------------------------
hl_rdb01 ACTIVE
sqlplus@hl_rdb01(TNSV1-V3)
ALTERTABLEA_PDA_SP_STATSPLITPARTITIONP_MAXAT(20090609) INTO(PARTITIONP
_20090608TABLESPACETS_DATA_A ,PARTITIONP_MAXTABLESPACETS_DATA_A)

SQL>selecteventfromv$session_waitwheresid=329;

EVENT
----------------------------------------------------------------
row cache lock

发现也是在执行split语句，但是问了同事，他已经把之前运行失败的脚本完全kill掉了。
估计在数据库中进程挂死了，没有完全的释放。
kill掉329号进程后，发现还是挂住，所以我们继续做hanganlyze：

==============
HANG ANALYSIS:
==============

Cycle 1 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/295/57125/0x4d6b8978/19237/rowcachelock>
Cycle 2 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/254/19761/0x4d687438/23307/librarycachelock>
--<0/239/57618/0x4d6b74f8/13476/rowcachelock>

我们继续把其他的进程杀掉。终于295的split执行成功。

SQL>ALTERTABLEA_PDA_SP_STATSPLITPARTITIONP_MAXAT(20090609)
INTO(PARTITIONP_20090608TABLESPACETS_DATA_A ,PARTITIONP_MAXTABLESPACETS_DATA_A)
SQL> /

Tablealtered.

Elapsed:00:31:03.21
SQL>

继续执行split下一个分区，也很快完成。

SQL>ALTERTABLEA_PDA_SP_STATSPLITPARTITIONP_MAXAT(20090610)
2 INTO(PARTITIONP_20090609TABLESPACETS_DATA_A
3 ,PARTITIONP_MAXTABLESPACETS_DATA_A);

Tablealtered.

Elapsed:00:00:00.02
SQL>
至此，问题解决.

[238]/0/239/57618/0x4d7b18a0/13476/IN_HANG/395/402/[294][238][328][253]/none
[253]/0/254/19761/0x4d7bb710/23307/IN_HANG/397/400/[328][238][294]/294
[294]/0/295/57125/0x4d7d6820/19237/IN_HANG/396/401/[294][238][253]/238
[328]/0/329/43816/0x4d7ecf40/23487/IN_HANG/398/399/[253]/253
329堵塞住了254
254堵塞住了295
295堵塞住了238

杀掉的应该是329,254,295