一個案例看Oracle的歷史故障回放功 --技術人生系列第三十七期-我和數據中心的故事

11 月25日，周五晚上，正在家里看電視, 電話響了 ，是一位銀行客戶資深DBA的來電，也是我的好朋友、好兄弟，看來，他遇到麻煩了…

細心的同學，可能已經從這段話中發現了很多信息：

?    舉例故障發生已經過去五天了，還可以查么？

?    故障只出現了不到1分鐘，還可以查么？

?    簡單的一筆INSERT INTO VALUES 怎么可能需要30秒呢?

在Oracle中，答案是YES！

而幫助我們完成這項核查任務的正是客戶提到的ASH dump.

接下來這個case的根因分析，可能會顛覆很多人的運維“經驗”，“沒想到，這么做，對高并發的系統的影響這么大啊…”，還可能會有很多人生收獲哦，我們不妨一起往下看吧。

打開郵件，不僅只有 awr 報告、 ash 報告，

還有一個表 ash_1120_2040 的dump,即ASH DUMP，真是貼心極了！

這個表實際上是 dba_hist_active_session_history 的備份， 該表按照 10 秒為粒度，記錄數據庫中活動的會話在執行的 SQL 和發生的等待，且不會隨著重啟而丟失。而 gv$active_session_history 則是按秒采樣存儲，但因為是存放在內存中，因此會隨著重啟而丟失，且保存的數量有限 .

這就是 ASH 功能，即活動會話歷史功能。

將 ash_1120_2040 的dump導入電腦后，

立刻發出下列查詢，獲得按時間分布的活動會話個數的趨勢 。

結果繪制為下圖所示 ：

可以看到：

?    兩個紅色豎線之間的 30 秒左右，正是出現部分聯機交易超時的時候。

?    但是在出問題前的幾分鐘，即紅色加框部分，活動進程數已經上來了，這個和客戶確認了一下，是批量調起來的時間，批量是多個進程并發處理的

接下來，我們發出下列查詢，獲得交易超時期間的等待事件

結果如下所示：

可以看到，都是和 RAC global cache 相關的等待 , 需要說明的是，不懂 RAC 也不影響對這個 case 的閱讀和理解，小 y 主要是通過這個 case 傳授給大家核查疑難歷史問題的方法和思路，以及不斷顛覆自己常識的勇氣，才能不斷進步。

可以看到 :

排在第一位的是 gc buffer busy acquire ， 表示數據庫集群中的某個節點，如節點 1 向節點 2 請求一個 BLOCK 的時候，節點 1 已經先有人在我前面申請了同樣一個 BLOCK ，所以連申請都是繁忙的， busy  acquire 。

這個等待說明什么呢？

兩個或者兩個以上的會話同時申請同一個 BLOCK ，撞上了。

常見原因：

通常和 SQL 的效率有關，如果 SQL 效率夠高，則無需申請那么多 BLOCK ，就不會和其他會話撞在一起同時申請一個 BLOCK 去了。

但在這里，顯然不是 SQL 效率的問題，因為他就是一條簡單的 INSERT INTO VALUES 的語句而已，不存在執行計劃不好的問題。

顯然，在我之前的申請的那個進程，向節點 2 請求 BLOCK 的過程中遇到了異常，導致了問題的發生。

如果是你，接下來該怎么往下分析呢 ?

我們做根因分析，常用的手段就是梳理進程之間的關系。找到阻塞的源頭后分析他在做什么，為什么比平時要慢很多，導致了問題的發生。

分析到了這里，也許有同學會問道，那 “我可以查到本節點是哪個會話在我之前申請了 BLOCK 么？我想去看看排在我前面的會話在經歷什么 … ”

答案是 YES!！！

ASH 中的  blocking_session 字段標識了“哪個會話在我之前先行申請了該 BLOCK ”

接下來，我們發出下列查詢，找到某一瞬間，正在等 gc buffer busy acquire 的上百個會話，分別在申請哪些 BLOCK(p1/p2) ，被誰阻塞了 (blocking_session) 。

可以看到，在開始出現問題的時刻，即 20:44:04

節點 1 有 82 個會話申請同一個 BLOCK 在等 gc bufferbusy acquire, 被節點 1 SID 為 3200 的會話阻塞了，即節點 1 SID 為 3200 的會話先于 82 個進程向節點 2 請求。

乘勝追擊，我們看看節點 1SID 為 3200 的會話在等什么，被誰阻塞了呢？

如此遞歸下去，直到我們找到源頭 , 到底是誰在“一夫當關，萬夫莫開呢” …

結果如下：

可以看到：

異常出現了！節點 1 SID 為 3200 的會話在請求收到文件號 47  ， BLOCK 號 1540116 的時候，無法快速獲取，等待事件是 gc current blockbusy, 并且這次申請從 20:44:04 到 20:44:24, 持續了 20 秒以上，但是崩潰的是，沒有辦法知道誰是我的阻塞者了 …

是的， ash 是一座寶藏，但是很多人卻倒在了去挖寶藏的路上。

接下來，該怎么往下查呢？到底去往寶藏的路在哪里呢？

很抱歉，小 y 帶著大家走了一遍這條死路，現實中，確實有很多朋友在不斷重復這條死路，不想繼續重復這條死路，想找一個帶路人的，來參加我們的通向高手系列培訓吧。

小 y 喜歡化繁為簡，既然客戶已經提到，有一筆插入報文表的聯機交易 2016-11-20 20:44:04 ~ 20:44:34 ，時間達到了30秒。那么我們就從這里開始好了…

結果如下所示

可以看到：

SQL_ID 為 '15vru8xqgdkjf' 在ASH中被連續采樣到了4次，說明執行時間大于30秒.與客戶描述完全一致。然后呢？如果是你，怎么接著往下查，不妨思考幾十秒…

