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

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

細(xì)心的同學(xué)，可能已經(jīng)從這段話中發(fā)現(xiàn)了很多信息：

?    舉例故障發(fā)生已經(jīng)過去五天了，還可以查么？

?    故障只出現(xiàn)了不到1分鐘，還可以查么？

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

在Oracle中，答案是YES！

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

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

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

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

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

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

將 ash_1120_2040 的dump導(dǎo)入電腦后，

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

結(jié)果繪制為下圖所示 ：

可以看到：

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

?    但是在出問題前的幾分鐘，即紅色加框部分，活動進(jìn)程數(shù)已經(jīng)上來了，這個和客戶確認(rèn)了一下，是批量調(diào)起來的時間，批量是多個進(jìn)程并發(fā)處理的

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

結(jié)果如下所示：

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

可以看到 :

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

這個等待說明什么呢？

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

常見原因：

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

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

顯然，在我之前的申請的那個進(jìn)程，向節(jié)點 2 請求 BLOCK 的過程中遇到了異常，導(dǎo)致了問題的發(fā)生。

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

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

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

答案是 YES!??！

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

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

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

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

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

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

結(jié)果如下：

可以看到：

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

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

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

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

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

結(jié)果如下所示

可以看到：

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

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

結(jié)果如下所示 :

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

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

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

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

“gc currentretry” ，從字面上，看是請求當(dāng)前 BLOCK ，但是無法獲取，在 retry. 既然是向節(jié)點 2 請求一個 BLOCK ，無法獲取，需要 retry, 那么我們有必要查下節(jié)點 2 是誰負(fù)責(zé)供應(yīng)這個 BLOCK  呢？ 沒錯！就是節(jié)點 2 的 LMS 進(jìn)程！

接下來，我們于情于理，都應(yīng)該去查下問題期間， LMS 進(jìn)程在做什么 …

發(fā)出下列查詢即可

結(jié)果如下圖所示

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

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

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

結(jié)果如下所示：

可以看到：

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

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

結(jié)果如下：

可以看到， sid=1369 是節(jié)點 1 的 ckpt 檢查點進(jìn)程

ckpt 正在進(jìn)行控制文件的讀寫，因此持有控制文件的鎖。

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

進(jìn)一步檢查 IO 的性能

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

檢查大量寫 IO 的來源

檢查 ASH 中的等待事件

結(jié)果如下所示：

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

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

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

不妨思考幾十秒…

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

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

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

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

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

接下來發(fā)出下面這條命令來驗證下 ：

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

為什么以前沒事？？

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

你確認(rèn)這就是問題的真相？

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