RAC环境报错ORA-00239: timeout waiting for control file enqueue排查

近期，有一用户的RAC环境反映业务缓慢；排查数据库日志发现有报错ORA-00239: timeout waiting for control file enqueue: held by 'inst 2, osid 7591' for more than 900 seconds；检查当时系统负载非常低；通过alert日志中报错的进程（这里是inst 2, osid 7591），查出持有control file enqueue的为LGWR进程；进一步排查LGWR进程TRACE日志，可以发现有大量IO缓慢的提示。

在此前提下，排查OS日志，也有些磁盘的报错信息；进一步与硬件维护人员排查确认，通过更换主机的HBA卡，之后系统恢复正常。

相关日志如下：

1.ALERT日志中的ORA-00239: timeout waiting for control file enqueue信息
Sat Feb 19 21:47:36 2022
Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_arc0_8317.trc  (incident=1154998):
ORA-00239: timeout waiting for control file enqueue: held by 'inst 2, osid 7591' for more than 900 seconds
Incident details in: /u01/app/oracle/diag/rdbms/orcl/orcl1/incident/incdir_1154998/orcl1_arc0_8317_i1154998.trc
opidrv aborting process ARC0 ospid (8317) as a result of ORA-603
Sat Feb 19 21:47:37 2022
Sweep [inc][1154998]: completed
Sweep [inc2][1154998]: completed
Sat Feb 19 21:52:52 2022
Suspending MMON slave action ketbgact_ for 82800 seconds
Sat Feb 19 21:53:55 2022
Suspending MMON action 'undo usage' for 82800 seconds

2.检查数据库中持有锁的进程信息

[oracle@CRXJ-DB-2 ~]$ cd /u01/app/oracle/diag/rdbms/orcl/orcl2/trace
[oracle@CRXJ-DB-2 trace]$ ls *7591*
orcl2_lgwr_7591.trc  orcl2_lgwr_7591.trm
[oracle@CRXJ-DB-2 trace]$ ls -al orcl2_lgwr_7591.trc
-rw-r----- 1 oracle asmadmin 748774 Feb 19 20:00 orcl2_lgwr_7591.trc
3.查看LGWR进程TRACE信息
[oracle@CRXJ-DB-2 trace]$ tail -n 50 orcl2_lgwr_7591.trc
…………

*** 2022-02-19 17:02:47.221
Warning: log write elapsed time 837ms, size 1KB
 (set event 10468 level 4 to disable this warning)

*** 2022-02-19 19:10:58.951
Warning: log write elapsed time 516ms, size 1058KB
 (set event 10468 level 4 to disable this warning)

*** 2022-02-19 19:22:50.852
Warning: log write elapsed time 534ms, size 0KB
 (set event 10468 level 4 to disable this warning)

*** 2022-02-19 20:00:55.692
Warning: log write broadcast wait time 3354ms
 (set event 10468 level 8 to disable this warning)
 
 
 
 4.查看操作系统日志：

Feb 20 13:00:48 crxj-db-2 kernel: 6>sd 3:0:0:16: [sdq] Sense Key : Illegal Request [current] 
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:16: [sdq] 
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:10: [sdk] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:10: [sdk] Sense Key : Illegal Request [current] 
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:10: [sdk] <<vendor>> ASC=0x94 ASCQ=0x1<<vendor>> ASC=0x94 ASCQ=0x1ASC=0x94 ASCQ=0x1
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:16: [sdq] CDB: Read(10): 28 00 00 00 00 00 00 00 08 00
Feb 20 13:00:48 crxj-db-2 kernel: end_request: I/O error, dev sdq, sector 0
Feb 20 13:00:48 crxj-db-2 kernel: ASC=0x94 ASCQ=0x1
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:10: [sdk] CDB: Read(10): 28 00 00 00 00 00 00 00 08 00
Feb 20 13:00:48 crxj-db-2 kernel: end_request: I/O error, dev sdk, sector 0
…………
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:18: [sds] Sense Key : Illegal Request [current] 
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:18: [sds] <<vendor>> ASC=0x94 ASCQ=0x1ASC=0x94 ASCQ=0x1
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:18: [sds] CDB: Read(10): 28 00 00 00 00 00 00 00 08 00
Feb 20 13:00:48 crxj-db-2 kernel: end_request: I/O error, dev sds, sector 0
Feb 20 13:00:48 crxj-db-2 kernel: [current] 
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:2: [sdc] <<vendor>> ASC=0x94 ASCQ=0x1ASC=0x94 ASCQ=0x1
Feb 20 13:00:48 crxj-db-2 kernel: sd 3:0:0:2: [sdc] CDB: Read(10): 28 00 00 00 00 00 00 00 08 00