使用Oracle Hanganalyze诊断Oracle故障及等待事件

客户突然报障说系统比较慢，登录Oracle数据库服务器查看系统资源非常忙,登录数据库发现非常卡,现在介绍一下使用Oracle Hanganalyze来分析与诊断的过程

1、首先介绍一下为什么要使用Hanganalyze？

Hanganalyze工具使用内核调用检测会话在等待什么资源，报告出占有者和等待者的相互关系。另外，它还会将一些比较”interesting”的进程状态dump出来，这个取决于我们使用hanganalyze的分析级别。

Oracle 数据库“真的”hang住了，可以理解为数据库内部发生死锁。因为普通的DML死锁，oracle服务器会自动监测他们的依赖关系，并回滚其中一个操作， 终止这种相互等待的局面。而当这种死锁发生在争夺内核级别的资源（比如说是pins或latches）时，Oracle并不能自动的监测并处理这种死锁。
其实很多时候数据库并没有hang住，而只是由于数据库的性能问题，处理的时间比较长而已。
hanganalyze工具从oracle8i第二版开始提供，到9i增强了诊断RAC环境下的“集群范围”的信息，这意味着它将会报告出整个集群下的所有会话的信息。

2、hanganalyze基本的使用方法

目前有三种使用hanganalyze的方法:
一种是会话级别的：
SQL>ALTER SESSION SET EVENTS 'immediate trace name HANGANALYZE level ';

一种是实例级别:
SQL>ORADEBUG hanganalyze

一种是Oracle RAC集群范围的：
SQL>ORADEBUG setmypid
SQL>ORADEBUG setinst all
SQL>ORADEBUG -g def hanganalyze

