转载

基于oracle 10.2.0.1 rac使用oradebug dump hanganalyze 分析oracle hang系列四

背景

发现oracle 10.2.0.1 rac的SQL查询也HANG住了，借此用下hanganalyze，练练手，但发现基于RAC的HANGANALYZE与单实例的TRACE FILE区别相当大，一时也抓不到头绪，
既然如此，学习下基于RAC的HANAANALYZE的产生TRACE FILE的格式及内容构成。

结论

1,基于rac环境下
默认的RAC下的ORADEBUG DUMP HANGANALYZE 3与ORADEBUG SETINST ALL以及ORADEBUG DUMP HANGANALYZE 3产生的TRACE FILE内容相同

2,trace file共计4个部分
2.1，第一部分
Open chains found: --这是第一部分，这个部分可能有值，也可能无值，经过对比，发现如果DB HANG，此部分会有值

2.2, 第二部分
Other chains found: --这是第二部分
Chain 1 : :
<1>

2.3,第三部分
Extra information that will be dumped at higher levels: ---如果DUMP级别越高，获取的信息越多，下为具体的讲解
[level 5] : 6 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]
[level 10] : 21 node dumps -- [IGN]

2.4，第四部分
State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[135]/1/136/47/0x83b53b38/22712/IGN/1/2//none
[136]/1/137/1/0x83b54f70/7504/SINGLE_NODE/3/4//none --可见predecessor全为none
[137]/1/138/2/0x83b563a8/7377/SINGLE_NODE/5/6//none
[139]/1/140/5/0x83b58c18/7137/SINGLE_NODE/7/8//none --可见adjlist为

3，trace file中一些标识的含义：
cnode即生成hanganalyze的RAC节点编号（节点编号从0开始，依次递增），这个其实对于分析没有什么实质的意义，不过可以从这个看出，TRACEFILE是在哪个RAC节点生成的
start及finish感觉好像是2个连续的数字，并且采用回环式前进编号，即1，2为对应一条记录，然后3，4对应下面的记录，依次类推
sess_srno为session为v$session.saddr

4,同时从另一个RAC节点，可见在持锁会话的告警日志会提示持锁进程的信息以及生成TRACE FILE
Tue Nov 10 09:00:06 2015
GES: Potential blocker (pid=3541) on resource TX-0xa0007-0x87;
enqueue info in file /u01/app/oracle/admin/jingfa/bdump/jingfa1_lmd0_15271.trc and DIAG trace file
引申下，即发生锁问题，可以从告警日志找到相关的线索，进一步分析

分析方法

1,以模拟环境生成trace file,以理解其内容，尔后反推和生产环境进行比对参考学习
2,对比性学习，即如果对某个值不同，以正向测试下，再以反向测试下，可以了解此值或标识的含义

测试

--node1

SQL> select sid,serial#,saddr from v$session where sid=(select sid from v$mystat where rownum=1);

SID SERIAL# SADDR
---------- ---------- ----------------
153 5 0000000083B692F0

SQL> select pid,spid from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum=1));

PID SPID
---------- ------------
18 3541

SQL> select * from t_lock;

A B
---------- ----------
1 1
2 2

--node2

SQL> conn tbs_zxy/system
Connected.
SQL> select sid,serial#,saddr from v$session where sid=153;

SID SERIAL# SADDR
---------- ---------- ----------------
153 5 0000000083B692F0

SQL> select pid,spid from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum=1));

PID SPID
---------- ------------
18 31569

--node1
SQL> update t_lock set a=11 where a=1;

1 row updated.

--node2
SQL> update t_lock set a=121 where a=1;

--hang住

---node2
--生成一个tracefile
SQL> oradebug setmypid
Statement processed.
SQL> oradebug dump hanganalyze 3
Statement processed.
SQL> oradebug tracefile_name

==============
HANG ANALYSIS:
==============
Open chains found: --这是第一部分，这个部分可能有值，也可能无值，经过对比，发现如果DB HANG，此部分会有值
Other chains found: --这是第二部分
Chain 1 : :
<1>
Chain 2 : :
<1>
Chain 3 : : --空闲等待事件不用关注
<1>
Chain 4 : :
<1> --No Wait表明当前会话不等待什么资源，不用关注
Chain 5 : :
<1> ---需要关注，直接可以定位到
Chain 6 : :
<1>

如下为第三部分
Extra information that will be dumped at higher levels: ---如果DUMP级别越高，获取的信息越多，下为具体的讲解
[level 5] : 6 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]
[level 10] : 21 node dumps -- [IGN]

