DRM特性引起的RAC節點當機

某銀行客戶叢集1 節點出現異常重啟的問題，希望我們能夠找出問題所在。開始本次故障排查之前，我們先來了解下DRM （動態資源管理）的原理。

假設某叢集資料庫包含3 個節點，根據RAC 記憶體融合的原理，每個例項會儲存資料庫1/3 的主節點資訊，同時也意味著，每個節點訪問資料時會有2/3 的機率需要從遠端節點獲取資料塊的鎖資訊，從而造成更多節點間的訊息通訊。在實際應用中更有可能出現的情況是，一些資料塊在非主節點上被訪問了很多次，而主節點卻很少訪問。這種情況就意味著會產生大量的資源訪問節點和資源主節點的訊息，從而增加了私網的工作負載，甚至可能還會影響到資料庫的效能。所以，Oracle 從10g 開始，推出了DRM 特性，使資源的主節點資訊可以被動態修改。當然，決定這種修改的依據是每個節點對資源的訪問頻率。DRM 的移動過程主要可分為如下幾個步驟。

1）    靜默節點（Quiesce ）。

2）    凍結階段（Freeze ）。

3）    清除階段（Cleanup ）。

4）    重建節點（Rebuild ）。

5）    解凍節點（Unfreeze ）。

下面先來看看資料庫的告警日誌，如圖2-47 所示。

                                             

圖2- 47 告警日誌

不難看出，2018 年10 月9 日23:41:14 ，由於資料庫的後臺程式LMON 和LMS 節點間存在通訊異常，LMS0 程式終止了資料庫例項。因此，我們繼續檢查資料庫LMON 和LMS 日誌，以便檢視是否因為程式出現了問題，才導致資料庫當機。接下來檢視LMON 跟蹤日誌，輸出如下：

*** 2018-10-09 23:34:18.405

* DRM RCFG called (swin 0)

  CGS recovery timeout = 85 sec

Begin DRM(139949) (swin 0)

* drm quiesce

*** 2018-10-09 23:34:18.759

2018-10-09 23:34:18.759522 : DRM(139949) resources quiesced [0-65535], rescount 588987

2018-10-09 23:34:18.759882 : DRM(139949) local converts quiesced [0-65535], lockcount 0, bucket 0

* drm sync 1

* drm freeze

* drm cleanup

* drm sync 2

* drm replay

* drm sync 3

* drm fix writes

* drm sync 4

* drm end

* DRM RCFG called (swin 0)

  CGS recovery timeout = 85 sec

* drm quiesce

<!--…… 省略部分-->

 

*** 2018-10-09 23:34:20.780

2018-10-09 23:34:20.780063 : DRM(139949) resources quiesced [131072-196607], rescount 589078

2018-10-09 23:34:20.780437 : DRM(139949) local converts quiesced [131072-196607], lockcount 1, bucket 228

* drm sync 1

* drm freeze

kjxgm_Notify_Eviction: Received an instance eviction notification from instance 2

*** 2018-10-09 23:41:14.147

kjxgm_Notify_Eviction: eviction member count 1 reason 0x2

kjxgm_Notify_Eviction: eviction map 1

2018 年10 月9 日 23:34:18.405 ，LMON 程式就已經接收到了來自2 節點的驅逐資訊。此時資料庫正在發生DRM ，但直到例項當機（23:41 ），DRM 也沒有結束的跡象。也就是說一個DRM 竟持續了7 分鐘都沒結束。

下面進一步檢視LMD trace 日誌DRM 的啟動資訊，內容如下：

*** 2018-10-09 23:34:18.359

* received DRM start msg from 2 (cnt 1, last 1, rmno 139949)

Rcvd DRM(139949) AFFINITY Transfer pkey 5999817.0 from 1 to 2 oscan 1.1

ftd (30) received from node 2 (76 0.30/0.0)

all ftds received

* kjxftdn: break from kjxftdn, post lmon later

*** 2018-10-09 23:34:18.812

ftd (33) received from node 2 (76 0.33/0.0)

all ftds received

* kjxftdn: break from kjxftdn, post lmon later

ftd (35) received from node 2 (76 0.36/0.0)

all ftds received

ftd (37) received from node 2 (76 0.38/0.0)

all ftds received

