问题描述
本文链接地址: About Oracle Hanganalyze
1. 数据库hang的几种可能性
oracle死锁或者系统负载非常高比如cpu使用或其他一些锁等待很高都可能导致系统hang住，比如大量的DX锁。
通常来说，我们所指的系统hang住，是指应用无响应，普通的sqlplus几乎无法操作等等。
2. 如何进行hang分析？hang分析有哪些level？如何选择level？
hanganalyze有如下几种level：
10 Dump all processes (IGN state) 5 Level 4 + Dump all processes involved in wait chains (NLEAF state) 4 Level 3 + Dump leaf nodes (blockers) in wait chains (LEAF,LEAF_NW,IGN_DMP state) 3 Level 2 + Dump only processes thought to be in a hang (IN_HANG state) 1-2 Only HANGANALYZE output, no process dump at all
专家解答
从上面的信息看,在进行hanganalyze dump时有多种级别的level可以选择，那么如何选择level？
一般来讲,不建议使用level 3以上的操作,因为产生的trace可能会很大,尤其是大型的OLTP系统;
另外一般数据库hang住时可能系统压力都巨大,所以再产生很大的trace可能导致问题更加严重。
从oracle 9i开始hangalanyze 操作提供了针对Oracle RAC的支持,有如下2种方式：
1) ALTER SESSION SET EVENTS ‘immediate trace name HANGANALYZE level <level>’;
2) 使用oradebug 命令
ORADEBUG setmypid
ORADEBUG setinst all
ORADEBUG -g def hanganalyze <level> —针对rac的用法
对于单实例，我们通常进行如下操作即可:
oradebug setmypid
oradebug hanganalyze 3
其次在做hang分析的时候,建议同时做一个systemstate dump或针对个别的process进行processstate dump,如下：
---systemstate dump oradebug setmypid oradebug unlimit oradebug dump systemstate level 2; oradebug close_trace oradebug tracefile_name ---processstate dump oradebug setospid xxxx oradebug dump processstate level 3; oradebug close_trace oradebug tracefile_name
我们知道当一个数据库hang住时,最头痛的问题是无法登陆数据，也就无法进行故障的处理,因此很多人只能通过重启
操作系统来讲解决问题，其实从Oracle 10g开始,Oracle提供了prelim的登陆方式，如下:
sqlplus -prelim / as sysdba
oradebug setospid <process ID>
oradebug unlimit
oradebug dump systemstate 10
退一万步讲，即使我们无法通过SQLPLUS登陆数据库，仍然还是可以从操作系统层面入手的，即通过操作系统的命令来
对进程进行dump,例如aix环境中可以使用dbx命令来dump processstate，如下：
dbx -a PID (where PID = any oracle shadow process) —通过ps -ef|grep xxx查看
dbx() print ksudss(10)
…return value printed here
dbx() detach
3. 如何解读hang分析的trace文件，获取有用信息?
*** ACTION NAME:() 2010-03-12 00:04:01.497
*** MODULE NAME:(sqlplus@S7_C_YZ_YZSJK (TNS V1-V3)) 2010-03-12 00:04:01.497 —模块名 跟v$session.module_name一样
*** SERVICE NAME:(SYS$USERS) 2010-03-12 00:04:01.497
*** SESSION ID:(5184.45287) 2010-03-12 00:04:01.497 —-sid (5184) serial# (35287)
*** 2010-03-12 00:04:01.497
==============
HANG ANALYSIS:
==============
Found 54 objects waiting for <cnode/sid/sess_srno/proc_ptr/ospid/wait_event>
<0/5210/10419/0x99d0a88/11215038/No Wait> —从这里看 session 5210 阻塞了54个对象
Open chains found:
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> : —从这里开始以下的session都是被前面的5210阻塞
<0/5210/10419/0x99d0a88/11215038/No Wait>
— <0/3994/15494/0xd9ac1b0/6574102/enq: TM – contention>
— <0/4962/58962/0xca03618/5710044/enq: DX – contention>
Other chains found: —下面的session也是被前面所阻塞,被间接阻塞
Chain 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/4001/31548/0xf9f3ab0/4980956/enq: DX – contention>
Chain 3 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/4014/30717/0xaa27b48/7446746/gc buffer busy>
Chain 4 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/4039/42115/0xd9f5710/5595180/PX Deq: Table Q Normal>
Cycle 1 : <sid/sess_srno/proc_ptr/ospid/wait_event> : —cycle 通常是死锁 一般来说很有可能就是hang的根源
<980/3887/0xe4214964/24065/latch free>
— <2518/352/0xe4216560/24574/latch free>
— <55/10/0xe41236a8/13751/latch free>
如果trace中出现了Cycle，基本上Oracle就hang了。
4. 不同版本hang分析的差异？trace有何异同？
如下是oracle8~10g的 hanganalyze trace信息格式：
Oracle 8.x : [nodenum]/sid/sess_srno/session/state/start/finish/[adjlist]/predecessor
Oracle9i: [nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
Oracle10g：[nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
Nodenum –》 每个session做hanganalyze生成的一个序列号
sid –》 Session ID
sess_srno –》 Serial#
ospid –》 OS Process Id (v$process spid)
state –》 State of the node
adjlist –》 adjacent node (Usually represents a blocker node) –通常是阻塞者
predecessor –》 predecessor node (Usually represents a waiter node) –通常是被阻塞者
cnode –》 节点号 从9i开始才有
关于state 有如下几种值:
IN_HANG –》 该状态是一个非常危险的状态，通常表现为一个节点陷入了死循环或是hung。
一般来说出现这种情况，该节点的临辟节点也是一样的状态 即adjlist
例如：
[16]/0/17/154/0x24617be0/26800/IN_HANG/29/32/[185]/19 —从IN_HANG 我们可以看出185被16阻塞
[185]/1/16/4966/0x24617270//IN_HANG/30/31/[16]/16 —
LEAF –》通常是被认为blockers的重点对象。那么如何去确定呢？
一般根据后面的predecesor来判断该session是不是blocker或者是waiter。
例子：
[ nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor
[16]/0/17/154/0x24617be0/26800/LEAF/29/30//19 –从这里看19是waiter 因此我们认为17阻塞了20
[19]/0/20/13/0x24619830/26791/NLEAF/33/34/[16]/186
LEAF_NW –》跟leaf类似 不过可能会占用cpu
NLEAF –》该状态的session通常被认为 “stuck” session。即其他session所需要的资源正被其holding。
IGN –》该状态的session通常是处理IDLE状态，除非其adjlist存在，如果是，那么该session正在等待其他session。
IGN_DMP –》跟IGN类似。
例子：
[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
[189]/1/20/36/0x24619830//IGN/95/96/[19]/none
[176]/1/7/1/0x24611d80//IGN/75/76//none
从上面看，189在等待19,19在等待16，而176是一个idle session。
SINGLE_NODE，SINGLE_NODE_NW 可以认为跟LEAF，LEAF_NW一样，除非没有依赖对象。
5. 11g中hanganalyze trace格式的变化
我们知道从11g(应该是从11.1)开始,Oracle的trace格式相比10g而已，有很大的改变.hanganalyze trace格式也不例外.
如下是今天一个学生提到的问题，drop user xxxx cascade 删除用户时hang住. 通过oradebug hanganalyze 3我们来
寻找问题的根本原因，首先来看一下trace的内容 ：
*** 2014-01-23 10:53:59.779
===============================================================================
HANG ANALYSIS:
instances (db_name.oracle_sid): tlgdb.tlgdb
oradebug_node_dump_level: 3
analysis initiated by oradebug
os thread scheduling delay history: (sampling every 1.000000 secs)
0.000000 secs at [ 10:53:59 ]
NOTE: scheduling delay has not been sampled for 0.578092 secs 0.000000 secs from [ 10:53:55 - 10:54:00 ], 5 sec avg
0.000000 secs from [ 10:52:59 - 10:54:00 ], 1 min avg
0.000000 secs from [ 10:49:00 - 10:54:00 ], 5 min avg
vktm time drift history
===============================================================================
Chains most likely to have caused the hang:
[a] Chain 1 Signature: 'enq: TX - row lock contention' (cycle)
Chain 1 Signature Hash: 0xe6386940
===============================================================================
Cycles:
-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (tlgdb.tlgdb)
os id: 14027
process id: 19, oracle@sinosoft19 (TNS V1-V3)
session id: 191
session serial #: 3
}
is waiting for 'enq: TX - row lock contention' with wait info:
{
p1: 'name|mode'=0x54580004
p2: 'usn<<16 | slot'=0x90008
p3: 'sequence'=0x2e03
time in wait: 0.760805 sec
timeout after: never
wait id: 3836
blocking: 0 sessions
current sql: <none: error encountered - unable to get kgl lock no-wait>
short stack: ksedsts()+465<-ksdxfstk()+32<-ksdxcb()+1927<-sspuser()+112<-__sighandler()<-semtimedop()+10<-skgpwwait()+160<-ksliwat()+2022<-kslwaitctx()+163<-ksqcmi()+2848<-ksqgtlctx()+3501<-ksqgelctx()+557<-ktuGetTxForXid()+131<-ktcwit1()+336<-ktbgtl0()+1142<-kdiins0()+44906<-kdiinsp()+91<-kauxsin()+1784<-qesltcLoadIndexList()+922<-qesltcLoadIndexes()+55<-qerltcNoKdtBufferedInsRowCBK()+374<-qerltcSingleRowLoad()+279<-qerltcFetch()+380<-insexe()+682<-opiexe()+5632<-opipls()+2164<-opiodr()+917<-rpidrus()+211<-skgmstack()+148<-rp
wait history:
* time between current wait and wait #1: 0.002079 sec
1. event: 'utl_file I/O'
time waited: 0.000011 sec
wait id: 3835 p1: ''=0x3
* time between wait #1 and #2: 0.000005 sec
2. event: 'utl_file I/O'
time waited: 0.000000 sec
wait id: 3834 p1: ''=0x1
* time between wait #2 and #3: 0.000003 sec
3. event: 'utl_file I/O'
time waited: 0.000001 sec
wait id: 3833 p1: ''=0x1
}
and is blocked by the session at the start of the chain.
Chain 1 Signature: 'enq: TX - row lock contention' (cycle)
Chain 1 Signature Hash: 0xe6386940
-------------------------------------------------------------------------------
===============================================================================
Extra information that will be dumped at higher levels:
[level 3] : 1 node dumps -- [UNDEF] [IN_HANG]
State of ALL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[190]/1/191/3/0x1eb8ac1b0/14027/IN_HANG/[190]
*** 2014-01-23 10:53:59.788
===============================================================================
END OF HANG ANALYSIS
===============================================================================
*** 2014-01-23 10:53:59.788
===============================================================================
HANG ANALYSIS DUMPS:
oradebug_node_dump_level: 3
===============================================================================
State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[190]/1/191/3/0x1eb8ac1b0/14027/IN_HANG/[190]
Dumping call stack for process with ospid 14027
Dumping call stack for process with ospid 14027
Dumping detailed process information (fixed sga, context, etc.) for ospid 14027
dump location: /u01/app/oracle/diag/rdbms/tlgdb/tlgdb/trace/tlgdb_ora_14027.trc
*** 2014-01-23 10:54:01.005
===============================================================================
HANG ANALYSIS DUMPS: END
===============================================================================大家可以看到trace的内容跟10g版本相比，变化比较大，其实这看起来更容易一些了，只是我们还不太习惯而已。
当然，重点是这一段内容：
State of ALL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[190]/1/191/3/0x1eb8ac1b0/14027/IN_HANG/[190]
我们将上述内容进行分解:
nodenum： 190 表示sid
cnode: 1 表示数据库节点编号
sid: 191 表示sid
0x1eb8ac1b0: 3 表示serial#号
session: 0x1eb8ac1b0 表示该Session的saddr地址
ospid: 14027 表示该session的操作系统进程编号
state: IN_HANG 表示该session的状态
adjlist: 190 表示blocker的sid值
当我们将上述内容分解之后，你会发现,之所以drop user没反应，是因为被sid 190所阻塞了，那么我们最后来看一下
sid=190 是什么进程：
SYS@tlgdb> select p.SPID from v$session s,v$process p 2 where s.PADDR=p.ADDR and s.SID=190; SPID ------------------------ 14014 [oracle@sinosoft19 trace]$ ps -ef | grep 14014 oracle 14014 1 0 10:44 ? 00:00:00 ora_mmon_tlgdb oracle 14682 14251 0 11:12 pts/0 00:00:00 grep 14014
很显然,mmon进程为非核心进程,我们可以直接kill掉。当然最后kill mmon进程之后drop user很快完成.
