10gR2 rac(asm) crash with ora-15064
本站文章除注明转载外,均为本站原创: 转载自love wife love life —Roger的Oracle/MySQL/PostgreSQL数据恢复博客
以前同事发过来一个rac log,让帮忙分析一下,该问题2011年我也看过,当时没有详细分析,这次我们再来看看,
能否找到根本的原因,首先我们来看database的alert log:
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 |
Mon Sep 17 09:59:37 2012 Thread 1 advanced to log sequence 8631 Current log# 1 seq# 8631 mem# 0: +DG_DATA/cmsdb3/onlinelog/redo01_1.log Current log# 1 seq# 8631 mem# 1: +DG_DATA/cmsdb3/onlinelog/redo01_2.log Mon Sep 17 10:35:00 2012 Errors in file /oracle/admin/cmsdb3/bdump/cmsdb31_asmb_1155.trc: ORA-15064: communication failure with ASM instance ORA-03113: end-of-file on communication channel Mon Sep 17 10:35:00 2012 ASMB: terminating instance due to error 15064 Mon Sep 17 10:35:00 2012 System state dump is made for local instance System State dumped to trace file /oracle/admin/cmsdb3/bdump/cmsdb31_diag_639.trc Mon Sep 17 10:35:02 2012 Shutting down instance (abort) License high water mark = 177 Mon Sep 17 10:35:05 2012 Instance terminated by ASMB, pid = 1155 Mon Sep 17 10:35:07 2012 Instance terminated by USER, pid = 106 Mon Sep 17 10:35:16 2012 Starting ORACLE instance (normal) LICENSE_MAX_SESSION = 0 LICENSE_SESSIONS_WARNING = 0 Interface type 1 ce1 192.168.0.0 configured from OCR for use as a cluster interconnect Interface type 1 ce0 172.16.0.0 configured from OCR for use as a public interface Picked latch-free SCN scheme 3 WARNING: db_recovery_file_dest is same as db_create_file_dest Autotune of undo retention is turned on. LICENSE_MAX_USERS = 0 SYS auditing is disabled ksdpec: called for event 13740 prior to event group initialization Starting up ORACLE RDBMS Version: 10.2.0.3.0. System parameters with non-default values: processes = 723 sessions = 800 |
从上面错误可以清楚的看到,在时间点Mon Sep 17 10:35:00 2012 出现故障,数据库实例的asmb进程出现故障,导致
数据库实例无法跟asm进行交互。
这里补充一下,数据库实例和asm实例都存在asmb进程,我猜测应该是数据库实例的asmb进程和asm实例的asmb进程
进行交互,只要其中一个asmb进程出现故障,那么可能都会导致数据库crash。
我们来看上面提到的trace cmsdb31_asmb_1155.trc内容,如下:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
/oracle/admin/cmsdb3/bdump/cmsdb31_asmb_1155.trc Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production With the Partitioning, Real Application Clusters, OLAP and Data Mining options ORACLE_HOME = /oracle/product/10.2.0/cmsdb System name: SunOS Node name: cmsdb05 Release: 5.10 Version: Generic_137111-01 Machine: sun4u Instance name: cmsdb31 Redo thread mounted by this instance: 1 Oracle process number: 52 Unix process pid: 1155, image: oracle@cmsdb05 (ASMB) *** 2012-09-17 10:35:00.281 *** SERVICE NAME:(SYS$BACKGROUND) 2012-09-17 10:35:00.280 *** SESSION ID:(586.1) 2012-09-17 10:35:00.280 error 15064 detected in background process ORA-15064: communication failure with ASM instance ORA-03113: end-of-file on communication channel ksuitm: waiting for [5] seconds before killing DIAG |
我们看到这个trace基本上没有什么信息,就只有ora-15064和ora-03113错误,这2个错误很好理解,不多说。
后面还有一句ksuitm: waiting for [5] seconds before killing DIAG 其实也值得我们关注。
这个oracle 10g中是通过一个隐含参数来进行控制的:
1 2 3 4 5 6 |
SQL> show parameter ksu_diag NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ _ksu_diag_kill_time integer 5 SQL> |
该参数默认是5s,也就上面错误提到的5s,下面是关于该参数的描述:
number of seconds ksuitm waits before killing diag
这里解释下ksu是什么意思:kernel service user 的简称。所以这里不难猜测ksuitm是一个函数,大概是下面的简称:
kernel service user diag wait time。
也就是说diag进程默认等待超过5s,就会被kill掉。
接着我们来继续看asm实例的alert log,如下:
1 2 3 4 5 |
Mon Sep 17 10:35:15 2012 Starting background process ASMB ASMB started with pid=22, OS id=599 Mon Sep 17 10:38:21 2012 NOTE: ASMB process exiting due to lack of ASM file activity |
从上面信息可以看到,在Mon Sep 17 10:35:15 2012,asm实例启动了asmb进程,这里说明一下,asm实例的asmb进程
是需要进行数据交互时,才会启动,否则不会启动,我通过vm asm环境测试发现的。
另外通过分析asm的pmon 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 |
/oracle/admin/+ASM/bdump/+asm1_pmon_18359.trc Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production With the Partitioning, Real Application Clusters, OLAP and Data Mining options ORACLE_HOME = /oracle/product/10.2.0/cmsdb System name: SunOS Node name: cmsdb05 Release: 5.10 Version: Generic_137111-01 Machine: sun4u Instance name: +ASM1 Redo thread mounted by this instance: 0 <none> Oracle process number: 2 Unix process pid: 18359, image: oracle@cmsdb05 (PMON) *** 2012-09-10 13:55:18.344 *** SERVICE NAME:() 2012-09-10 13:55:18.343 *** SESSION ID:(49.1) 2012-09-10 13:55:18.343 [claim lock for dead process][lp 0x3877a7308][p 0x3877265d0.0][hist x951] [claim lock for dead process][lp 0x3877a71a0][p 0x3877265d0.0][hist x951] [claim lock for dead process][lp 0x3877a7050][p 0x3877265d0.0][hist x951] [claim lock for dead process][lp 0x3877a6f00][p 0x3877265d0.0][hist x951] [claim lock for dead process][lp 0x3877a6db0][p 0x3877265d0.0][hist x951] [claim lock for dead process][lp 0x3877a6c60][p 0x3877265d0.0][hist x951] [claim lock for dead process][lp 0x3877a6b10][p 0x3877265d0.0][hist x951] |
通过查询mos发现,这个是一个bug,不过无关紧要,如下描述:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
Cause This is an informational message. The meaning of "claim lock for dead process" message: The message "claim lock for dead process" indicates that PMON is cleaning up the dead process and releasing the locks held by this process.These messages do not correlate to any instance termination. This message will be logged when sessions/processes are killed manually and PMON is clearing the lock held by the dead process. Solution This is a regular massage and there is no ways to remove or suppress it. Database and System Administrator should focus on finding why the processes are dying. If that is expected then they just can ignore the messages included in the PMON trace file. |
从前面的信息,我们可以发现,都没有什么具体价值的东西,下面我们来看看diag的trace,看看能不能找到一些蛛丝马迹。
搜索asmb,找到如下信息:
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 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 |
PROCESS 52: ---------------------------------------- SO: 680005f58, type: 2, owner: 0, flag: INIT/-/-/0x00 (process) Oracle pid=52, calls cur/top: 68015ba68/68015ba68, flag: (6) SYSTEM int error: 0, call error: 0, sess error: 0, txn error 0 (post info) last post received: 0 0 33 last post received-location: ksrpublish last process to post me: 741001830 5 0 last post sent: 818 0 4 last post sent-location: kslpsr last process posted by me: 6800037d0 1 6 (latch info) wait_event=0 bits=0 Process Group: DEFAULT, pseudo proc: 5373ab390 O/S info: user: oracle, term: UNKNOWN, ospid: 1155 OSD pid info: Unix process pid: 1155, image: oracle@cmsdb05 (ASMB) Dump of memory from 0x0000000534329A58 to 0x0000000534329C60 534329A50 00000005 00000000 [........] 534329A60 00000006 801CFF08 00000010 0003139D [................] 534329A70 00000006 8015BA68 00000003 0003139D [.......h........] 534329A80 00000005 3643C6B0 00000013 00031291 [....6C..........] 534329A90 00000006 801BFD58 0000000B 0003139D [.......X........] 534329AA0 00000006 801482C8 00000004 00031291 [................] 534329AB0 00000000 00000000 00000000 00000000 [................] Repeat 26 times ---------------------------------------- SO: 6801482c8, type: 4, owner: 680005f58, flag: INIT/-/-/0x00 (session) sid: 586 trans: 0, creator: 680005f58, flag: (51) USR/- BSY/-/-/-/-/- DID: 0000-0034-00000003, short-term DID: 0000-0000-00000000 txn branch: 0 oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS last wait for 'ASM background timer' blocking sess=0x0 seq=3 wait_time=1310127 seconds since wait started=592766 =0, =0, =0 Dumping Session Wait History for 'ASM background timer' count=1 wait_time=1310127 =0, =0, =0 for 'ASM background timer' count=1 wait_time=4892509 =0, =0, =0 for 'ASM background timer' count=1 wait_time=4892503 =0, =0, =0 for 'ASM background timer' count=1 wait_time=4892462 =0, =0, =0 for 'ASM background timer' count=1 wait_time=4892512 =0, =0, =0 for 'ASM background timer' count=1 wait_time=4892454 =0, =0, =0 for 'ASM background timer' count=1 wait_time=4892504 =0, =0, =0 for 'ASM background timer' count=1 wait_time=4892602 =0, =0, =0 for 'ASM background timer' count=1 wait_time=4892541 =0, =0, =0 for 'ASM background timer' count=1 wait_time=4892473 =0, =0, =0 temporary object counter: 0 ---------------------------------------- UOL used : 0 locks(used=0, free=0) KGX Atomic Operation Log 51df73dc0 Mutex 0(0, 0) idn 0 oper NONE Library Cache uid 586 efd 0 whr 0 slp 0 KGX Atomic Operation Log 51df73e08 Mutex 0(0, 0) idn 0 oper NONE Library Cache uid 586 efd 0 whr 0 slp 0 KGX Atomic Operation Log 51df73e50 Mutex 0(0, 0) idn 0 oper NONE Library Cache uid 586 efd 0 whr 0 slp 0 ---------------------------------------- SO: 6812679b8, type: 41, owner: 6801482c8, flag: INIT/-/-/0x00 (dummy) nxc=0, nlb=0 ---------------------------------------- SO: 6801bfd58, type: 11, owner: 680005f58, flag: INIT/-/-/0x00 (broadcast handle) flag: (2) ACTIVE SUBSCRIBER, owner: 680005f58, event: 24, last message event: 24, last message waited event: 24, messages read: 0 channel: (5363f4a98) system events broadcast channel scope: 2, event: 8814, last mesage event: 33, publishers/subscribers: 0/201, messages published: 1 ---------------------------------------- SO: 53643c6b0, type: 19, owner: 680005f58, flag: INIT/-/-/0x00 GES MSG BUFFERS: st=emp chunk=0x0 hdr=0x0 lnk=0x0 flags=0x0 inc=0 outq=0 sndq=0 opid=0 prmb=0x0 mbg[i]=(0 0) mbg[b]=(0 0) mbg[r]=(0 0) fmq[i]=(0 0) fmq[b]=(0 0) fmq[r]=(0 0) mop[s]=0 mop[q]=0 pendq=0 zmbq=0 ------------process 0x53643c6b0-------------------- proc version : 0 Local node : 0 pid : 1155 lkp_node : 0 svr_mode : 0 proc state : KJP_FROZEN Last drm hb acked : 0 Total accesses : 1 Imm. accesses : 0 Locks on ASTQ : 0 Locks Pending AST : 0 Granted locks : 0 AST_Q: PENDING_Q: GRANTED_Q: ---------------------------------------- SO: 68015ba68, type: 3, owner: 680005f58, flag: INIT/-/-/0x00 (call) sess: cur 6801482c8, rec 0, usr 6801482c8; depth: 0 ---------------------------------------- SO: 6812a5b90, type: 84, owner: 68015ba68, flag: INIT/-/-/0x00 (kfgso) flags: 00000000 clt: 3 err: 0 hint: 0 (kfgpn) rpi: 1 itrn:0 gst:0 usrp:0 busy: 0 rep: 0 grp: 0 check: 0/0 glink: 812a5c10 812a5c10 ---------------------------------------- SO: 6801cff08, type: 16, owner: 680005f58, flag: INIT/-/-/0x00 (osp req holder) |
似乎没有什么异常,ASM background timer是一个idle event,虽然wait time挺长的,但是这里是一个累积值。
另外看下了diag进程的信息,也没有什么特别的,如下:
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 96 97 98 |
PROCESS 8: ---------------------------------------- SO: 680000860, type: 2, owner: 0, flag: INIT/-/-/0x00 (process) Oracle pid=8, calls cur/top: 68015bfe8/68015bfe8, flag: (2) SYSTEM int error: 0, call error: 0, sess error: 0, txn error 0 (post info) last post received: 0 0 0 last post received-location: No post last process to post me: none last post sent: 0 0 48 last post sent-location: ksoreq_reply last process posted by me: 800058f98 1 0 (latch info) wait_event=0 bits=0 Process Group: DEFAULT, pseudo proc: 5373ab390 O/S info: user: oracle, term: UNKNOWN, ospid: 639 OSD pid info: Unix process pid: 639, image: oracle@cmsdb05 (DIAG) Dump of memory from 0x0000000534328400 to 0x0000000534328608 534328400 00000005 00000000 00000006 801D0018 [................] 534328410 00000010 0003139D 00000006 8015BFE8 [................] 534328420 00000003 0003139D 00000006 801C0088 [................] 534328430 0000000B 0003139D 00000006 80158FB8 [................] 534328440 00000004 00031291 00000005 3643D520 [............6C. ] 534328450 00000013 00031291 00000000 00000000 [................] 534328460 00000000 00000000 00000000 00000000 [................] Repeat 25 times 534328600 00000000 00000000 [........] ---------------------------------------- SO: 53643d520, type: 19, owner: 680000860, flag: INIT/-/-/0x00 GES MSG BUFFERS: st=emp chunk=0x0 hdr=0x0 lnk=0x0 flags=0x0 inc=0 outq=0 sndq=0 opid=0 prmb=0x0 mbg[i]=(0 0) mbg[b]=(0 0) mbg[r]=(0 0) fmq[i]=(0 0) fmq[b]=(0 0) fmq[r]=(0 0) mop[s]=0 mop[q]=0 pendq=0 zmbq=0 ------------process 0x53643d520-------------------- proc version : 0 Local node : 0 pid : 639 lkp_node : 0 svr_mode : 0 proc state : KJP_FROZEN Last drm hb acked : 0 Total accesses : 1 Imm. accesses : 0 Locks on ASTQ : 0 Locks Pending AST : 0 Granted locks : 0 AST_Q: PENDING_Q: GRANTED_Q: ---------------------------------------- SO: 680158fb8, type: 4, owner: 680000860, flag: INIT/-/-/0x00 (session) sid: 599 trans: 0, creator: 680000860, flag: (51) USR/- BSY/-/-/-/-/- DID: 0000-0000-00000000, short-term DID: 0000-0000-00000000 txn branch: 0 oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS last wait for 'DIAG idle wait' blocking sess=0x0 seq=3 wait_time=136913 seconds since wait started=592763 component=1, where=1, wait time(millisec)=c8 Dumping Session Wait History for 'DIAG idle wait' count=1 wait_time=136913 component=1, where=1, wait time(millisec)=c8 for 'DIAG idle wait' count=1 wait_time=309499 component=1, where=1, wait time(millisec)=c8 for 'DIAG idle wait' count=1 wait_time=205062 component=1, where=1, wait time(millisec)=c8 for 'DIAG idle wait' count=1 wait_time=205050 component=1, where=1, wait time(millisec)=c8 for 'DIAG idle wait' count=1 wait_time=204984 component=1, where=1, wait time(millisec)=c8 for 'DIAG idle wait' count=1 wait_time=205079 component=1, where=1, wait time(millisec)=c8 for 'DIAG idle wait' count=1 wait_time=205032 component=1, where=1, wait time(millisec)=c8 for 'DIAG idle wait' count=1 wait_time=205052 component=1, where=1, wait time(millisec)=c8 for 'DIAG idle wait' count=1 wait_time=205057 component=1, where=1, wait time(millisec)=c8 for 'DIAG idle wait' count=1 wait_time=204994 component=1, where=1, wait time(millisec)=c8 temporary object counter: 0 ---------------------------------------- UOL used : 0 locks(used=0, free=0) KGX Atomic Operation Log 52cffe850 Mutex 0(0, 0) idn 0 oper NONE Library Cache uid 599 efd 0 whr 0 slp 0 KGX Atomic Operation Log 52cffe898 Mutex 0(0, 0) idn 0 oper NONE Library Cache uid 599 efd 0 whr 0 slp 0 KGX Atomic Operation Log 52cffe8e0 Mutex 0(0, 0) idn 0 oper NONE Library Cache uid 599 efd 0 whr 0 slp 0 ---------------------------------------- SO: 681267698, type: 41, owner: 680158fb8, flag: INIT/-/-/0x00 (dummy) nxc=0, nlb=0 ---------------------------------------- SO: 68015bfe8, type: 3, owner: 680000860, flag: INIT/-/-/0x00 (call) sess: cur 680158fb8, rec 0, usr 680158fb8; depth: 0 ---------------------------------------- SO: 6801d0018, type: 16, owner: 680000860, flag: INIT/-/-/0x00 (osp req holder) |
可以看到diag 的等待时间确实挺长的,以至于该进程被kill。
通过strace 跟踪asm和数据库实例的asmb进程发现都是如下类似的几个函数,没有别的:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 |
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- nan 0.000000 0 22 read nan 0.000000 0 22 write nan 0.000000 0 66 gettimeofday ------ ----------- ----------- --------- --------- ---------------- 100.00 0.000000 110 total 但是通过查看/proc/pid/fd/下面的信息,发现应该就是asmb 2个进程进行数据交互的: --datbase instance lr-x------ 1 oracle oinstall 64 Sep 26 08:35 23 -> pipe:[141579] l-wx------ 1 oracle oinstall 64 Sep 26 08:35 22 -> pipe:[141578] lrwx------ 1 oracle oinstall 64 Sep 26 08:35 20 -> socket:[141577] ---asm instance lr-x------ 1 oracle oinstall 64 Sep 26 08:40 22 -> pipe:[142437] l-wx------ 1 oracle oinstall 64 Sep 26 08:40 21 -> pipe:[142436] lr-x------ 1 oracle oinstall 64 Sep 26 08:40 2 -> /dev/null lrwx------ 1 oracle oinstall 64 Sep 26 08:40 19 -> socket:[142435] |
不过至于具体是怎么交互,就不清楚了。
从diag trace看也没有发现任何的死进程,如下:
Orapids on dead process list: [count = 0]
综上所掌握的信息来看,就是数据库实例的asmb进程crash,然后导致数据库实例crash,进而被crs给重启了。
到最后我们都没有搞清楚数据库实例的asmb进程为何会crash 掉。 从数据库alert log看,故障前6天都是正常的,alert中
只有redo切换信息,而且并不频繁,所以最后我不得不再次怀疑是oracle bug了。
我记得该客户除了这3套10.2.0.3 rac(asm)外,还有另外2套10.2.0.4、10.2.0.5的asm rac,几乎从来没有出现过问题。
最后还是没有找到根本原因,不知道是不是应该直接建议该客户直接升级得了。
mos有个bug 有点沾边,虽然是说的11.1.0.7,但是以下版本可能也会受影响,但是关于该bug的具体信息看不到,比较遗憾。
Bug 9246245 – Instance crash due to ORA-15064 in RAC [ID 9246245.8]
另外一种猜测就是有可能当前系统负载过高,可能触发什么bug之类的,不过这些都是猜测,总的来说,bug的可能性是非常之大的。
5 Responses to “10gR2 rac(asm) crash with ora-15064”
“另外2套10.2.0.4、10.2.0.5的asm rac”
另外 2套也是 10.2.0.3的。 但并没有报类似的错。
该客户我记得应该一共有5套rac(asm),其中3套10203,一套10204,一套10205吧。
是否有ocssd.log
I think I met the same issue on an 7 nodes RAC on Linux platform. ASM crash times and times. I think we can check the OS log /var/log/messages , if there is something error like “kernel*segfualt” the momment before ASM crash,then it is very likely to have core dump file which can diagnios with gdb under crs log dir. It might be caused by memory issue, check if hugepages has been configured on OS level. After I config the hugepages on OS level for my 7 nodes RAC, issue dispear.
hi,shawn,thanks for you reply. there is not valuable information of messages. The machine is not configure hugepages. I have changed my job now, so no longer follow-up of the case.
Leave a Reply
You must be logged in to post a comment.