Skip to content

Oracle的hanganalyze分析工具介绍及测试示例分析

1. HANGANALYZE绍及命令

此部分信息主要参考MOS文档:Interpreting HANGANALYZE trace files to diagnose hanging and performance problems for 9i and 10g. (文档 ID 215858.1)

1.1 使用hanganalyze的场景:

当数据库出现严重的性能问题时,问题的原因可能是HANG。 使用HANGANALYZE生成的跟踪文件,将能够快速确定两个或多个进程是否死锁以及多少其他进程可能会受到影响。 通过使用HANGANALYZE,还可以确定在发生HANG时是否需要执行性能分析来诊断真实问题。

 

很多时候数据库并没有hang住,而只是由于数据库的性能问题,处理的时间比较长。Hanganalyze工具使用内核调用检测会话在等待什么资源,报告出占有者和等待者的相互关系。另外,它还会将一些比较”interesting”的进程状态dump出来,这个取决于我们使用hanganalyze的分析级别。

 

“true” hang,可理解为数据库内部发生死锁。普通的DML产生死锁时oracle服务器会自动监测他们的依赖关系并回滚其中一个操作, 终止这种相互等待的局面。而当这种死锁发生在争夺内核级别的资源(比如说是pins或latches)时,Oracle并不能自动的监测并处理这种死锁。

 

hanganalyze工具从8.1.6可用,在9i增强了诊断RAC环境下的信息,在任一节点执行即可报告出整个集群下的所有会话的信息。

 

1.2 SYSTEMSTATEHANGANALYZE在处理hang问题时的对比:

SYSTEMSTATE处理hang问题时有如下不足:

SYSTEMSTATE dump reads the SGA in a “dirty” manner, so it may be inconsistent when the time to dump all the process is long.

转储时间过长时可能会读到非一致的数据

SYSTEMSTATE dump usually dumps a lot of information (most of which is not needed to determine the source of the hang), which makes difficult to determine the dependencies between processes quickly.

通过会转储大量无关的信息,不利于快速分析

SYSTEMSTATE dumps do not identify “interesting” processes on which to perform additional dumps (ERRORSTACK or PROCESS STATE).

1.3 HANGANALYZE处理hang问题的方式:

HANGANALYZE使用内部内核调用来确定会话是否正在等待资源,并报告阻塞者和被阻塞者之间的关系。 此外,它将“interesting”进程转储,并且根据在执行HANGANALYZE时使用的level在这些进程上执行自动PROCESSSTATE转储和ERRORSTACKS。

注意:HANGANALYZE不是用来替换SYSTEMSTATE转储,而是可以在诊断复杂问题的同时作为解释SYSTEMSTATE的路线图。

 

 

1.4 HANGANALYZE命令示例及level

会话级别的:
SQL>ALTER SESSION SET EVENTS ‘immediate trace name HANGANALYZE level <level>’;实例级别: ===》》需要以SYSDBA; sqlplus -prelim / as sysdba 或者sqlplus  / as sysdba
SQL>ORADEBUG hanganalyze <level>

 

单实例:

oradebug setmypid

oradebug unlimit

oradebug tracefile_name

oradebug hanganalyze 3

 

 

集群范围的:
SQL>ORADEBUG setmypid
SQL>ORADEBUG setinst all
SQL>ORADEBUG -g def hanganalyze <level>

或者:

For 11g:

sqlplus ‘/ as sysdba’

oradebug setorapname reco

oradebug  unlimit

oradebug -g all hanganalyze 3

exit

 

For 10g, run oradebug setmypid instead of oradebug setorapname reco:

sqlplus ‘/ as sysdba’

oradebug setmypid

oradebug unlimit

oradebug -g all hanganalyze 3

oradebug tracefile_name

exit

各个level的含义如下:
1-2:只有hanganalyze输出,不dump任何进程
3:Level2+Dump出在IN_HANG状态的进程
4:Level3+Dump出在等待链里面的blockers(状态为LEAF/LEAF_NW/IGN_DMP)
5:Level4+Dump出所有在等待链中的进程(状态为NLEAF)

10 :Dump all processes (IGN state)

Oracle官方建议不要超过level 3,一般level 3也能够解决问题,超过level 3会给系统带来较大负载。

 

1.5 HANGANALYZE trace文件分析- State of ALL nodes部分

LINUX64+11.2.0.4单实例使用删除不提交模拟TX等待时的TRACE:

 

State of ALL nodes  =====》》》全部节点的状态, 单实例时和state of local nodes内容一样

