由OGG引發的資料庫故障

      首先在本文開始前介紹幾個 Oracle 資料庫中的概念。

LMS 程式：

實際上就是GCS(Global Cache Service Processes) 。這個是在RAC 環境中才會有的程式，負責管理叢集的資源，並協調叢集資源的訪問。這裡的資源主要指的是Buffer Cache 。

LMS 程式對於RAC 來說極為重要，因為叢集的Cache Fusion 的動作由它來完成，如果它發生了故障，則叢集的處理能力會受到很大的影響，嚴重的話可能導致資料庫例項被叢集驅逐。
    以下為官方描述：

The LMS process maintains records of the data file statuses and each cached block by recording information in a Global Resource Directory (GRD). The LMS process also controls the flow of messages to remote instances and manages global data block access and transmits block images between the buffer caches of different instances. This processing is part of the Cache Fusion feature.

 

LMD 程式：

Global Enqueue Service Daemon 。主要負責管理叢集之間鎖的使用。

以下是官方描述：

The LMD process manages incoming remote resource requests within each instance.

 

此程式對於叢集來說也非常重要。它要協調節點之間對於latch( 輕量級的互斥鎖) ，lock, mutex 等的訪問。這些結構都是獨佔的。

 

LMON:
Global Enqueue Service Monitor 。監控整個叢集的排隊與資源，並進行全域性的排隊操作的恢復

    以下是官方描述：
The LMON process monitors global enqueues and resources across the cluster and performs global enqueue recovery operations.

 

DIAG ：

    Diagnostic Capture Process 。負責進行程式或者例項發生故障時，進行 dump 操作。會記錄程式的執行堆疊以及程式的記憶體等資訊。

 

 

 

接下來，分享一個實際生產環境中的故障，以及診斷處理的過程。

某客戶使用的是一套HP-UX 小機下的11.2.0.3 的雙節點RAC ，資料庫節點1 上搭建了了OGG 進行資料的抽取。

2020 年3 月3 日，某客戶核心資料庫在上午執行極為緩慢，業務辦理極為不暢。下午據反饋執行較為正常。

3 月4 日上午，出現出現了同樣的狀況。同時，節點1 的資料庫軟體安裝目錄不斷有大量的寫入動作，使得資料庫軟體目錄有爆滿的危險。此時客戶要求我們進行介入。

首先，對於資料庫軟體的目錄不斷有大量寫入的問題，按照時間將資料庫節點1 的trace 目錄檔案進行了排序，結果如下：

可以看到有兩個檔案特別巨大，ora_26340.trc, ora_26241.trc 。Oracle 的trace 檔名中的數字實際上是作業系統的程式編號。

通過作業系統檢視程式，發現這兩個程式都是LOCAL=NO 的程式，即資料庫使用者連線到資料庫時的會話程式。

通過資料庫的檢視gv$session_blockers 檢視阻塞情況, 結果發現有兩個會話持有的gc element 的latch 阻塞了大量的會話：

通過v$process 與v$session 查詢，與程式26340 ， 26241 對應。同時，這兩個程式的連線的資料庫使用者是OGG 抽取所使用的使用者，與客戶確認之後，殺掉了這兩個程式，並進行了重啟OGG 服務的操作。經過此操作後，latch: gc element 的相關阻塞消失。同時，資料庫軟體安裝目錄的大量寫入也消失了。

檢視3 月3 日上午的AWR 報告，發現資料庫的主要負載就是叢集節點之間的資料互動與latch: gc element 等待，一次等待的時間多於600 毫秒， 資料庫負載也極高:

   其實這裡也與gv$session_blockers 檢視中的結果相對應。

   客戶的DBA 反映3 月3 日出現了問題，自然，首先檢視告警日誌:

     Errors in file /oracle/diag/rdbms/testdb/testdb1/trace/testdb1_ora_23342.trc  (incident=1023790):

