以前和一些年輕的DBA溝通的時候，他們總是對我們這種二十年前的DBA總?cè)ヌ骄磕承?shù)據(jù)庫內(nèi)部實現(xiàn)機(jī)理感到不能理解。他們覺得現(xiàn)在要學(xué)的東西太多，學(xué)習(xí)各種操作和實施方案就夠費(fèi)勁了，還花那么多精力去細(xì)摳一些很可能八百年都用不上的屠龍技，意義并不大。確實，我們這些年在Oracle的一些內(nèi)部原理方面的知識都是一些碎片化的屠龍技，不是遇到問題的時候，真的沒有太多其他的用處。不過在一些復(fù)雜問題定位的時候，這些知識往往是找到解決問題辦法的關(guān)鍵。

前陣子有個券商的系統(tǒng)出現(xiàn)了一次故障，交易在3秒鐘左右的時間里出現(xiàn)了嚴(yán)重卡頓，影響到了幾百筆關(guān)鍵業(yè)務(wù)的成交。為了避免類似問題再出現(xiàn)，領(lǐng)導(dǎo)希望找到根因。

圖片

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

3秒鐘的抖動，在30分鐘的報告里可能會被稀釋。以前我也寫文章談過這個問題，宏觀分析用AWR，而微觀分析要用ASH。有經(jīng)驗的DBA一般會在這個時候?qū)С鯝SH數(shù)據(jù)，然后在EXCEL里去做分析。在我們的DBAIOPS運(yùn)維知識自動化系統(tǒng)中，就是通過ASH數(shù)據(jù)去做根因定位的。

圖片

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

圖片

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

圖片

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

圖片

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

圖片

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

圖片

在這里我們發(fā)現(xiàn)了一個十分奇怪的現(xiàn)象，這個會話實際上也在執(zhí)行一條INSERT語句，而且是與被阻塞的會話的SQLID是完全相同的。從三個采樣上看，這條SQL是一次執(zhí)行持續(xù)了3秒鐘，因為我們看到SQL_EXEC_ID是同一個。一條簡單的單行INSERT語句持續(xù)執(zhí)行了3秒鐘，這太不合理了?？吹降却录际莇b file sequential read，USER/IO類的等待。

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

定位清楚根因?qū)τ趶氐赘祟悊栴}十分關(guān)鍵，因此本次分析尚未完成，還需要繼續(xù)分析下去?？赡苌厦娴姆治鯝SH數(shù)據(jù)的過程大家還常用一些，下面就要介紹一些不常用的技巧了。

圖片

在Oracle導(dǎo)出的ASH數(shù)據(jù)的尾部，有很多十分有價值的 DELTA數(shù)據(jù)，就是兩次采樣之間，這個SESSION的一些開銷。從這些開銷可以推理出很多細(xì)微的問題來，對于定位問題十分關(guān)鍵。

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

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

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

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

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