([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):

[0]/1/1/7/0xc38b1360/1966/LEAF/  =====》》》 LEAF/持锁会话,即它不等待任何会话或资源

[31]/1/32/31/0xc3852840/2211/NLEAF/[0][41] =====》》》NLEAF表明等待会话nodenum=0/41

[41]/1/42/11/0xc3833f80/2038/NLEAF/[0] =====》》》NLEAF表明是等待会话nodenum=0

 

关于此部分信息各个列的含义解释:

nodenum  =====》》》HANGANALYZE工具用于标识每个会话的连续序号

cnode =====》》》为实例编号,从1开始,在RAC中会显示为1、2、3这样,oracle9i起可用

sid         = Session ID

sess_srno   = Serial#

session  这个可能是进程的PADDR

ospid        = OS Process Id

state       = State of the node,详细的状态见下面。

[adjlist]:当state为NLEAF时adjlist列会有值,对应阻塞会话的[nodenum]值(可能有多个阻塞会话,RAC时显示的[nodenum]值可能在另一节点上此时在State of LOCAL nodes部分会找不到对应[nodenum])

predecessor: 表示waiter node,即等待此会话的节点  =====》》》11.2.0.3、11.2.0.4未发现有此列

 

state列的不同值:

IN_HANG:这表示该node处于死锁状态,通常还有其他node(blocker)也处于该状态

持锁会话:

LEAF 持锁会话,即它不等待任何会话或资源

LEAF_NW它也是持锁会话

LEAF/LEAF_NW:该node通常是blocker.通过”predecessor”列可以判断这个node是否是blocker。LEAF说明该NODE没有等待其他资源,而LEAF_NW则可能是没有等待其他资源或者是在使用CPU。

被阻塞会话:

NLEAF 表明是处于等待的会话(被阻塞),此时adjlist列会阻塞会话的[nodenum]值;

当有许多行会话信息中的state列都是NLEAF状态,可能是数据库发生性能问题而不是数据库hang。

其它状态:

SINGLE_NODE/SINGLE_NODE_NW: This can be described the same as LEAF and LEAF_NW, except that they don’t have processes depending on them

IGN/IGN_DMP:这类会话通常被认为是空闲会话,除非其adjlist列里存在node。如果是非空闲会话则说明其adjlist里的node正在等待其他node释放资源。

 

 

 

 

2. HANGANALYZE分析示例1

示例1:linux32位+10.2.0.1.0单实例 update产生TX锁的TRACE文件:

State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[145]/0/146/5/0x786fc944/3858/LEAF/9/10//153

–这里的LEAF表示该SID阻塞了predecessor=153,nodenum153对应的SID=154,即为被阻塞者
[148]/0/149/1/0x78700160/3806/SINGLE_NODE/11/12//none
[150]/0/151/1/0x787026c8/3804/SINGLE_NODE/13/14//none
[153]/0/154/5/0x78705ee4/3903/NLEAF/15/16/[145]/none

–这里的NLEAF表示该会话被阻塞了,adjlist对应的nodenum=145对应的SID=146,即为阻塞者.

 

示例2:HP-UX +9.2.0.6.0单实例 split分区时HANG

步骤1:split分区时HANG住后执行hanganalyze进行分析如下:

HANG ANALYSIS:
==============
Cycle 1 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/329/43816/0x4d6b5638/23487/rowcachelock>
–<0/254/19761/0x4d687438/23307/librarycachelock>
Cycle 2 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/295/57125/0x4d6b8978/19237/rowcachelock>
Cycle 3 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/295/57125/0x4d6b8978/19237/rowcachelock>
Open chains found:
Other chains found:
Chain 1 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/312/10459/0x4d69f9b8/25247/NoWait>
Extra information that will be dumped at higher levels:
[level  3] :   4 node dumps — [IN_HANG]
[level  5] :   1 node dumps — [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]
[level 10] : 223 node dumps — [IGN]

State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[0]/0/1/1/0x4d7146c0/5132/IGN/1/2//none
……………………………………………………
[238]/0/239/57618/0x4d7b18a0/13476/IN_HANG/395/402/[294][238][328][253]/none
……………………………………………………
[253]/0/254/19761/0x4d7bb710/23307/IN_HANG/397/400/[328][238][294]/294
………………………………………………………………
[294]/0/295/57125/0x4d7d6820/19237/IN_HANG/396/401/[294][238][253]/238
[328]/0/329/43816/0x4d7ecf40/23487/IN_HANG/398/399/[253]/253
………………………………………………………………

cycle表示oracle内部确定的死锁。其中我们的当前手工执行split的295进程也在里面。我们观察其他的进程在做什么,如329:
SQL>selectmachine,status,program,sql_textfromv$sessiona,v$sqlareab
2  wherea.sql_address=b.addressanda.sid=329;
MACHINE   STATUS    PROGRAM                              SQL_TEXT
——— ——-  ———         ——————————————————————-
hl_rdb01  ACTIVE   sqlplus@hl_rdb01(TNSV1-V3)   ALTER TABLEA_PDA_SP_STATS PLITPARTITION P_MAXAT(20090609) INTO(PARTITION P_20090608  TABLESPACETS_DATA_A  ,PARTITION P_MAX TABLESPACETS_DATA_A)
SQL>select event from v$session_wait where sid=329;
EVENT
——————————————–
row cache lock
发现也是在执行split语句,但是问了同事,他已经把之前运行失败的脚本完全kill掉了。估计在数据库中进程挂死了,没有完全的释放。
kill掉329号进程后,发现还是挂住,所以我们继续做hanganlyze:

 

==============
HANG ANALYSIS:
==============
Cycle 1 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/295/57125/0x4d6b8978/19237/rowcachelock>
Cycle 2 :<cnode/sid/sess_srno/proc_ptr/ospid/wait_event>:
<0/254/19761/0x4d687438/23307/librarycachelock>
–<0/239/57618/0x4d6b74f8/13476/rowcachelock>

([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):

[238]/0/239/57618/0x4d7b18a0/13476/IN_HANG/395/402/[294][238][328][253]/none
[253]/0/254/19761/0x4d7bb710/23307/IN_HANG/397/400/[328][238][294]/294
[294]/0/295/57125/0x4d7d6820/19237/IN_HANG/396/401/[294][238][253]/238
[328]/0/329/43816/0x4d7ecf40/23487/IN_HANG/398/399/[253]/253

 

对STATE OF NODES部分分析,可以发现:

nodenum=238在等待[294][238][328][253],没有阻塞别的会话

nodenum=294即执行分区操作的进程,此进程阻塞了nodenum=238的,同时在等待nodenum= [294][238][253]释放资源

nodenum=253阻塞了nodenum=294,即执行分区的会话,同时在等待nodenum=[328][238][294]

nodenum=328的阻塞了nodenum=253,同时也被253阻塞

简单来说,就是 nodenum=328阻塞了nodenum=253,nodenum=253阻塞了nodenum=294.

可以尝试kill nodenum=328,不能解决了再kill nodenum=253,再不行了kill [238]

 

我们继续把其他的进程杀掉。终于295的split执行成功。
SQL>ALTER TABLEA_PDA_SP_STAT SPLIT  PARTITIONP_MAXAT(20090609)
INTO(PARTITIONP_20090608 TABLESPACETS_DATA_A  ,PARTITION P_MAX TABLESPACETS_DATA_A)
Table altered.
Elapsed:00:31:03.21
继续执行split下一个分区,也很快完成。
SQL>ALTER TABLEA_PDA_SP_STATS PLITPARTITION P_MAXAT(20090610)
2   INTO(PARTITIONP_20090609 TABLESPACETS_DATA_A
3   ,PARTITIONP_MAX TABLESPACETS_DATA_A);
Table altered.
Elapsed:00:00:00.02
至此,问题解决.

 

示例3:11.2.0.3两节点RAC模拟TX锁时两个节点均有会话hang

 

============================================================================

Extra information that will be dumped at higher levels:

[level  4] :   1 node dumps — [LEAF] [LEAF_NW]

[level  5] :   3 node dumps — [NO_WAIT] [INVOL_WT] [SINGLE_NODE] [NLEAF] [SINGLE_NODE_NW]

 

State of ALL nodes

([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):

[9]/1/10/193/0x95231978/24694/NLEAF/[136]

[136]/1/137/2227/0x95376400/18342/LEAF/ [481]/2/10/3041/0x95231978/24814/NLEAF/[136]

[726]/2/255/3581/0x94d0a760/1112/NLEAF/[136]

 

分析如下:

—->nodenum=9的 session(即:1号实例上sid为10的session)的blocker(阻塞者)为nodenum=136的 session

——>nodenum=136的 session是blocker(阻塞者),位于1号节点SID=137

->nodenum=481的 session(即:2号实例上sid为10的session)的blocker(阻塞者)为nodenum=136的 session

->nodenum=726的 session(即:2号实例上sid为255的session)的blocker(阻塞者)为nodenum=136的 session

 

  •  *** 2015-11-13 19:20:12.061

=============================================================================

  •  END OF HANG ANALYSIS

============================================================================

  •  *** 2015-11-13 19:20:12.064
  •  =============================================================================
  •  HANG ANALYSIS DUMPS:
  •    oradebug_node_dump_level: 3
  •  =============================================================================
  •  State of LOCAL nodes
  •  ([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
  •  [9]/1/10/193/0x95231978/24694/NLEAF/[136]
  •  [136]/1/137/2227/0x95376400/18342/LEAF/
  •     ·  No processes qualify for dumping.
  •     ·  =============================================================================
  •  HANG ANALYSIS DUMPS: END
  •  =============================================================================
  •  session (kjzddbx) switches to a new action
  •  PORADATA SERIAL:1 RINST:2 RDIAG:31036
  •  PORADATA SERIAL:1 RINST:2 REMOTE EXEC OSPID:31036 =====》》远程节点的执行信息
  •  PORADATA SERIAL:1 RINST:2 TRACEFILE:/u02/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_diag_31036.trc  =====》》远程节点的TRACE文件信息
  •  PORADATA SERIAL:1 RINST:2  DONE

 

节点2的TRACE文件可以发现:

  •  State of LOCAL nodes
  •  ([nodenum]/cnode/sid/sess_srno/session/ospid/state/[adjlist]):
  •  [481]/2/10/3041/0x95231978/24814/NLEAF/[136]
  •  [726]/2/255/3581/0x94d0a760/1112/NLEAF/[136]

—->可以看到,sid为10的session的blocker(阻塞者)是 nodenum=136,而这个136不在State of LOCAL nodes中,这说明这个nodenum=136在对方实例上。

—->可以看到,sid为255的session的blocker(阻塞者)是 nodenum=136,而这个136不在State of LOCAL nodes中,这说明这个nodenum=136在对方实例上。