ORA-00600: internal error code, arguments: [15711], [4], [0xC000001C6FA6E798], [0xC000001C6FA91D28], [], [], [], [], [], [], [], []

Incident details in: /oracle/diag/rdbms/testdb/testdb1/incident/incdir_1023790/testdb1_ora_23342_i1023790.trc

 

可以看到程式23342 發生了ORA-00600 的錯誤。ORA-00600 很多情況下是Oracle 軟體自身的bug 。檢視這個trace 檔案，檔案頭有如下內容：
   

 

其中的MODULE NAME: OGG-EXT 說明這個程式屬於OGG 的抽取程式。

檢視OGG 的ggserr.log ，發現確實有此錯誤：

2020-03-03 05:19:06  ERROR   OGG-00665  Oracle GoldenGate Capture for Oracle, ext_zj.prm:  OCI Error executing statement (status = 600-ORA-00600: internal error code, arguments: [15711], [4], [0xC000001C6FA6E798], [0xC000001C6FA91D28], [], [], [], [], [], [], [], []), SQL<SELECT TO_CHAR(startup_time, 'YYYY-MM-DD HH24:MI:SS') FROM gv$instance WHERE inst_id = 2>.

2020-03-03 05:19:07  INFO    OGG-00991  Oracle GoldenGate Capture for Oracle, ext_zj.prm:  EXTRACT EXT_ZJ stopped normally.

 

繼續檢視告警日誌，發現有如下內容:

Errors in file /oracle/diag/rdbms/testdb/testdb1/trace/testdb1_lmhb_6033.trc  (incident=1020926):

ORA-29771: process USER (OSID 23254) blocks LMS0 (OSID 6025) for more than 70 seconds

Incident details in: /oracle/diag/rdbms/testdb/testdb1/incident/incdir_1020926/testdb1_lmhb_6033_i1020926.trc

Tue Mar 03 11:58:47 2020

Sweep [inc][1020926]: completed

Tue Mar 03 11:58:47 2020

USER (ospid: 23254) is blocking LMS0 (ospid: 6025) in a wait

LMHB (ospid: 6033) kills USER (ospid: 23254).

Please check LMHB trace file for more detail.

 

Tue Mar 03 12:07:26 2020

Non critical error ORA-48113 caught while writing to trace file "/oracle/diag/rdbms/testdb/testdb1/trace/testdb1_ora_23342.trc"

Error message:

Writing to the above trace file is disabled for now on...

Tue Mar 03 12:07:29 2020

Non critical error ORA-48113 caught while writing to trace file "/oracle/diag/rdbms/testdb/testdb1/trace/testdb1_lmd0_6023.trc"

 

這裡說的是LMS 程式被使用者程式23254 所阻塞，阻塞的時間太長，LMON 程式把23254 程式殺掉了。這也是為什麼客戶反饋說3 月3 日下午業務執行良好, 因為阻塞的程式被LMON 程式殺掉了。

另外需要注意的是這個ORA-48113, 這個錯誤是: unable to write to stream file because of out of space condition ， 也就是說，例項當時在嘗試寫trace ，但是磁碟上已經沒有空間可以繼續寫入了。這是因為，Oracle 的DIAG 程式在dump 這兩個程式，而這兩個程式都是OGG 的相關程式，dump 的內容太多，已經把磁碟撐爆了。

 

檢視LMON 日誌，有記錄kill 的動作。

 

 

 

至此，故障的整個時間線就清楚了。

3 月3 日5 點15 分左右，OGG 抽取程式發生故障ORA-00600[15711] ，導致了兩個程式異常。不幸的是，這兩個程式持有了latch: gc element ，LMS 程式需要這個latch 才能進行資料的傳遞。這個latch 都是節點1 持有，這樣是為什麼gc cr grant 2-way 的等待時間如此之高。因為節點2 向節點1 申請讀取資料塊，但是節點1 的LMS 遲遲不能得到這個gc element 的latch 。對於這個ORA-00600[15711], MOS 也沒有很多資訊, 只有一個相關的文件: ORA-600 [15711] (Doc ID 370916.1) ，也沒有相關的補丁提供。

