Exadata instance down

lsz_qh

我这边有一台四分之一配X2-2的Exadata，数据库版本为11.2.0.3.7，昨天下午17：45分左右，实例1 down了，附件是alert日志和生成的trace文件（我用“error informations”关键字将错误前后的日志进行了分割），麻烦大家帮我分析一下，谢谢！

lsz_qh

Oracle的分析是日志文件切换太频繁，checkpoint没有完成，导致它一直持有CF，而控制文件写也需要CF，控制文件等待时间超过900秒，认为它有问题，就把ckpt给kill了（这边的环境redo大小为500M，每个节点2组，一组2个成员）

Liu Maclean(刘相兵

当时 pid=5886 持有CF ENQUEUE LOCK但是control file parallel write 控制文件写一些不能完成 超过了15分钟=》 900s

1.   SO: 0x640a55960, type: 4, owner: 0x63069ae90, flag: INIT/-/-/0x00 if: 0x3 c: 0x3
   
2.      proc=0x63069ae90, name=session, file=ksu.h LINE:12624, pg=0
   
3.     (session) sid: 1496 ser: 1 trans: (nil), creator: 0x63069ae90
   
4.               flags: (0x51) USR/- flags_idl: (0x1) BSY/-/-/-/-/-
   
5.               flags2: (0x409) -/-/INC
   
6.               DID: , short-term DID:
   
7.               txn branch: (nil)
   
8.               oct: 0, prv: 0, sql: (nil), psql: (nil), user: 0/SYS
   
9.     ksuxds FALSE at location: 0
   
10.     service name: SYS$BACKGROUND
    
11.     Current Wait Stack:
    
12.      0: waiting for 'control file parallel write'
    
13.         files=0x2, block#=0x358, requests=0x2
    
14.         wait_id=14118530 seq_num=28734 snap_id=1
    
15.         wait times: snap=16 min 18 sec, exc=16 min 18 sec, total=16 min 18 sec
    
16.         wait times: max=infinite, heur=16 min 18 sec
    
17.         wait counts: calls=0 os=0
    
18.         in_wait=1 iflags=0x5a0
    
19.     There are 7 sessions blocked by this session.
    
20.     Dumping one waiter:
    
21.       inst: 1, sid: 800, ser: 32199
    
22.       wait event: 'DFS lock handle'
    
23.         p1: 'type|mode'=0x43490005
    
24.         p2: 'id1'=0xa
    
25.         p3: 'id2'=0x2
    
26.       row_wait_obj#: 4294967295, block#: 0, row#: 0, file# 0
    
27.       min_blocked_time: 947 secs, waiter_cache_ver: 26236
    
28.     Wait State:
    
29.       fixed_waits=0 flags=0x22 boundary=(nil)/-1
    
30.     Session Wait History:
    
31.         elapsed time of 0.000129 sec since current wait
    
32.      0: waited for 'control file sequential read'
    
33.         file#=0x0, block#=0x357, blocks=0x1
    
34.         wait_id=14118529 seq_num=28733 snap_id=1
    
35.         wait times: snap=0.000544 sec, exc=0.000544 sec, total=0.000544 sec
    
36.         wait times: max=infinite
    
37.         wait counts: calls=0 os=0
    
38.         occurred after 0.000031 sec of elapsed time
    
39.      1: waited for 'control file sequential read'
    
40.         file#=0x0, block#=0x29, blocks=0x1
    
41.         wait_id=14118528 seq_num=28732 snap_id=1
    
42.         wait times: snap=0.000610 sec, exc=0.000610 sec, total=0.000610 sec
    
43.         wait times: max=infinite
    
44.         wait counts: calls=0 os=0
    
45.         occurred after 0.000027 sec of elapsed time
    
46.      2: waited for 'control file sequential read'
    
47.         file#=0x0, block#=0x27, blocks=0x1
    
48.         wait_id=14118527 seq_num=28731 snap_id=1
    
49.         wait times: snap=0.001003 sec, exc=0.001003 sec, total=0.001003 sec
    
50.         wait times: max=infinite
    
51.         wait counts: calls=0 os=0
    
52.         occurred after 0.000015 sec of elapsed time
    
53.      3: waited for 'control file sequential read'
    
54.         file#=0x1, block#=0x1, blocks=0x1
    
55.         wait_id=14118526 seq_num=28730 snap_id=1
    
56.         wait times: snap=0.000225 sec, exc=0.000225 sec, total=0.000225 sec
    
57.         wait times: max=infinite

复制代码

这个问题之后诊断的大致思路是  为什么control file parallel write 控制文件写 一直无法完成，是否存在IO 问题

lsz_qh

嗯，由于CKPT长期持有CF enqueue，所以CKPT被kill了，但我一直没有分析出来9509进程是干什么的

Liu Maclean(刘相兵

1. Tue Dec 11 17:26:04 2012
   
2. minact-scn: useg scan erroring out with error e:12751
   
3. Tue Dec 11 17:31:11 2012
   
4. minact-scn: useg scan erroring out with error e:12751
   
5. Tue Dec 11 17:36:16 2012
   
6. minact-scn: useg scan erroring out with error e:12751
   
7. Suspending MMON action 'Block Cleanout Optim, Undo Segment Scan' for 82800 seconds
   
8. 
   
9. 
   
10. 
    
11. 
    
12. error informations:
    
13. Tue Dec 11 17:41:19 2012
    
14. Errors in file /u01/app/oracle/diag/rdbms/odsprd/odsprd1/trace/odsprd1_m000_29229.trc:
    
15. ORA-12751: cpu time or run time policy violation
    
16. Tue Dec 11 17:44:25 2012
    
17. Errors in file /u01/app/oracle/diag/rdbms/odsprd/odsprd1/trace/odsprd1_diag_5847.trc  (incident=221249):
    
18. ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 5886'
    
19. Incident details in: /u01/app/oracle/diag/rdbms/odsprd/odsprd1/incident/incdir_221249/odsprd1_diag_5847_i221249.trc
    
20. Tue Dec 11 17:44:27 2012
    
21. Sweep [inc][221249]: completed
    
22. Sweep [inc2][221249]: completed
    
23. Tue Dec 11 17:46:45 2012
    
24. Killing enqueue blocker (pid=5886) on resource CF-00000000-00000000 by (pid=9509)
    
25. by killing session 1496.1
    
26. Killing enqueue blocker (pid=5886) on resource CF-00000000-00000000 by (pid=9509)
    
27. by terminating the process
    
28. USER (ospid: 9509): terminating the instance due to error 2103
    
29. Tue Dec 11 17:46:45 2012
    
30. System state dump requested by (instance=1, osid=9509), summary=[abnormal instance termination].
    
31. System State dumped to trace file /u01/app/oracle/diag/rdbms/odsprd/odsprd1/trace/odsprd1_diag_5847.trc
    
32. Tue Dec 11 17:46:45 2012
    
33. ORA-1092 : opitsk aborting process
    
34. Tue Dec 11 17:46:45 2012
    
35. License high water mark = 429
    
36. Instance terminated by USER, pid = 9509
    
37. USER (ospid: 14233): terminating the instance
    
38. Instance terminated by USER, pid = 14233
    
39. Tue Dec 11 17:46:57 2012
    
40. Starting ORACLE instance (normal)
    
41. ****************** Large Pages Information *****************

复制代码

CF-00000000-00000000 by (pid=9509)   r (pid=5886) 长期持有CF ENQUEUE LOCK


导致 9509 引发systemstate dump ,并Instance terminated by USER, pid = 9509