0

About Oracle Hanganalyze

Roger 2019-06-17
23
摘要:通常来说,我们所指的系统hang住,是指应用无响应,普通的sqlplus几乎无法操作等等。

问题描述

本文链接地址: 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 &lt;process ID&gt;
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&lt;&lt;16 | slot'=0x90008
 p3: 'sequence'=0x2e03
 time in wait: 0.760805 sec
 timeout after: never
 wait id: 3836
 blocking: 0 sessions
 current sql: &lt;none: error encountered - unable to get kgl lock no-wait&gt;
 short stack: ksedsts()+465&lt;-ksdxfstk()+32&lt;-ksdxcb()+1927&lt;-sspuser()+112&lt;-__sighandler()&lt;-semtimedop()+10&lt;-skgpwwait()+160&lt;-ksliwat()+2022&lt;-kslwaitctx()+163&lt;-ksqcmi()+2848&lt;-ksqgtlctx()+3501&lt;-ksqgelctx()+557&lt;-ktuGetTxForXid()+131&lt;-ktcwit1()+336&lt;-ktbgtl0()+1142&lt;-kdiins0()+44906&lt;-kdiinsp()+91&lt;-kauxsin()+1784&lt;-qesltcLoadIndexList()+922&lt;-qesltcLoadIndexes()+55&lt;-qerltcNoKdtBufferedInsRowCBK()+374&lt;-qerltcSingleRowLoad()+279&lt;-qerltcFetch()+380&lt;-insexe()+682&lt;-opiexe()+5632&lt;-opipls()+2164&lt;-opiodr()+917&lt;-rpidrus()+211&lt;-skgmstack()+148&lt;-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&gt; 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很快完成.

「喜欢文章,快来给作者赞赏墨值吧」

评论

0
0
Oracle
订阅
欢迎订阅Oracle频道,订阅之后可以获取最新资讯和更新通知。
墨值排行
今日本周综合
近期活动
全部
相关课程
全部