ftd (30) received from node 2 (76 0.30/0.0)

all ftds received

* kjxftdn: break from kjxftdn, post lmon later

*** 2018-10-09 23:34:20.830

ftd (33) received from node 2 (76 0.32/0.0)

all ftds received

* kjxftdn: break from kjxftdn, post lmon later

*** 2018-10-09 23:34:34.002

kjddt2vb: valblk  [0.4e693] > local ts [0.4e692]

*** 2018-10-09 23:34:35.173

kjddt2vb: valblk  [0.4e699] > local ts [0.4e698]

<!--…… 省略大量kjddt2vb: valblk 資訊-->

*** 2018-10-09 23:41:12.133

kjddt2vb: valblk  [0.504e9] > local ts [0.504e8]

2018 年10 月9 日 23:34:18 ，LMS 程式開始啟動DRM ，直到例項當機都沒有結束，結合LMON 的資訊，我們可以猜測到當時節點間通訊的私網流量較大。

客戶端zabbix 監控故障時間段系統的心跳網路流量，也印證了上面的判斷。此時基本上可以判定是DRM 引起了此次當機。為了進一步明確當機的原因，我們再來檢視23 點34 分左右資料庫的會話資訊，如圖2-48 所示。

圖2- 48 故障時間點會話資訊

“gcs drm freeze in enter server mode ” 正是DRM 期間使用者需要操作相同資料塊時資料庫發生的等待事件，如圖2-49 所示。

圖2- 49 等待事件資訊

從會話等待及鎖資訊也能看出，故障發生前正在進行DRM 操作，但最終鎖的源頭LMS0 卻處於空閒等待的狀態。進一步檢視LMS0 及2 節點的跟蹤檔案資訊（ges2 LMON to wake up LMD - mrcvr ，2018-10-09 23:41:13.048015 : * kjfcdrmrcfg: waited 413 secs for lmd to receive all  ftdones, requesting memberkill of instances w/o ftdones: ），內容與BUG 13399435/BUG13732226 匹配，MOS Oracle 官方參考文件LMON received an instance eviction notification from instance n (Doc ID 1440892.1) 。

最終，我們可以確認此次當機是由於節點間產生了大量的DRM 觸發了Bug ，從而導致1 節點資料庫當機。

分析到這裡，當機的原因已經很明確了，但是為什麼會產生大量的DRM ，使得節點間通訊加劇，這也是我們需要進一步排查的。由於資料庫故障時間段丟失了部分快照點及自重啟，我們儘可能地對現有日誌進行分析，下面就來介紹排查的過程。首先，檢視當機前資料庫的會話資訊，如圖2-50 所示。

圖2- 50 當機前資料庫的會話資訊

2018 年10 月9 日23 ：34 ，節點間有大量的GC 類等待。堵塞的會話幾乎都是來自2480 和2353 的會話，下面分別看下2480 和2353 會話，如圖2-51 所示。

圖2- 51 2480 會話資訊

可以看出，2480 會話也被2353 會話堵塞，以相同的方式檢視別的blocking_session ，可以發現它們都是來自同一個2353 會話，如圖2-52 所示。

圖2- 52 2353 會話資訊

從以上會話資訊中我們可以看出，最終鎖的源頭來自2353 號會話，它沒有被任何會話堵塞，經排查，此會話是OGG （Oracle GoldenGate ）挖掘程式，在執行SQL 23j1ukc8sjv4v 時構建了大量的全域性CR 塊。分析到這裡，觸發的條件也已經很明確了，是OGG 抽取程式引起的。

OGG 是本次故障的導火索，OGG 抽取導致了大量節點間的GC 類等待，造成大量會話阻塞，引起節點間的DRM ，觸發Oracle Bug ，最終導致當機。

由於DRM 觸發了Oracle Bug ，因此建議關閉DRM 。

在Oracle 11G 中，可以使用如下方式禁用DRM ：

SQL> alter system set "_gc_policy_time"=0 scope=spfile;

然後，同時重啟所有例項生效。如果不想完全禁用DRM ，但是需要禁用read-mostly locking 或reader bypass 的機制。可以使用如下命令：

SQL> alter system set "_gc_read_mostly_locking"=false scope=spfile;

SQL> alter system set "_gc_bypass_readers"=false scope=spfile;