由于在故障点之前也会报一些ORA-3136的错误,故这里不做说明,与本次错误干系不大。从alert日志中发现,数据库实例在1:40:55时,被ASMB(进程号:5898342)进程终止,直到8点46分左右才开始启动(客户自己手动重启)。
2.相关trace文件分析
test5_ora_16581034.trc:
*** 2015-01-05 01:40:50.900
*** SESSION ID:(424.19913) 2015-01-05 01:40:50.900
*** CLIENT ID:() 2015-01-05 01:40:50.900
*** SERVICE NAME:(SYS$USERS) 2015-01-05 01:40:50.900
*** MODULE NAME:(backup incr datafile) 2015-01-05 01:40:50.900
*** ACTION NAME:(0000097 STARTED16) 2015-01-05 01:40:50.900
WARNING: ASM communication error: op 18 state 0x50 (3113)
ERROR: slave communication error with ASM
NOTE: Deferred communication with ASM instance
ORA-03113: end-of-file on communication channel
Process ID:
Session ID: 288 Serial number: 5649
基本与alert日志中报的错误相同,就是获知在1:40分这个故障点,数据库与ASM实例的连接中断了
test5_asmb_5898342.trc:
*** 2015-01-05 01:40:55.870
NOTE: ASMB terminating
*** 2015-01-05 01:40:55.922
ORA-15064: communication failure with ASM instance
ORA-03135: connection lost contact
Process ID:
Session ID: 216 Serial number: 7
error 15064 detected in background process
ORA-15064: communication failure with ASM instance
ORA-03135: connection lost contact
Process ID:
Session ID: 216 Serial number: 7
kjzduptcctx: Notifying DIAG for crash event
----- Abridged Call Stack Trace -----
ksedsts()+360<-kjzdssdmp()+240<-kjzduptcctx()+228<-kjzdicrshnfy()+100<-ksuitm()+5124<-ksbrdp()+4508<-opirip()+1624<-opidrv()+608<-sou2o()+136<-opimai_real()+188<-ssthrdmain()+268<-main()+204<-__start()+112
----- End of Abridged Call Stack Trace -----
*** 2015-01-05 01:40:55.954
ASMB (ospid: 5898342): terminating the instance due to error 15064
ksuitm: waiting up to [5] seconds before killing DIAG(20578640)
从这个trace文件可以获知,由于遭遇ora-15064错误,ASMB进程终止了数据库实例。
test5_diag_20578640.trc:
Session Wait History:
elapsed time of 1.543354 sec since last wait
0: waited for 'ASM background timer'
=0x0, =0x0, =0x0
wait_id=881966 seq_num=30034 snap_id=1
wait times: snap=0.000422 sec, exc=0.000422 sec, total=0.000422 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000016 sec of elapsed time
1: waited for 'ASM file metadata operation'
msgop=0x2, locn=0x3, =0x0
wait_id=881964 seq_num=30033 snap_id=2
wait times: snap=0.000082 sec, exc=0.000127 sec, total=4 min 4 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000000 sec of elapsed time
2: waited for 'latch: shared pool'
address=0x700000000107048, number=0x133, tries=0x0
wait_id=881965 seq_num=30032 snap_id=1
wait times: snap=4 min 4 sec, exc=4 min 4 sec, total=4 min 4 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000000 sec of elapsed time
3: waited for 'ASM file metadata operation'
msgop=0x2, locn=0x3, =0x0
wait_id=881964 seq_num=30031 snap_id=1
wait times: snap=0.000045 sec, exc=0.000045 sec, total=0.000045 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000019 sec of elapsed time
4: waited for 'ASM background timer'
=0x0, =0x0, =0x0
wait_id=881963 seq_num=30030 snap_id=1
wait times: snap=3.285876 sec, exc=3.285876 sec, total=3.285876 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000011 sec of elapsed time
5: waited for 'ASM file metadata operation'
msgop=0xc, locn=0x3, =0x0
wait_id=881962 seq_num=30029 snap_id=1
wait times: snap=0.000034 sec, exc=0.000034 sec, total=0.000034 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000019 sec of elapsed time
6: waited for 'ASM background timer'
=0x0, =0x0, =0x0
wait_id=881961 seq_num=30028 snap_id=1
wait times: snap=5.000528 sec, exc=5.000528 sec, total=5.000528 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000009 sec of elapsed time
7: waited for 'ASM file metadata operation'
msgop=0x0, locn=0x3, =0x0
wait_id=881960 seq_num=30027 snap_id=1
wait times: snap=0.000003 sec, exc=0.000003 sec, total=0.000003 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000016 sec of elapsed time
8: waited for 'ASM background timer'
=0x0, =0x0, =0x0
wait_id=881959 seq_num=30026 snap_id=1
wait times: snap=5.000493 sec, exc=5.000493 sec, total=5.000493 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000011 sec of elapsed time
9: waited for 'ASM file metadata operation'
msgop=0x0, locn=0x3, =0x0
wait_id=881958 seq_num=30025 snap_id=1
wait times: snap=0.000002 sec, exc=0.000002 sec, total=0.000002 sec
wait times: max=infinite
wait counts: calls=0 os=0
occurred after 0.000017 sec of elapsed time
sample interval: 1 sec, max history 120 sec
---------------------------------------------------
[120 samples, 01:38:56 - 01:40:55]
waited for 'latch: shared pool', seq_num: 30032
p1: 'address'=0x700000000107048
p2: 'number'=0x133
p3: 'tries'=0x0
time_waited: >= 119 sec (still in wait)
---------------------------------------------------
Sampled Session History Summary:
longest_non_idle_wait: 'latch: shared pool'
[120 samples, 01:38:56 - 01:40:55]
time_waited: >= 119 sec (still in wait)