各个level的含义如下：
1-2:只有hanganalyze输出，不dump任何进程
3：Level2+Dump出在IN_HANG状态的进程
4：Level3+Dump出在等待链里面的blockers(状态为LEAF/LEAF_NW/IGN_DMP)
5：Level4+Dump出所有在等待链中的进程（状态为NLEAF）
Oracle官方建议不要超过level 3，一般level 3也能够解决问题，超过level 3会给系统带来额外负担。
如果sqlplus不能登录,可以使用[color=#cc0000]sqlplus -[color=#cc0000]prelim /as sysdba登录操作。

3、案例分析过程
登录数据库：
SQL> ORADEBUG setmypid
Statement processed.
SQL> ORADEBUG setinst all
Statement processed.
SQL> ORADEBUG -g def hanganalyze 3
Hang Analysis in /oracle/diag/rdbms/yydb/yydb1/trace/yydb1_diag_4260840.trc

如果得到相应的trc文件，这里介绍获取trc文件的另外两种方法：

1）使用oradebug跟踪：
oradebug setmypid
[color=#cc00]oradebugtracefile_name

其中oradebug setmypid是跟踪自己当时的进程，如果是跟踪其它进程呢？
如果是系统的进程ID，可以使用oradebug setospid id.来追踪。如果是根据Oracle ID，可以使用oradebug setorapid id 来追踪。
下面介绍一下如何查找进程ID，可以查询Linux系统的pid或是oracle自己的pid：SQL> select a.username,a.sid ,a.serial#,b.spid from v$session a,v$process b where a.paddr=b.addr;
USERNAME SID SERIAL# SPID---------- ---------- ---------- ------------SYS 159 1702 27028

查询spidSQL> select pid,spid,username from v$process;
PID SPID USERNAME---------- ------------ ---------- 18 27028 oracle
[color=green]v$process 下的pid 是Oracle 的ID。spid 是系统的ID。

SQL> oradebug setospid 27028 -- 根据系统IDOracle pid: 18, Unix process pid: 27028, image: mailto:system@db]system@db
或者：SQL> oradebug setorapid 18 --根据Oracle IDUnix process pid: 27028, image: system@db

[color=#cc00]2）使用sql语句
[color=#08080]SELECT[color=#0080] d.VALUE || '/'[color=#0080] || [color=#08080]LOWER[color=#0080]([color=#08080]RTRIM[color=#0080](i.INSTANCE, [color=#08080]CHR[color=#0080](0[color=#0080]))) || '_ora_'[color=#0080] ||
[color=#0080] p.spid || '.trc'[color=#0080] [color=#08080]AS[color=#0080] "trace_file_name"
[color=#0080] [color=#08080]FROM[color=#0080] ([color=#08080]SELECT[color=#0080] p.spid
[color=#0080] [color=#08080]FROM[color=#0080] v$mystat m, v$session s, v$process p
[color=#0080] [color=#08080]WHERE[color=#0080] m.statistic# = 1
[color=#0080] [color=#08080]AND[color=#0080] s.SID = m.SID
[color=#0080] [color=#08080]AND[color=#0080] p.addr = s.paddr) p,
[color=#0080] ([color=#08080]SELECT[color=#0080] t.INSTANCE
[color=#0080] [color=#08080]FROM[color=#0080] v$thread t, v$parameter v
[color=#0080] [color=#08080]WHERE[color=#0080] v.NAME = 'thread'
[color=#0080] [color=#08080]AND[color=#0080] (v.VALUE = 0[color=#0080] [color=#08080]OR[color=#0080] t.thread# = TO_NUMBER(v.VALUE))) i,
[color=#0080] ([color=#08080]SELECT[color=#0080] [color=#08080]VALUE[color=#0080] [color=#08080]FROM[color=#0080] v$parameter [color=#08080]WHERE[color=#0080] [color=#08080]NAME[color=#0080] = 'user_dump_dest'[color=#0080]) d;

[color=#cc00]查看HANGANALYZE log的内容，发现大量的TX锁等待，154 sessions锁住了141，如果trc比较乱，可以使用ass.awk工具分析。
*** SERVICE NAME:(SYS$USERS) 2012-11-10 09:48:36.421
*** SESSION ID:(142.24) 2012-11-10 09:48:36.421
*** 2012-11-10 09:48:36.421
==============
HANG ANALYSIS:
==============
Open chains found:
Chain 1 : :
<0/154/3/0x3424d7dc/9544/SQL*Net message from client>
-- <0/141/14/0x3424d1ec/9720/enq: TX - row lock contention>
Other chains found:
Chain 2 : :
<0/142/24/0x3424e3bc/9112/No Wait>
Chain 3 : :
<0/146/2/0x3425075c/10724/Streams AQ: qmn slave idle wait>
Chain 4 : :
<0/149/32/0x3424cbfc/8452/jobq slave wait>
Chain 5 : :
<0/153/4/0x3424ddcc/10600/Streams AQ: qmn coordinator idle>
Chain 6 : :
<0/158/4/0x3424c60c/8736/Streams AQ: waiting for time man>
Extra information that will be dumped at higher levels:
[level 4] : 1 node dumps -- [REMOTE_WT] [LEAF] [LEAF_NW]
[level 5] : 5 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]
[level 6] : 1 node dumps -- [NLEAF]
[level 10] : 11 node dumps -- [IGN]

State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[[color=#c000]140]/0/141/14/0x3432a014/9720/NLEAF/1/4/[[color=#c000]153]/none
[141]/0/142/24/0x3432b2dc/9112/SINGLE_NODE_NW/5/6//none
[145]/0/146/2/0x3432fdfc/10724/SINGLE_NODE/7/8//none
[148]/0/149/32/0x34333654/8452/SINGLE_NODE/9/10//none
[152]/0/153/4/0x34338174/10600/SINGLE_NODE/11/12//none
[[color=#c000]153]/0/154/3/0x3433943c/9544/LEAF/2/3//[color=#c000]140
[157]/0/158/4/0x3433df5c/8736/SINGLE_NODE/13/14//none
[159]/0/160/1/0x343404ec/11228/IGN/15/16//none
[160]/0/161/1/0x343417b4/11836/IGN/17/18//none
[161]/0/162/1/0x34342a7c/11656/IGN/19/20//none
[162]/0/163/1/0x34343d44/9420/IGN/21/22//none
[163]/0/164/1/0x3434500c/5700/IGN/23/24//none
[164]/0/165/1/0x343462d4/9476/IGN/25/26//none
[165]/0/166/1/0x3434759c/4908/IGN/27/28//none
[166]/0/167/1/0x34348864/12156/IGN/29/30//none
[167]/0/168/1/0x34349b2c/8496/IGN/31/32//none
[168]/0/169/1/0x3434adf4/10732/IGN/33/34//none
[169]/0/170/1/0x3434c0bc/11856/IGN/35/36//none
====================
END OF HANG ANALYSIS
====================
从上面可以看到sid 154锁住了141，所以只要将154 kill掉，141就可以继续执行了。

Kill掉154的session可以有两种办法：

1、alter system kill session ‘sid,serial#’;
SQL> [color=#8000]select s.sid,s.serial#,p.spid from v$process p,v$session s where p.addr=s.paddr and s.username='[color=#8000]TEST1[color=#8000]';

SID SERIAL# SPID
---------- ---------- ------------
141 14 9720
154 3 9544

SQL>[color=#8000] alter system kill session '154,3';

系统已更改。

2、杀进程
[color=#8000]如果是[color=#8000]windows:[color=#8000]在[color=#8000]DOC[color=#8000]窗口下执行：[color=#8000]orakill ORACLE_SID ospid
orakill TEST1 9544
[color=#8000]如果是[color=#8000]Unix[color=#8000]或者[color=#8000]linux[color=#8000]下，那么就用[color=#8000]kill -9 ospid

执行kill操作后：回到窗口A看到：通道结束
在窗口B看到成功删除。

4、关于HANGANALYZE的TRC文件中术语解释

[color=navy]sid是 Session ID
sess_srno是serial#
proc_ptr是Process Pointer
ospid 是OS Process ID
cnode是Node Id，Oracle9i才用
Nodenum是hanganalyze
自己为了记录这些会话而定制的编号，从0开始排起。
State 是node的状态
Adjlist是临近的node(通常代表一个blocker node)
Predecessor是Predecessor node ,通常代表一个 waiter node

State有如下几种状态： [color=navy]IN_HANG：这表示该node处于死锁状态，通常还有其他node（blocker）也处于该状态
LEAF/LEAF_NW：该node通常是blocker。通过条目的”predecessor”列可以判断这个node是否是blocker。LEAF说明该NODE没有等待其他资源，而LEAF_NW则可能是没有等待其他资源或者是在使用CPU.
[color=navy]如下的实例说明了node16阻塞了node19的资源：
[nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
[16]/0/17/154/0x24617be0/26800/LEAF/29/30//19
[19]/0/20/13/0x24619830/26791/NLEAF/33/34/[16]/186
[color=navy]NLEAF：通常可以看作这些会话是被阻塞的资源。发生这种情况一般说明数据库发生性能问题而不是数据库hang
IGN/IGN_DMP：这类会话通常被认为是空闲会话，除非其adjlist列里存在node。如果是非空闲会话则说明其adjlist里的node正在等待其他node释放资源。
SINGLE_NODE/SINGLE_NODE_NW：近似于空闲会话

5、Scripts-Hanganalyze and systemstate
sqlplus -prelim / as sysdba;

Hanganalyze and systemstate

$ sqlplus /nolog
connect / as sysdba
oradebug setmypid
oradebug unlimit
oradebug hanganalyze 3
wait 90 seconds
oradebug hanganalyze 3
exit

$ sqlplus /nolog
connect / as sysdba
oradebug setmypid
oradebug unlimit
oradebug dump systemstate 10
wait 90 seconds
oradebug dump systemstate 10
wait 90 seconds
oradebug dump systemstate 10
exit

Use level 266 where appropriate

Related articles
Note 61552.1 Diagnosing Database Hanging Issues
Note.215858.1 Interpreting HANGANALYZE trace files to diagnose hanging and performance problems
Note.423153.1 Understanding and Reading Systemstates

266: 256+10 -->short stack+ dump

--如果是-g all，代表RAC

systemstate dump有多个级别：
　　2: dump (不包括lock element)
　　10: dump
　　11: dump + global cache of RAC
　　256: short stack （函数堆栈）
　　258: 256+2 –>short stack +dump(不包括lock element)
　　266: 256+10 –>short stack+ dump
　　267: 256+11 –>short stack+ dump + global cache of RAC
　　level 11和 267会 dump global cache, 会生成较大的trace 文件，一般情况下不推荐。
　　一般情况下，如果进程不是太多，推荐用266，因为这样可以dump出来进程的函数堆栈，可以用来分析进程在执行什么操作。
　　但是生成short stack比较耗时，如果进程非常多，比如2000个进程，那么可能耗时30分钟以上。这种情况下，可以生成level 10 或者 level 258， level 258 比 level 10会多收集short short stack, 但比level 10少收集一些lock element data.