如下連結可以參考此Oracle 錯誤:
     https://www.eygle.com/archives/2019/09/ora-00600_15711_ogg.html

 

接下來整個上午都因為這個gc element 的latch 業務都不能進行辦理。直到中午11 點58 分左右, 資料庫的LMON 介入，殺掉兩個程式之後，資料庫才恢復正常。

 

3 月4 日狀況稍有不同，多了一個錯誤。也是在同樣的時間點OGG 程式崩潰，錯誤有所不同：

2020-03-04 06:33:13  ERROR   OGG-00665  Oracle GoldenGate Capture for Oracle, ext_cslm.prm:  OCI Error executing statement (status = 600-ORA-00600: internal error code, arguments: [15711], [4], [0xC000001C6FA6FBE0], [0xC000001C6FA86D18], [], [], [], [], [], [], [], []), SQL<SELECT TO_CHAR(startup_time, 'YYYY-MM-DD HH24:MI:SS') FROM gv$instance WHERE inst_id = 2>.

2020-03-04 06:33:15  INFO    OGG-00991  Oracle GoldenGate Capture for Oracle, ext_cslm.prm:  EXTRACT EXT_CSLM stopped normally.

2020-03-04 06:33:23  ERROR   OGG-00665  Oracle GoldenGate Capture for Oracle, ext_ac20.prm:  OCI Error executing statement (status = 600-ORA-00600: internal error code, arguments: [15711], [4], [0xC000001C6FA9D158], [0xC000001C6FA97020], [], [], [], [], [], [], [], []), SQL<SELECT TO_CHAR(startup_time, 'YYYY-MM-DD HH24:MI:SS') FROM gv$instance WHERE inst_id = 2>.

2020-03-04 06:36:15  ERROR   OGG-00665  Oracle GoldenGate Capture for Oracle, ext_ab.prm:  OCI Error executing statement (status = 600-ORA-00600: internal error code, arguments: [15711], [4], [0xC000001C6FA8ADB8], [0xC000001C6FA9A9B0], [], [], [], [], [], [], [], []), SQL<SELECT TO_CHAR(startup_time, 'YYYY-MM-DD HH24:MI:SS') FROM gv$instance WHERE inst_id = 2>.

2020-03-04 06:38:17  ERROR   OGG-00665  Oracle GoldenGate Capture for Oracle, ext_kc21.prm:  OCI Error describe for query (status = 12805-ORA-12805: parallel query server died unexpectedly), SQL<SELECT TO_CHAR(startup_time, 'YYYY-MM-DD HH24:MI:SS') FROM gv$instance WHERE inst_id = 2>.

2020-03-04 06:38:17  INFO    OGG-00991  Oracle GoldenGate Capture for Oracle, ext_kc21.prm:  EXTRACT EXT_KC21 stopped normall

 

3 月 4 日，我們是在下午 2 點客戶上班之前殺掉了兩個程式，所以，告警日誌並未發現有殺程式的資訊。但是， LMON, LMD 程式的 trace 檔案中，有大量的 gc element 的相關告警。基本可以確認與 3 月 3 日狀況類似。

3 月 4 日重啟了 OGG ，做了殺程式的動作之後， 3 月 5 日業務與恢復了正常。

 

Goldengate 的 ORA-12805 的錯誤，基本可以確認是OGG 的bug 。客戶的OGG 版本恰好在此bug 影響的版本之列。

MOS 給出的解決方案是升級OGG 版本或者對OGG 打補丁

 

鑑於客戶的資料庫沒有應用任何補丁，我們給出的建議是：應用此資料庫版本的最新PSU ， 並升級OGG 版本。

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/8520577/viewspace-2678952/，如需轉載，請註明出處，否則將追究法律責任。