接下來，我們通過 sql_exec_id 即 SQL 的唯一執行標記，來看看這筆超長交易的情況 ：

結果如下所示 :

確實，最長的一筆交易，在 04 秒到 24 秒期間，一直在等 ”gc current retry”

答案就在后面，什么時候往后翻，由你決定。

其實小 y 也不知道長交易的會話在等的那個人 ”  ”gc current retry” 到底是誰，因為“ gc current retry” 這個人，無論在度娘還是 GOOGLE 還是 METALINK 上都找不到任何解釋。

這個時候，小 y 習慣于向生活要答案。

“gc currentretry” ，從字面上，看是請求當前 BLOCK ，但是無法獲取，在 retry. 既然是向節點 2 請求一個 BLOCK ，無法獲取，需要 retry, 那么我們有必要查下節點 2 是誰負責供應這個 BLOCK  呢？ 沒錯！就是節點 2 的 LMS 進程！

接下來，我們于情于理，都應該去查下問題期間， LMS 進程在做什么 …

發出下列查詢即可

結果如下圖所示

可以看到，這些 LMS 進程在等 gcs log flush sync, 即 LMS 進程在把一個 BLOCK 傳給其他節點前，需要把這個 BLOCK 在 log buffer 中的改變，刷到磁盤中的在線日志文件，但是很可惜，刷了很長時間都沒有完成。所以沒有辦法快速將 BLOCK 傳輸給節點 1 ，因此節點 1 在不斷 retry. 這里 ” gcs log flush sync” 的阻塞者 2_2633 顯然就是我們所熟悉的 LGWR 進程，即 log buffer  的寫進程。

跨過了這道坎，顯然，我們就可以一路南下，一馬平川了！

接下來，看看節點 2 的 LGWR 進程是不是在忙其他事，無暇顧及 LMS 進程的刷日志請求呢？發出下列查詢

結果如下所示：

可以看到：

節點 2 的 LGWR 進程，在等 enq: CF-contention, 即想要去寫控制文件（例如切換日志時需要寫控制文件），但是被其他人領先一步，這個人是節點 1 的 1369 會話。 期間， LGWR 進程傻傻的繼續等控制文件的隊列鎖，但等了幾十秒都無法獲取。

乘勝追擊，發出下列查詢，看看節點 1 的 1369 會話為什么長時間持有控制文件的隊列鎖。

結果如下：

可以看到， sid=1369 是節點 1 的 ckpt 檢查點進程

ckpt 正在進行控制文件的讀寫，因此持有控制文件的鎖。

期間等待事件是控制文件的順序度和并行寫，并且沒有阻塞，而是一直在變化。 正常來說，如果 IO 比較快的話，那么持有控制文件的鎖的時間是非常快的 。

進一步檢查 IO 的性能

從 oswatcher 數據可以看到，在問題時段，很多磁盤 busy 100%, 平均響應時間 200 多毫秒， IO 基本上主要是寫 ，但不是所有盤都 100% ，例如 hdiskpower 11 依然是有少量讀寫的 。

檢查大量寫 IO 的來源

檢查 ASH 中的等待事件

結果如下所示：

可以看到是問題時刻，在等 db file parallel write 的進程有 24 個，顯然是 DBWR 進程在等 該數據庫總計 24 個 DBWR 進程，全部處于活動狀態，說明有什么動作觸發了大量刷臟塊的操作。

檢查 alert 日志，可以看到 alter system archive log all （ current ）的命令，該命令必然會觸發 DBWR 大量刷臟塊，導致磁盤在短時間內極忙，導致 HBA 卡帶寬也可能被占滿。

到這里，大家不妨停下思考下，導致是誰執行了這個觸發全量檢查點的 archivelog all(current) 命令呢？

不妨思考幾十秒…

答案就是我們大家所熟悉的 RMAN 備份腳本！

要說明的是，真相和你想的不一樣！不是備份產生的 IO 影響了磁盤繁忙！

因為之前我們看到了，磁盤繁忙 100% 來自于寫，而不是來自于讀！ RMAN 主要是讀！ 而且如果是 RMAN 的讀 IO 影響磁盤繁忙，那么不可能只影響了 30 秒左右！

因為 RMAN 腳本開始執行時的 alter system archive log all （ current ）的命令觸發了 DBWR 大量刷臟塊，導致磁盤很忙，而控制文件和數據文件在一起，導致 ckpt 進程在拿到控制文件隊列鎖后，操作很慢，繼而阻塞了 LGWR 進程， LGWR 進程于是不響應 LMS 進程，最后導致了 GC 等待數十秒，也就是聯機交易大量超時。全量檢查點完成后，交易恢復正常！

怎么再次驗證呢 alter system archivelog .. 的影響呢？

接下來發出下面這條命令來驗證下 ：

可以看到，  RMAN 就是在最初的 04 秒發起，之后的 43 分 34 秒往后 RMAN 進程都還在，但交易已經恢復正常，也就是說 RMAN 腳本里觸發的全量檢查點和批量并行寫操作產生大量臟塊疊加在一起，是問題的原因 ！

為什么以前沒事？？

經確認，當天備份提前了，和批量重疊了，但不是因為 RMAN 備份的讀 IO 導致問題，而是因為 RMAN 備份腳本在最開始執行的 alter system archivelog .. 命令觸發的這次全量檢查點和批量并行寫操作產生大量臟塊疊加在一起，導致 30 秒左右，檢查的 INSERT 聯機交易也出現了超時，這才是問題的真相和問題的根本原因！

你確認這就是問題的真相？

歡迎大家踴躍留言，說說你的想法，同時可以加小 y 微信  shadow-huang-bj ，一起加入學習探討群 . 我將在下期（技術人生系列）揭曉答案。