凌晨收到同事電話，反饋應用程式訪問Oracle資料庫時報錯，當時現場現象確認： 1. 應用程式訪問不了資料庫，使用SQL Developer測試發現訪問不了資料庫。報ORA-12570 TNS:packet reader failure 2. 使用lsnrctl status檢查監聽，一直沒有響應，... ...
凌晨收到同事電話，反饋應用程式訪問Oracle資料庫時報錯，當時現場現象確認：
1. 應用程式訪問不了資料庫，使用SQL Developer測試發現訪問不了資料庫。報ORA-12570 TNS:packet reader failure
2. 使用lsnrctl status檢查監聽，一直沒有響應，這個是極少見的情況。
3. 檢查資料庫狀態為OPEN，使用nmon檢查系統資源。如下一張截圖所示，CPU利用率不高，但是CPU Wait%非常高。這意味著I/O不正常。可能出現了IO等待和爭用（IO waits and contention）
CPU Wait%：顯示採集間隔內所有CPU處於空閑且等待I/O完成的時間比例，Wait%是CPU空閑狀態的一種，當CPU處於空閑狀態而又有進程處於D狀態（不可中斷睡眠）時，系統會統計這時的時間，並計算到Wait%里，Wait%不是一個時間值，而是時間的比例，因此在同樣I/O Wait時間下，伺服器CPU越多，Wait%越低，它體現了I/O操作與計算操作之間的比例。對I/O密集型的應用來說一般Wait%較高.）
4.打開郵件發現收到大量的監控告警日誌作業發出的郵件，檢查告警日誌，發現裡面有大量ORA錯誤信息，部分內容如下：
3 | | ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 5166'
10 | | ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 5166'
17 | | ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 5166'
24 | | ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 5166'
31 | | ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 5166'
38 | | ORA-00239: timeout waiting for control file enqueue: held by 'inst 1, osid 5166' for more than 900 seconds
41 | | ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 5166'
48 | | ORA-00239: timeout waiting for control file enqueue: held by 'inst 1, osid 5166' for more than 900 seconds
關於“ORA-00494: enqueue [CF] held for too long (more than 900 seconds).....”這個錯誤,我們先看看這個錯誤的相關描述：
[oracle@DB-Server ~]$ oerr ora 494
00494, 00000, "enqueue %s held for too long (more than %s seconds) by 'inst %s, osid %s'"// *Cause: The specified process did not release the enqueue within// the maximum allowed time.
// *Action: Reissue any commands that failed and contact Oracle Support
// Services with the incident information.
出現ORA-00494 意味這Instance Crash了，可以參考官方文檔 Database Crashes With ORA-00494 (文檔 ID 753290.1)：
This error can also be accompanied by ORA-600 [2103] which is basically the same problem - a process was unable to obtain the CF enqueue within the specified timeout (default 900 seconds).
This behavior can be correlated with server high load and high concurrency on resources, IO waits and contention, which keep the Oracle background processes from receiving the necessary resources.
Cause#1: The lgwr has killed the ckpt process, causing the instance to crash.
From the alert.log we can see:
The database has waited too long for a CF enqueue, so the next error is reported:
ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 38356'
Then the LGWR killed the blocker, which was in this case the CKPT process which then causes the instance to crash.
Checking the alert.log further we can see that the frequency of redo log files switch is very high (almost every 1 min).
Cause#2: Checking the I/O State in the AWR report we find that:
Average Read per ms (Av Rd(ms)) for the database files which are located on this mount point " /oracle/oa1l/data/" is facing I/O issue as per the data collection which was perform
Cause#3: The problem has been investigated in Bug 7692631 - 'DATABASE CRASHES WITH ORA-494 AFTER UPGRADE TO 10.2.0.4'
and unpublished Bug 7914003 'KILL BLOCKER AFTER ORA-494 LEADS TO FATAL BG PROCESS BEING KILLED'
The ORA-00494 error occurs during periods of super-high stress, activity to the point there the server becomes unresponsive due to overloaded disk I/O, CPU or RAM.
從上面分析看，這三種原因都存在可能性。但是需要跟多的信息和證據來確認到底是什麼原因導致ORA-00494錯誤, 以至資料庫實例Crash。
1:告警日誌裡面有“ORA-00494: enqueue [CF] held for too long (more than 900 seconds) by 'inst 1, osid 5166'” 錯誤，CF指Control file schema global enqueue。如果一個進程在指定的時間（預設900秒）內無法獲得CF鎖，則CF鎖的執行進程會被kill。這個參數為_controlfile_enqueue_timeout
SQL> COL NAME FOR A45 ;
SQL> COL VALUE FOR A32 ;
SQL> COL DESCR FOR A80 ;
SQL> SELECT x.ksppinm NAME
2 , y.ksppstvl VALUE3 , x.ksppdesc DESCR
4 FROM SYS.x$ksppi x, SYS.x$ksppcv y 5 WHERE x.indx = y.indx6 AND x.ksppinm LIKE '%&par%';
Enter value for par: controlfile_enqueue
old 6: AND x.ksppinm LIKE '%&par%'
new 6: AND x.ksppinm LIKE '%controlfile_enqueue%'
NAME VALUE DESCR--------------------------------------------- -------------------------------- --------------------------------------------------------------------------------_controlfile_enqueue_timeout 900 control file enqueue timeout in seconds_controlfile_enqueue_holding_time 120 control file enqueue max holding time in seconds
_controlfile_enqueue_dump FALSE dump the system states after controlfile enqueue timeout
_kill_controlfile_enqueue_blocker TRUE enable killing controlfile enqueue blocker on timeout
SQL>
檢查redo log的切換頻率，發現在2016-11-09 零點到2點，以及2016-11-08 22:00~ 24:00的redo log 切換頻率都很低。排除有大量DML操作的可能性, 根據以上一些分析，我們還不能完全排除Cause#1。我們接著分析其他信息
SELECT TO_CHAR(FIRST_TIME,'YYYY-MM-DD') DAY,
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'00',1,0)),'99') "00",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'01',1,0)),'99') "01",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'02',1,0)),'99') "02",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'03',1,0)),'99') "03",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'04',1,0)),'99') "04",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'05',1,0)),'99') "05",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'06',1,0)),'99') "06",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'07',1,0)),'99') "07",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'08',1,0)),'99') "08",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'09',1,0)),'99') "09",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'10',1,0)),'99') "10",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'11',1,0)),'99') "11",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'12',1,0)),'99') "12",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'13',1,0)),'99') "13",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'14',1,0)),'99') "14",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'15',1,0)),'99') "15",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'16',1,0)),'99') "16",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'17',1,0)),'99') "17",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'18',1,0)),'99') "18",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'19',1,0)),'99') "19",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'20',1,0)),'99') "20",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'21',1,0)),'99') "21",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'22',1,0)),'99') "22",
TO_CHAR(SUM(DECODE(TO_CHAR(FIRST_TIME,'HH24'),'23',1,0)),'99') "23"
FROMV$LOG_HISTORY
GROUP BY
TO_CHAR(FIRST_TIME,'YYYY-MM-DD') ORDER BY 1 DESC;
2：關於 The problem has been investigated in Bug 7692631 - 'DATABASE CRASHES WITH ORA-494 AFTER UPGRADE TO 10.2.0.4'
and unpublished Bug 7914003 'KILL BLOCKER AFTER ORA-494 LEADS TO FATAL BG PROCESS BEING KILLED'
告警日誌裡面出現ORA-00239，但是沒有出現ORA-603、ORA-00470之類的錯誤。按照官方文檔Disk I/O Contention/Slow Can Lead to ORA-239 and Instance Crash (文檔 ID 1068799.1)
I/O contention or slowness leads to control file enqueue timeout.
One particular situation that can be seen is LGWR timeout while waiting for control file enqueue, and the blocker is CKPT :
From the AWR:
1) high "log file parallel write" and "control file sequential read" waits
2) Very slow Tablespace I/O, Av Rd(ms) of 1000-4000 ms (when lower than 20 ms is acceptable)
3) very high %iowait : 98.57%.
4) confirmed IO peak during that time
Please note: Remote archive destination is also a possible cause. Networking issues can also cause this type of issue when a remote archive destination is in use for a standby database.
這台伺服器已經正常運行了很多年，所以我們更傾向是IO問題導致。結合當時CPU Wait%非常高。這意味著可能出現了嚴重的IO等待和爭用（IO waits and contention）
3：我們來看看監控工具OSWather生成這段時間的一些報告，如下，CPU資源非常空閑
Operating System CPU Utilization
CPU等待IO資源（Wait IO）也是從10:45 PM（22:45）之後變大。CPU利用率一直不高，最多20%多的樣子。
Operating System CPU Other
然後，我們看看Operating System I/O吧，如下截圖所示，可以看出在11點開始，系統IO設備非常繁忙 由此我們可以判斷IO異常導致資料庫出現ORA-00494錯誤的可能性很大。
Operating System I/O Throughput
然後我們檢查一下操作系統的日誌，如下所示：
如下截圖所示，“INFO: task kjournald:xxx blocked for more than 120 seconds.”從23:22開始，在這之前，出現大量這類日誌信息。這個是因為PlateSpin的作業複製導致（後面確認該作業在22:40啟動）。所以至此，我們更傾向是因為第二個源於引起資料庫Instance Crash。後面和系統管理員確認，PlateSpin的複製作業也是失敗了。所以種種分析，非常懷疑是PlateSpin的作業引起了IO異常。而IO發生短暫或長時間停止響應的時候，就導致資料庫實例崩潰。
