About Oracle Hanganalyze
本站文章除注明转载外，均为本站原创： 转载自love wife love life —Roger的Oracle/MySQL/PostgreSQL数据恢复博客
本文链接地址: About Oracle Hanganalyze
1. 数据库hang的几种可能性
oracle死锁或者系统负载非常高比如cpu使用或其他一些锁等待很高都可能导致系统hang住，比如大量的DX锁。
通常来说，我们所指的系统hang住，是指应用无响应，普通的sqlplus几乎无法操作等等。
2. 如何进行hang分析？hang分析有哪些level？如何选择level？
hanganalyze有如下几种level：
|
1 2 3 4 5 |
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,如下：
|
1 2 3 4 5 6 7 8 9 10 11 12 |
---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的登陆方式，如下:
|
1 |
sqlplus -prelim / as sysdba |
|
1 |
oradebug setospid <process ID> |
|
1 |
oradebug unlimit |
|
1 |
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的内容 ：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 |
*** 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 是什么进程：
|
1 2 3 4 5 6 7 8 9 10 |
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很快完成.
6 Responses to “About Oracle Hanganalyze”
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[190]/1/191/3/0x1eb8ac1b0/14027/IN_HANG/[190]
我们将上述内容进行分解:
State of LOCAL nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
[45]/1/46/49/0x8d6d5174/3966/NLEAF/[51]
[51]/1/52/35/0x8d6c453c/3928/LEAF/
我做出来的51并不是sid号 而是52号sid是blocker
兄弟，你看错地方了，我那里是in_hang的状态，是ok的。如果是nleaf，leaf的状态，应该看我上面写的内容，如下：
例子：
[ 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/0×24619830/26791/NLEAF/33/34/[16]/186
您的意思就是不用看其他的 leaf状态的就是阻塞源头 nleaf的就是被阻塞的 是这样理解吗
[16]/0/17/154/0x24617be0/26800/IN_HANG/29/32/[185]/19 —从IN_HANG 我们可以看出185被16阻塞
[185]/1/16/4966/0×24617270//IN_HANG/30/31/[16]/16 —
这段看不懂 2个都是in_hang 怎么判断哪个是堵塞者 哪个被堵塞？
[…] 一个insert也能死锁吗？这里不是太清楚，知道的朋友可以指点一下，因为drop的时候hang住了，所以这里想到了做hanganalyze分析一下，这里采用是的3级的hanganalyze分析，当是也是roger老师提示的，具体的分析hanganalyze的知识点和分析过程可以参考http://www.killdb.com/2014/01/23/about-oracle-hanganalyze.html当然我的这个案例也被他引入了，但是MMON 是可管理性监视器（Manageability Monitor），MMON主要用于AWR，ADDM，MMON会从SGA将统计结果写到系统表中。这是这个进程的作用，但是为什么跟删除一个用户有关系，原因还是不清楚希望知道的朋友指点下。 喜欢 0 抢沙发 分享 标签： […]
[…] repeatedly waiting*/ SPOOL OFF; 获取了数据之后 就是分析了！！ Reference: http://www.killdb.com/2014/01/23/about-oracle-hanganalyze/ http://blog.itpub.net/205377/viewspace-2124541/ 赞(0) 打赏 […]
Leave a Reply
You must be logged in to post a comment.