在很多情况下如果数据库HANG住则无法登陆sqlplus,
这时如果想要对系统进行hanganalyze可以加参数登录sqlplus 具体语法如下:
[oracle@SHDBService01 ~]$ sqlplus -prelim /nolog
SQL*Plus: Release 10.2.0.4.0 - Production on Fri Aug 21 15:42:23 2009
Copyright (c) 1982, 2007, Oracle. All Rights Reserved.
SQL> conn /as sysdba
Prelim connection established
SQL>
prelim参数只对10g 以后的版本有效。 登录以后 不允许执行SQL语句 可允许shutdown abort操作
为什么要使用hanganalyze
Oracle 数据库“真的”hang住了,可以理解为数据库内部发生死锁。因为普通的DML死锁,oracle服务器会自动监测他们的依赖关系,并回滚其中一个操作, 终止这种相互等待的局面。
而当这种死锁发生在争夺内核级别的资源(比如说是pins或latches)时,Oracle并不能自动的监测并处理这种死锁。其实很多时候数据库并没有hang住,而只是由于数据库的性能问题,处理的时间比较长而已。
Hanganalyze工具使用内核调用检测会话在等待什么资源,报告出占有者和等待者的相互关系。另外,它还会将一些比较”interesting”的进程状态dump出来,这个取决于我们使用hanganalyze的分析级别。
hanganalyze工具从oracle8i第二版开始提供,到9i增强了诊断RAC环境下的“集群范围”的信息,这意味着它将会报告出整个集群下的所有会话的信息。
目前有三种使用hanganalyze的方法:
一种是会话级别的:
SQL>ALTER SESSION SET EVENTS 'immediate trace name HANGANALYZE level <level>';
一种是实例级别:
SQL>ORADEBUG hanganalyze <level>
一种是集群范围的:
SQL>ORADEBUG setmypid
SQL>ORADEBUG setinst all
SQL>ORADEBUG -g def hanganalyze <level>
各个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会给系统带来额外负担。
更简单的办法是使用ass109.awk分析。。
hanganalyze实验
1.session1更新行数据
SQL> conn cqwr/cqwr
Connected.
SQL> create table tb_hang(id number,remark varchar2(20));
Table created.
SQL> insert into tb_hang values(1,'test');
1 row created.
SQL> commit;
Commit complete.
SQL> select USERENV('sid') from dual;
USERENV('SID')
--------------
159
SQL>
SQL> update tb_hang set remark='hang' where id=1;
1 row updated.
这个时候不提交
2.session2同样更新session1更新的行
SQL> conn cqwr/cqwr
Connected.
SQL> select USERENV('sid') from dual;
USERENV('SID')
--------------
146
SQL> update tb_hang set remark='hang' where id=1;
这个时候已经hang住了
3.session3使用hangalyze生成trace文件
SQL> connect / as sysdba
Connected.
SQL> oradebug hanganalyze 3;
Hang Analysis in /u01/oracle/admin/orcl/udump/orcl_ora_15029.trc
SQL> host
[oracle@txy orcl]$ more /u01/oracle/admin/orcl/udump/orcl_ora_15029.trc
/u01/oracle/admin/orcl/udump/orcl_ora_15029.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/oracle/product/10.2.0/db_1
System name: Linux
Node name: txy.whty.com.cn
Release: 2.6.32-431.el6.x86_64
Version: #1 SMP Fri Nov 22 03:15:09 UTC 2013
Machine: x86_64
Instance name: orcl
Redo thread mounted by this instance: 1
Oracle process number: 23
Unix process pid: 15029, image: oracle@txy.whty.com.cn (TNS V1-V3)
*** ACTION NAME:() 2015-01-23 13:46:31.572
*** MODULE NAME:(sqlplus@txy.whty.com.cn (TNS V1-V3)) 2015-01-23 13:46:31.572
*** SERVICE NAME:(SYS$USERS) 2015-01-23 13:46:31.572
*** SESSION ID:(142.97) 2015-01-23 13:46:31.572
*** 2015-01-23 13:46:31.572
==============
HANG ANALYSIS:
==============
Open chains found:
Chain 1 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/159/5/0xbf308098/15021/SQL*Net message from client>
-- <0/146/63/0xbf30a078/15022/enq: TX - row lock contention>
Other chains found:
Chain 2 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/142/97/0xbf30c058/15029/No Wait>
Chain 3 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/145/2/0xbf30c850/14664/Streams AQ: qmn slave idle wait>
Chain 4 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/147/1/0xbf30b860/14654/Streams AQ: waiting for time man>
Chain 5 : <cnode/sid/sess_srno/proc_ptr/ospid/wait_event> :
<0/153/1/0xbf309880/14644/Streams AQ: qmn coordinator idle>
Extra information that will be dumped at higher levels:
[level 4] : 1 node dumps -- [REMOTE_WT] [LEAF] [LEAF_NW]
[level 5] : 4 node dumps -- [SINGLE_NODE] [SINGLE_NODE_NW] [IGN_DMP]
[level 6] : 1 node dumps -- [NLEAF]
[level 10] : 15 node dumps -- [IGN]
State of nodes
([nodenum]/cnode/sid/sess_srno/session/ospid/state/start/finish/[adjlist]/predecessor):
[141]/0/142/97/0xbf412780/15029/SINGLE_NODE_NW/1/2//none
[144]/0/145/2/0xbf4167e8/14664/SINGLE_NODE/3/4//none
[145]/0/146/63/0xbf417d60/15022/NLEAF/5/8/[158]/none
[146]/0/147/1/0xbf4192d8/14654/SINGLE_NODE/9/10//none
[148]/0/149/8/0xbf41bdc8/14658/IGN/11/12//none
[149]/0/150/1/0xbf41d340/14652/IGN/13/14//none
[152]/0/153/1/0xbf4213a8/14644/SINGLE_NODE/15/16//none
[154]/0/155/1/0xbf423e98/14642/IGN/17/18//none
[155]/0/156/1/0xbf425410/14640/IGN/19/20//none
[158]/0/159/5/0xbf429478/15021/LEAF/6/7//145
[159]/0/160/1/0xbf42a9f0/14632/IGN/21/22//none
[160]/0/161/1/0xbf42bf68/14630/IGN/23/24//none
[161]/0/162/1/0xbf42d4e0/14628/IGN/25/26//none
[162]/0/163/1/0xbf42ea58/14626/IGN/27/28//none
[163]/0/164/1/0xbf42ffd0/14624/IGN/29/30//none
[164]/0/165/1/0xbf431548/14622/IGN/31/32//none
[165]/0/166/1/0xbf432ac0/14620/IGN/33/34//none
[166]/0/167/1/0xbf434038/14618/IGN/35/36//none
[167]/0/168/1/0xbf4355b0/14616/IGN/37/38//none
[168]/0/169/1/0xbf436b28/14614/IGN/39/40//none
[169]/0/170/1/0xbf4380a0/14612/IGN/41/42//none
====================
END OF HANG ANALYSIS
====================
[oracle@txy orcl]$
[145]/0/146/63/0xbf417d60/15022/NLEAF/5/8/[158]/none
[158]对应的SID 159 阻止了 [145]对应的SID 146
[158]/0/159/5/0xbf429478/15021/LEAF/6/7//145
145 被 158 阻止了
可以查看一下这个被阻止的进程具体在做什么 146
SQL>SELECT machine,
status,
program,
sql_text
FROM v$session a, v$sqlarea b
WHERE a.sql_address = b.address AND a.sid = 146;
MACHINE STATUS PROGRAM SQL_TEXT
tan.ceshi.com ACTIVE sqlplus@tan.ceshi.com (TNS V1-V3) update tb_hang set remark='hang' where id=1
MACHINE STATUS PROGRA SQL_TEXT
----------------------------------------------------------------------
txy.whty.com.cn ACTIVE sqlplus@txy.whty.com.cn (TNS V1-V3) update tb_hang set remark='hang' where id=1
SQL> select event from v$session_wait where sid=146;
EVENT
----------------------------------------------------------------
enq: TX - row lock contention
select B.SID,B.SERIAL#,B.SQL_ID from V$SESSION B where B.SID=535
杀掉进程 alter system kill session '159,5';
这个时候 第二个session 更新语句提交了
SQL> conn cqwr/cqwr
Connected.
SQL> select USERENV('sid') from dual;
USERENV('SID')
--------------
146
SQL> update tb_hang set remark='hang' where id=1;
1 row updated.
SQL> commit;
Commit complete.
实际案例
执行一个split分区的脚本时长时间没有响应。登录上去查看,手工执行了split脚本,发现确实会hang住:
SQL>ALTER TABLE A_PDA_SP_STAT SPLIT PARTITIONP_MAXAT(20090609)
INTO (PARTITIONP_20090608 TABLESPACE TS_DATA_A,PARTITIONP_MAX TABLESPACE TS_DATA_A)
检查该session的等待事件:
EVENT P1 P2 P3
------------------------------ ---------- ---------- ----------
rowcachelock 8 0 5
查 了网上的一些资料,说和sga的shared pool大小不足有关,或者和sequence的cache不大有关。经过分析,这2个原因应该都不是。因为1、如果是shared pool不足,这样的现象一般是某个sql执行的比较慢,但是还是会执行完,而不是像现在这样的挂住;2,只是执行split分区,并没有和 sequence相关。
在这里,我们用hanganalyze来进行分析。
我们现在来看看出来的trace文件:
SQL> select spid from v$session a,v$process b where a.paddr=b.addr and a.sid = 544
SPID
------------
1841
这个是系统进程 可以用 ps -ef| grep spid 即 ps – ef | grep 1841
SQL> oradebug SETOSPID 1841
Oracle pid: 235, Unix process pid: 19237, image: oracle@hl_rdb01 (TNS V1-V3)
SQL> oradebug hanganalyze 3;
Cycle 1: (0/295)
Cycle 2: (0/254)--(0/239)
Hang Analysis in /oracle/app/oracle/admin/hlreport/udump/hlreport_ora_25247.trc
SQL> !
$ more /oracle/app/oracle/admin/hlreport/udump/hlreport_ora_25247.trc
Dump file /oracle/app/oracle/admin/hlreport/udump/hlreport_ora_25247.trc
Oracle9i Enterprise Edition Release 9.2.0.6.0 - 64bit Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.6.0 - Production
ORACLE_HOME = /oracle/app/oracle/product/9.2.0
System name: HP-UX
Node name: hl_rdb01
Release: B.11.11
Version: U
Machine: 9000/800
Instance name: hlreport
Redo thread mounted by this instance: 1
Oracle process number: 157
Unix process pid: 25247, image: oracle@hl_rdb01 (TNS V1-V3)
*** SESSION ID:(312.10459) 2009-05-20 16:21:58.423
*** 2009-05-20 16:21:58.423
==============
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
………………………………………………………………
Dumping System_State and Fixed_SGA in process with ospid 13476
Dumping Process information for process with ospid 13476
Dumping Process information for process with ospid 23307
Dumping Process information for process with ospid 19237
Dumping Process information for process with ospid 23487
====================
END OF HANG ANALYSIS
====================
*** 2009-05-20 16:48:20.686
现在我们来看看我们的trace出来的文件:
Cycle 1 ::
<0/329/43816/0x4d6b5638/23487/row cache lock>
— <0/254/19761/0x4d687438/23307/library cache lock>
Cycle 2 ::
<0/295/57125/0x4d6b8978/19237/row cache lock>
Cycle 3 ::
<0/295/57125/0x4d6b8978/19237/row cache lock>
cycle表示oracle内部确定的死锁。其中我们的当前手工执行split的295进程也在里面。我们观察其他的进程在做什么,如329:
SQL>select machine,status,program,sql_text from v$sessiona,v$sqlareab
2 where a.sql_address=b.address and a.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 wheresid=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>
我们继续把其他的进程杀掉。终于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
至此,问题解决.
[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
329堵塞住了254
254堵塞住了295
295堵塞住了239
杀掉的应该是329,254,295