以前和一些年輕的DBA溝通的時候，他們總是對我們這種二十年前的DBA總去探究某些數據庫內部實現機理感到不能理解。他們覺得現在要學的東西太多，學習各種操作和實施方案就夠費勁了，還花那么多精力去細摳一些很可能八百年都用不上的屠龍技，意義并不大。確實，我們這些年在Oracle的一些內部原理方面的知識都是一些碎片化的屠龍技，不是遇到問題的時候，真的沒有太多其他的用處。不過在一些復雜問題定位的時候，這些知識往往是找到解決問題辦法的關鍵。

前陣子有個券商的系統出現了一次故障，交易在3秒鐘左右的時間里出現了嚴重卡頓，影響到了幾百筆關鍵業務的成交。為了避免類似問題再出現，領導希望找到根因。

圖片

從AWR報告的TOP EVENTS上看到了幾個疑點，分別是Log File SYNC、enq TX-INDEX CONTENTION和Control File Sequential Read。這三種等待確實都可能引發幾秒鐘的卡頓。當時駐場服務的維保廠商認定是log fie  sync引發了卡頓，要去考慮如何優化REDO方面的問題。我看了這個等待后，第一反應是索引引發的行鎖等待的可能性更大一些，因為平均延時夠大。

3秒鐘的抖動，在30分鐘的報告里可能會被稀釋。以前我也寫文章談過這個問題，宏觀分析用AWR，而微觀分析要用ASH。有經驗的DBA一般會在這個時候導出ASH數據，然后在EXCEL里去做分析。在我們的DBAIOPS運維知識自動化系統中，就是通過ASH數據去做根因定位的。

圖片

拿到ASH數據，第一步是刪除與本次分析無關的列，然后另存一個文件。Oracle的ASH數據的列太多了，看起來很浪費時間。這是為了分析本次問題我留下的列。其實不同的問題分析留下的列會略有不同，但是大同小異。

圖片

第二步就是對EVENT進行篩選，找出所有你需要分析的等待事件的樣本。找出enq: TX - index contention等待事件的所有行，然后去發現規律。我們過濾出了400多行，數量不多，這對于定位問題是十分好的兆頭。

圖片

下一步把這些行拷貝到另外一個EXECL頁里，進行進一步分析。接下來我們通過Blocking_session去找阻塞者，太幸運了。只找到一條記錄。會話4756。

圖片

這時候我們要回到原始文件中繼續分析，注意：一定要回到原始文件，因為enq: TX - index contention還有個相類似的等待事件enq: TX - row lock contention，其最終影響是類似的。大多數阻塞都存在類似的問題。過濾阻塞會話為4756的會話，發現有426條。與當時400多筆交易受影響的現象十分吻合。

圖片

下面就需要繼續分析會話4756了。找出4756存在的問題，就找到了解決問題的鑰匙。于是在原始表格中搜索4756會話。這個會話只有3條記錄，是三個連續采樣周期的數據，相隔一秒，3秒鐘也正好與系統故障阻塞的3秒鐘左右相吻合。看來這回是真正找到真兇了。

圖片

在這里我們發現了一個十分奇怪的現象，這個會話實際上也在執行一條INSERT語句，而且是與被阻塞的會話的SQLID是完全相同的。從三個采樣上看，這條SQL是一次執行持續了3秒鐘，因為我們看到SQL_EXEC_ID是同一個。一條簡單的單行INSERT語句持續執行了3秒鐘，這太不合理了。看到等待事件，都是db file sequential read，USER/IO類的等待。

至此，問題分析的前半段就基本上明確了，問題基本上定位。但是為了防止類似問題再發生，必須找出根因。維保廠商給出的日志同步的結論基本上可以推翻了，雖然說LOG FILE SYNC也能解釋某些INSERT緩慢的問題，但是4756壓根沒有等待過LOG FILE SYNC，所以不可能是日志同步引發的本次故障。

定位清楚根因對于徹底根除此類問題十分關鍵，因此本次分析尚未完成，還需要繼續分析下去。可能上面的分析ASH數據的過程大家還常用一些，下面就要介紹一些不常用的技巧了。

圖片

在Oracle導出的ASH數據的尾部，有很多十分有價值的 DELTA數據，就是兩次采樣之間，這個SESSION的一些開銷。從這些開銷可以推理出很多細微的問題來，對于定位問題十分關鍵。

從上面的數據里可以分析出，這個會話在執行這條INSERT的時候，產生了大量的物理IO，加在一起接近46M。案例說INSERT不應該產生如此多的物理IO的。這張表很熱，INSERT所需要的大部分數據塊（包含索引和表）都應該是在DB CACHE里的。其實在看到enq: TX - index contention這個等待事件的時候，我第一反應就是索引分裂。當時和用戶DBA討論這個問題的時候，也和他們一起分析了AWR報告里的葉節點分裂和枝節點分裂的統計數據，葉節點分裂大概每秒10個，枝節點分裂為0.2。葉節點分裂對于如此高并發的系統來說算是比較多的，但是還可以接受。不過枝節點分裂就有點過高了。

其實到這個地方，傳統的分析過程已經完畢。下面就要依靠分析問題的人的知識是否足以支撐下面的推理了。因為后面只能靠推理，而缺少實際數據支撐了。要分析的問題是為什么一條簡單的單行INSERT會產生接近50M的物理讀。在我的知識體系里，索引維護可能是最有可能的答案了。如果索引的節點分裂的時候，需要寫入新數據的前臺進程需要負責維護這個分裂過程，如果索引中存在大量的碎片，那么在這樣一次操作中可能會掃描大量的索引塊，引發此類問題。這種情況往往在于使用很長時間沒有維護過索引的系統中發生。但是本系統是一個券商的交易系統，這張表每個交易日結束都會TRUNCATE 的，因此這種情況不會發生。

那么下一種可能就是索引的“大分裂”，甚至可能是BLEVEL的重建，如果表足夠大，而且數據足夠冷，寫入后不怎么訪問。那么很可能重建BLEVEL的時候，很可能需要掃描很多不在內存中的索引塊，從而引發這個問題。這張表正好又是交易日志表，在交易時間內，基本上寫入后不會訪問的，很符合這個條件。我覺得這個解釋目前是最為合理的。因此如果要避免此類問題發生，把這張表做成HASH表可能是最佳的解決方案。

其實定位這個故障的最關鍵的一個拼圖就是對Oracle數據庫的前臺進程維護索引的原理的理解，如果你不掌握這個知識，那么分析到最后的推理往往會發生偏差，從而影響根因定位。實際上在b-tree結構的數據庫，比如MYSQL上，此類問題發生得更加頻繁。以前我就幫助用戶分析過幾次MYSQL的簡單INSERT 偶發性緩慢的問題，其原因和這個問題是十分類似的。

這些理論雖然可用的場景有限，不過如果你想成為分析問題的高手，還是需要去多學學數據庫的一些基礎理論，甚至理解到算法層面。今天這篇文章寫得有點費勁，寫到這里已經快9點了，后面還有些話好像沒寫痛快，不過還有其他事情要做，今天就先到這里吧。