此为第四部分
State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[135]/1/136/47/0x83b53b38/22712/IGN/1/2//none
[136]/1/137/1/0x83b54f70/7504/SINGLE_NODE/3/4//none --可见predecessor全为none
[137]/1/138/2/0x83b563a8/7377/SINGLE_NODE/5/6//none
[139]/1/140/5/0x83b58c18/7137/SINGLE_NODE/7/8//none --可见adjlist为空
[142]/1/143/1/0x83b5c8c0/6971/IGN/9/10//none
[143]/1/144/1/0x83b5dcf8/6944/IGN/11/12//none
[144]/1/145/1/0x83b5f130/6950/IGN/13/14//none
[147]/1/148/645/0x83b62dd8/5400/SINGLE_NODE_NW/15/16//none --start及finish感觉好像是2个连续的数字，并且采用回环式前进编号，即1，2为对应一条记录，然后3，4对应下面的记录，依次类推
[149]/1/150/1/0x83b65648/6710/IGN/17/18//none
[150]/1/151/1/0x83b66a80/6706/IGN/19/20//none
[152]/1/153/5/0x83b692f0/31569/SINGLE_NODE/21/22//none --等待者的信息，session为v$session.saddr
[153]/1/154/1/0x83b6a728/6701/IGN/23/24//none
[154]/1/155/1/0x83b6bb60/6649/IGN/25/26//none
[155]/1/156/1/0x83b6cf98/6647/IGN/27/28//none
[156]/1/157/1/0x83b6e3d0/6645/IGN/29/30//none
[157]/1/158/1/0x83b6f808/6643/IGN/31/32//none
[158]/1/159/1/0x83b70c40/6641/IGN/33/34//none
[159]/1/160/1/0x83b72078/6639/IGN/35/36//none
[160]/1/161/1/0x83b734b0/6637/IGN/37/38//none
[161]/1/162/1/0x83b748e8/6635/IGN/39/40//none
[162]/1/163/1/0x83b75d20/6633/IGN/41/42//none
[164]/1/165/1/0x83b78590/6629/IGN/43/44//none
[165]/1/166/1/0x83b799c8/6627/IGN/45/46//none
[166]/1/167/1/0x83b7ae00/6625/IGN/47/48//none
[167]/1/168/1/0x83b7c238/6623/IGN/49/50//none
[168]/1/169/1/0x83b7d670/6621/SINGLE_NODE/51/52//none
[169]/1/170/1/0x83b7eaa8/6619/IGN/53/54//none
====================
END OF HANG ANALYSIS
====================
/u01/app/oracle/admin/jingfa/udump/jingfa2_ora_5400.trc

同时从另一个RAC节点，可见在持锁会话的告警日志会提示持锁进程的信息以及生成TRACE FILE
Tue Nov 10 09:00:06 2015
GES: Potential blocker (pid=3541) on resource TX-0xa0007-0x87;
enqueue info in file /u01/app/oracle/admin/jingfa/bdump/jingfa1_lmd0_15271.trc and DIAG trace file

--node2
上述TRACE FILE是基于单实例模式生成TRACE FILE，我们基于RAC环境再生成下TRACE FILE，对比看内容有何区别

SQL> oradebug setinst all
Statement processed.
SQL> oradebug dump hanganalyze 3
Statement processed.
SQL> oradebug tracefile_name
/u01/app/oracle/admin/jingfa/udump/jingfa2_ora_1139.trc

经过对比，默认的RAC下的ORADEBUG DUMP HANGANALYZE 3与ORADEBUG SETINST ALL以及ORADEBUG DUMP HANGANALYZE 3产生的TRACE FILE内容相同

==============
HANG ANALYSIS:
==============
Open chains found:
Other chains found:
Chain 1 : :
<1>
Chain 2 : :
<1>
中间内容略
[166]/1/167/1/0x83b7ae00/6625/IGN/47/48//none
[167]/1/168/1/0x83b7c238/6623/IGN/49/50//none
[168]/1/169/1/0x83b7d670/6621/SINGLE_NODE/51/52//none
[169]/1/170/1/0x83b7eaa8/6619/IGN/53/54//none
====================
END OF HANG ANALYSIS
====================

再看看下cnode的含义
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[135]/1/136/47/0x83b53b38/22712/IGN/1/2//none

我们调整下在RAC2个节点阻塞者及等待者的顺序

---node2
SQL> select sid,serial#,saddr from v$session where sid=(select sid from v$mystat where rownum=1);

SID SERIAL# SADDR
---------- ---------- ----------------
153 20 0000000083B692F0

SQL> select pid,spid from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum=1));

PID SPID
---------- ------------
18 15971

SQL> update t_lock set a=11 where a=1;

1 row updated.

---node1

SQL> select sid,serial#,saddr from v$session where sid=(select sid from v$mystat where rownum=1);

SID SERIAL# SADDR
---------- ---------- ----------------
153 9 0000000083B692F0

SQL> select pid,spid from v$process where addr=(select paddr from v$session where sid=(select sid from v$mystat where rownum=1));

PID SPID
---------- ------------
18 27178

SQL> update t_lock set a=123 where a=1;

hang住

--node1
生成trace file

SQL> oradebug setmypid
Statement processed.
SQL> oradebug dump hanganalyze 3
Statement processed.
SQL> oradebug tracefile_name
/u01/app/oracle/admin/jingfa/udump/jingfa1_ora_30236.trc

---可见在NODE1生成trace file,cnode为0
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[136]/0/137/6/0x83b54f70/31964/IGN/1/2//none
中间内容略
[167]/0/168/1/0x83b7c238/15267/IGN/43/44//none
[168]/0/169/1/0x83b7d670/15265/SINGLE_NODE/45/46//none
[169]/0/170/1/0x83b7eaa8/15263/IGN/47/48//none

---延续上，在node2生成TRACE FILE
---可见在NODE2生成trace file,cnode为1
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[135]/1/136/47/0x83b53b38/22712/IGN/1/2//none
[136]/1/137/1/0x83b54f70/7504/SINGLE_NODE/3/4//none
中间内容略
[169]/1/170/1/0x83b7eaa8/6619/IGN/53/54//none

可见在不同RAC节点生成hanganalyze ,其cnode对应生成hanganalyze的RAC节点编号（节点编号从0开始，依次递增）
这个其实对于分析没有什么实质的意义，不过可以从这个看出，TRACEFILE是在哪个RAC节点生成的

正文到此结束