記一條500行執(zhí)行計(jì)劃的SQL問(wèn)題分析-從應(yīng)急處理到根因分析-技術(shù)人生系列第十八期

4 月 24 日，早上七點(diǎn)，老 K 為迎接某國(guó)有大型銀行批次投產(chǎn)后開(kāi)門(mén)營(yíng)業(yè)作現(xiàn)場(chǎng)支持該行運(yùn)維團(tuán)隊(duì)的工作；根據(jù)以往的經(jīng)驗(yàn)，該行每次批次投產(chǎn)會(huì)有數(shù)十套系統(tǒng)的軟件 / 環(huán)境版本變化、系統(tǒng)遷移等操作，在投產(chǎn)后的第一個(gè)工作日開(kāi)門(mén)營(yíng)業(yè)后，多少會(huì)有一些問(wèn)題；而 ORACLE 數(shù)據(jù)庫(kù)作為各業(yè)務(wù)系統(tǒng)中的重要一環(huán)，往往是領(lǐng)導(dǎo)們關(guān)注的重點(diǎn)。

時(shí)間大約在 8 點(diǎn)左右，應(yīng)用維護(hù)團(tuán)隊(duì)報(bào)出問(wèn)題來(lái)：某套系統(tǒng)的某關(guān)鍵業(yè)務(wù)在開(kāi)門(mén)前，需要先上送報(bào)表到某國(guó)家監(jiān)管機(jī)構(gòu)，報(bào)表主要就是通過(guò)在數(shù)據(jù)庫(kù)中執(zhí)行 SQL 語(yǔ)句生成的；以往這個(gè)報(bào)表的生成時(shí)間只需要 2 分鐘，而今跑了二十分鐘也沒(méi)有動(dòng)靜，重提了好幾次也沒(méi)有效果，而前端柜臺(tái)業(yè)務(wù)開(kāi)門(mén)時(shí)間是在 8 點(diǎn)半，必須要馬上解決，避免影響到業(yè)務(wù)開(kāi)門(mén)時(shí)間；

通過(guò)現(xiàn)場(chǎng)快速查看，系統(tǒng)整體無(wú)異常，只是業(yè)務(wù)報(bào)表的 SQL 執(zhí)行時(shí)間偏長(zhǎng)，主要運(yùn)行在 CPU 上，看起來(lái)可能是邏輯讀過(guò)大了，在分析間，老 K 也了解到該系統(tǒng)在這次批次投產(chǎn)過(guò)程中的變化；

雖然這個(gè)報(bào)表 SQL 以前也運(yùn)行過(guò)，奈何這是新的環(huán)境，原環(huán)境也已經(jīng)不在，沒(méi)法對(duì)比，看起來(lái)需要從頭開(kāi)始分析了；

老 K 首先通過(guò) dbms_workload_repository.create_snapshot 做了一個(gè) snapshot ，然后抓一下 awrsqrpt 對(duì)語(yǔ)句進(jìn)行分析；

語(yǔ)句邏輯讀確實(shí)非常大：

可以看到：

語(yǔ)句執(zhí)行了將近 1300 秒，仍未執(zhí)行完成；

邏輯讀達(dá)到 4.5 億；

通常來(lái)說(shuō)，對(duì)于 SQL 性能問(wèn)題，只需要理解 SQL 業(yè)務(wù)邏輯，分析一下 SQL 執(zhí)行計(jì)劃，然后充分了解相關(guān)各表的數(shù)據(jù)分布，就可以給出相應(yīng)的解決方案；只不過(guò)，這一次留給老 K 時(shí)間似乎有些短，壓力山大。

不過(guò)沒(méi)有關(guān)系，按套路來(lái)，先看看語(yǔ)句內(nèi)容和執(zhí)行計(jì)劃，然而，事情是這個(gè)樣子的：

這樣，老 K 就有幾分方了，光是執(zhí)行計(jì)劃就達(dá)到了 568 行；再去看 SQL 語(yǔ)句內(nèi)容，語(yǔ)句密密麻麻，操作終端上的 SQL 工具根本無(wú)法格式化 SQL 內(nèi)容，基本也不具備可讀性；簡(jiǎn)單看一眼執(zhí)行計(jì)劃，稍微能總結(jié)一些執(zhí)行計(jì)劃的特點(diǎn)：

如果是你，你將如何進(jìn)一步分析呢？

說(shuō)話間，從開(kāi)始查問(wèn)題，到與應(yīng)用溝通，大致看語(yǔ)句，了解執(zhí)行計(jì)劃，十分鐘已經(jīng)過(guò)去了，時(shí)間已經(jīng)來(lái)到了 8 點(diǎn) 10 分，留給老 K 的時(shí)間已經(jīng)不多了；除了執(zhí)行計(jì)劃，其他思考結(jié)果如下：

那么，這里，看起來(lái)我們目前能做的應(yīng)該就是統(tǒng)計(jì)信息了，在短時(shí)間內(nèi)沒(méi)有辦法分析 SQL 和 SQL 執(zhí)行計(jì)劃的情況下，收集統(tǒng)計(jì)信息應(yīng)該是值得一試的方案；但是新問(wèn)題來(lái)了，涉及上百?gòu)埍?，大的有幾十個(gè) G ，如果逐個(gè)收集統(tǒng)計(jì)信息，再先后重提應(yīng)用報(bào)表 SQL ，估計(jì)又得損失幾百萬(wàn)了 ~~ 所以， 到這里，我們需要做的事情是，找到那個(gè)最有可能有問(wèn)題的表，收集統(tǒng)計(jì)信息，然后試著再重提批量，這里，時(shí)間緊迫，要求必須一擊即中。 老 K 需要閉上眼睛靜靜的思考一分鐘，確實(shí)，在一分鐘以后，老 K 想到了一個(gè)可以一試的思路，并且取得很好的效果！

OK ，思考?xì)w來(lái)，老 K 的思路是，語(yǔ)句的邏輯讀非常大，而以前執(zhí)行較快，正常來(lái)說(shuō)邏輯讀不會(huì)太大，如果這里真的是某個(gè)表的統(tǒng)計(jì)信息不準(zhǔn)的話， 應(yīng)該該表或者與該表關(guān)聯(lián)的表的邏輯讀會(huì)比較大 （這一句很重要），而該段時(shí)間內(nèi)主要就是這條 SQL 在執(zhí)行，那么我們?yōu)槭裁床豢纯催@段時(shí)間的 AWR 報(bào)告，看看是哪個(gè)表或者哪些表的邏輯讀比較大呢？

可以看到， XXDEALS 表占比整庫(kù)邏輯讀的 92.35% ；

XXDEALS_IDX7 的邏輯讀也達(dá)到了 1600 萬(wàn)；

所屬用戶也正是運(yùn)行報(bào)表 SQL 的用戶；

進(jìn)一步檢查可以知道，執(zhí)行計(jì)劃中的該表是存在的， 查看表的信息，大小大約 700M 左右，不算大，而且表的上次統(tǒng)計(jì)信息收集時(shí)間已經(jīng)是 4 月 7 日，看上去距離當(dāng)前時(shí)間也較久了 ；說(shuō)干就干，開(kāi) 8 個(gè)并行收集該表的統(tǒng)計(jì)信息；一分鐘時(shí)間就收集完成，再重提批量任務(wù)，執(zhí)行計(jì)劃已經(jīng)發(fā)生變化，執(zhí)行完整個(gè)批量需要的時(shí)間大約就在 5 分鐘左右 ;

最終，報(bào)表順利上報(bào)，業(yè)務(wù)也基本準(zhǔn)時(shí)開(kāi)門(mén)，皆大歡喜。

我們看到，在這里的問(wèn)題處理過(guò)程中，老 K 取巧了一下，在 SQL 語(yǔ)句和執(zhí)行計(jì)劃都非常長(zhǎng)，無(wú)法在短時(shí)間內(nèi)直接定位執(zhí)行計(jì)劃中所存在的問(wèn)題的情況下，基于 SQL 執(zhí)行時(shí)邏輯讀非常高的特點(diǎn)，借助 AWR 報(bào)告中邏輯讀 top 分布的情況，大致定位到可能存在導(dǎo)致執(zhí)行計(jì)劃不正確的表，并收集統(tǒng)計(jì)信息，最終解決了問(wèn)題； ORACLE 提供了很多工具和方法來(lái)定位不同的問(wèn)題，關(guān)鍵看我們能不能利用這些已有信息，發(fā)現(xiàn)信息中的特征來(lái)找到解決方法；

問(wèn)題是解決了，但是因?yàn)椴铧c(diǎn)影響到業(yè)務(wù)開(kāi)門(mén)，上面的領(lǐng)導(dǎo)還是比較關(guān)切，需要一個(gè)解釋?zhuān)蛘哒f(shuō)需要一個(gè)團(tuán)隊(duì)來(lái)承擔(dān)這個(gè)責(zé)任，這中間幾個(gè)關(guān)鍵點(diǎn)：

然而時(shí)間已經(jīng)過(guò)了 8 點(diǎn)半，業(yè)務(wù)也均已開(kāi)門(mén)，各新投系統(tǒng)和升級(jí)的系統(tǒng)也陸陸續(xù)續(xù)出現(xiàn)了一些小問(wèn)題，需要在數(shù)據(jù)庫(kù)方面進(jìn)行排查；要給出這個(gè)解釋暫時(shí)只能是口頭上的，也許沒(méi)有足夠的時(shí)間進(jìn)行驗(yàn)證。

通常來(lái)說(shuō)，通過(guò)統(tǒng)計(jì)信息收集解決的問(wèn)題，那無(wú)非就是統(tǒng)計(jì)信息過(guò)舊導(dǎo)致的；

但是這里有一個(gè)問(wèn)題無(wú)法用統(tǒng)計(jì)信息過(guò)舊來(lái)解釋?zhuān)簽槭裁匆酝恢睕](méi)有問(wèn)題，這次遷移到新的環(huán)境了，上來(lái)就有問(wèn)題？是不是導(dǎo)入過(guò)程中有什么不該做的操作呢？

這里就需要仔細(xì)看看表的統(tǒng)計(jì)信息的收集時(shí)間了 :

可以看到，除最新收集的統(tǒng)計(jì)信息外， XXDEALS 表曾經(jīng)收集過(guò)兩次，一次收集時(shí)間是 4 月 7 日，一次收集時(shí)間是 4 月 22 日（也就是數(shù)據(jù)導(dǎo)入當(dāng)天），然而在我們最近一次收集之前表的最新統(tǒng)計(jì)信息收集時(shí)間是 4 月 7 日，那么意味著表的統(tǒng)計(jì)信息分析時(shí)間軸是這樣的：

  4 月 22 日   ---->  4 月 7 日   ----->  4 月 24 日

是不是很奇怪，老 K 頓感疑惑，不過(guò)通過(guò)數(shù)據(jù)導(dǎo)入日志確認(rèn)了 4 月 22 日 18:04 這個(gè)時(shí)間點(diǎn)其實(shí)正是在 dump 的導(dǎo)入過(guò)程中之后，老 K 的疑惑也就解開(kāi)了。

在確認(rèn)完這個(gè)統(tǒng)計(jì)信息分析的時(shí)間軸后，老 K 就有理由做出下述完美的猜想了：

我們通過(guò)腳本查看 SQL 涉及的表的統(tǒng)計(jì)信息的最新時(shí)間，發(fā)現(xiàn)確實(shí)有部分表的統(tǒng)計(jì)信息分析時(shí)間是在導(dǎo)入完成之后，部分表的分析時(shí)間是在導(dǎo)入完成之前；這樣看來(lái)，上述假設(shè)是極有可能的，基于上述可能，我們?cè)俅沃厣炅宋覀儗?duì) ORACLE 數(shù)據(jù)庫(kù)數(shù)據(jù)導(dǎo)入后對(duì)應(yīng)用維護(hù)團(tuán)隊(duì)的操作要求也是我們的結(jié)論：

在導(dǎo)入完成后，需要重新收集表的統(tǒng)計(jì)信息（可以按表或者按用戶收集），其中， method_opt 參數(shù)建議指定為 repeat ；

在與領(lǐng)導(dǎo)匯報(bào)完后，這口老鍋算是甩的非常完美了 ^_^ ，老 K 繼續(xù)匆匆投入到其他問(wèn)題的處理當(dāng)中，驗(yàn)證的事情可能需要留待后續(xù)來(lái)實(shí)現(xiàn)了。

到目前為止，我們分析到的問(wèn)題可以捋一下：

時(shí)間空下來(lái)，想到如此完美的猜想，老 K 立即開(kāi)始驗(yàn)證起來(lái)；現(xiàn)在，我們有了針對(duì) SQL 前后的兩個(gè)執(zhí)行計(jì)劃，可以通過(guò)對(duì)比結(jié)果來(lái)分析原因了；語(yǔ)句依然還是太長(zhǎng)，基本沒(méi)法直接讀，但是確認(rèn)了一點(diǎn)， 語(yǔ)句確實(shí)是由 unionall 組合了大量的較簡(jiǎn)單的多表連接來(lái)完成的 。

我們收集了表 XXDEALS 的統(tǒng)計(jì)信息，那么我們主要關(guān)注執(zhí)行計(jì)劃中 XXDEALS 相關(guān)的部分的變化即可，然而， 568 行的執(zhí)行計(jì)劃，與 XXDEALS 相關(guān)的部分也有幾十處，我們又如何能快速定位出導(dǎo)致邏輯讀劇增的那部分呢？

較差執(zhí)行計(jì)劃:

較好的執(zhí)行計(jì)劃：

從執(zhí)行計(jì)劃分析，符合我們上述的小技巧，如果使用 hash join ，原則上兩表只需要執(zhí)行一次掃描，而如果是 NL ，則可能會(huì)因?yàn)轵?qū)動(dòng)表估算的行數(shù)不準(zhǔn)而導(dǎo)致被驅(qū)動(dòng)表的邏輯讀大增；

從變態(tài)的 SQL 語(yǔ)句中搜索出對(duì)應(yīng)這段執(zhí)行計(jì)劃的 SQL 大致如下：

并通過(guò)使用加 hint 的方式執(zhí)行該語(yǔ)句讓其跑出兩個(gè)執(zhí)行計(jì)劃對(duì)比起邏輯讀和執(zhí)行計(jì)劃，可以驗(yàn)證這段 SQL 確實(shí)是導(dǎo)致整個(gè) SQL 執(zhí)行效率大大下降的原因； 就這樣，我們通過(guò)執(zhí)行計(jì)劃的分析，將紛繁的 SQL 分析化解為簡(jiǎn)短的兩表關(guān)聯(lián)的分析；

根據(jù)上述分析，這里我們又可以進(jìn)一步簡(jiǎn)化；兩個(gè)執(zhí)行計(jì)劃中，驅(qū)動(dòng)表的位置和評(píng)估行數(shù)都沒(méi)有變化，那么我們唯一需要關(guān)注的是在較差的執(zhí)行計(jì)劃中，為什么會(huì)使用 NL 呢？

即，我們需要關(guān)注的就只剩下表 XXDEALS 在相關(guān) maturitydate 條件和 flagofdeal 條件下，為什么一個(gè)會(huì)走索引，而另一個(gè)卻沒(méi)有走索引，與統(tǒng)計(jì)信息的關(guān)系又如何?

要精確定位問(wèn)題，在這里可能需要重現(xiàn)問(wèn)題。這里其實(shí)要重現(xiàn)問(wèn)題比較簡(jiǎn)單，老 K 通過(guò) dbms_stats.restore_table_stats 恢復(fù)表的統(tǒng)計(jì)信息，并將新舊表的定義（包含了統(tǒng)計(jì)信息又不用導(dǎo)數(shù)據(jù)）各導(dǎo)出一份，導(dǎo)入到 11.2.0.4 的測(cè)試環(huán)境中去，分別命名為 DEALS_0407 和 DEALS_0424 ，兩表分別使用的是 4 月 7 日的統(tǒng)計(jì)信息和 4 月 24 日的統(tǒng)計(jì)信息，也可以基本反映兩個(gè)日期中表的數(shù)據(jù)分布情況。

通過(guò)簡(jiǎn)單測(cè)試，我們又把 maturitydate 字段的影響給排除掉了，現(xiàn)在唯一的區(qū)別就在與使用 flagofdeal=‘O’ 時(shí)，兩表評(píng)估的行數(shù)不一致；

那么這里 317 和 455K 都是怎么算出來(lái)的呢？我們?cè)囍纯? 10053 能不能給我們一些幫助 ;

DEALS_0407 的 10053 關(guān)鍵評(píng)估信息：

DEALS_0424 的 10053 關(guān)鍵評(píng)估信息：

我們可以看到，兩表總行數(shù)上（ Original ）的區(qū)別不大， flagofdeal 列的密度（ Density ）有一些區(qū)別，最主要的是區(qū)別是兩表 flagofdeal 列 Frequency 直方圖的桶數(shù)量（ Bkts ）居然不同， DEALS_0407 只有 5 個(gè)桶，而 DEALS_0424 卻有 6 個(gè)桶；

老 K 簡(jiǎn)單一算，對(duì)于 DEALS_0407 最終估算的 317 不正是等于 1017318 （ Original ） *0.000311 （ Newdensity ）嗎？這樣看來(lái)，顯然 ’O’ 值并不在直方圖的 popular value 中了；

而 DEALS_0424 中，最終估算的 455K 條記錄則像是其 popular value 中估算出來(lái)的了；如果真的是這樣的話，那么基本是可以確認(rèn)是因?yàn)閿?shù)據(jù)變化，即 DEALS_0407 表中沒(méi)有 ’O’ 值記錄，而在 DEALS_0424 中則大量插入 / 修改了 ’O’ 值記錄了。

然而，這一次，有了充分的時(shí)間，老 K 就不再輕易下結(jié)論了！

首先，我們來(lái)驗(yàn)證 DEALS_0424 的估算值是否準(zhǔn)確：

其中 get_external_value 數(shù)據(jù)來(lái)為自定義的轉(zhuǎn)換 endpoint_value 為實(shí)際字符串的函數(shù)，已經(jīng)發(fā)布在 “ 中亦安圖”公眾賬號(hào)中，有需要的朋友可以關(guān)注中亦安圖公眾號(hào)，回復(fù) “ 直方圖函數(shù) ” 獲取；

我們看到， ‘O’ 值的 endpoint_number 為 14164 ；

那么其評(píng)估值即為： 1021005 （ Original ） * （（ 14164-7839 ） /14177 ） =455K

與 10053 trace 和執(zhí)行計(jì)劃中的都一致；

另一方面， DEALS_0407 直方圖桶的個(gè)數(shù)是 5 個(gè)，那么它又是些什么值呢，我們不妨也簡(jiǎn)單看一下，確認(rèn)一下是否確實(shí)是缺少了 ‘O’ 值：

然而，結(jié)果似乎不如我們所愿， DEALS_0407 雖然確實(shí)是 5 個(gè)桶，但是卻是包含了 ‘O’ 值的；使用同樣方法去估算 ’O’ 值的記錄數(shù)應(yīng)該差不多是 465K ：

看起來(lái)，確實(shí)在遷移升級(jí)期間沒(méi)有那么大的數(shù)據(jù)的變化；

那到這里，問(wèn)題又是什么呢？

考慮到在之前環(huán)境中，原 SQL 的執(zhí)行是沒(méi)有問(wèn)題的，那么是不是說(shuō)在原環(huán)境中對(duì) flagofdeal=‘O’ 的記錄數(shù)評(píng)估應(yīng)該是準(zhǔn)確的呢？不如我們?cè)賮?lái)驗(yàn)證一下：

沒(méi)錯(cuò)，我們看到，如果我們?cè)? SQL 中增加 OPTIMIZER_FEATURES_ENABLE('10.2.0.5') 的 hint 讓數(shù)據(jù)庫(kù)使用 10.2.0.5 的優(yōu)化器的話，是能正確的評(píng)估出該 ’O’ 值記錄的行數(shù)；

同樣，即使是 11.2.0.3 的優(yōu)化器，也同樣能正確的評(píng)估出 ’O’ 值記錄的行數(shù)：

如此，老 K 更是迷惘了，難道單單 11.2.0.4 有問(wèn)題，那是為什么呢？

我們還是要回到評(píng)估行數(shù)的問(wèn)題上來(lái)，為什么明明我們看到的直方圖的記錄中有 ‘O’ 值， 11.2.0.4 的優(yōu)化器卻認(rèn)為直方圖信息中沒(méi)有 ‘O’ 值呢？難道是老 K 給出的 get_external_value 函數(shù)存在問(wèn)題？這時(shí)，老 K 想起了在處理字符串的問(wèn)題是經(jīng)常會(huì)給我們帶來(lái)視覺(jué)錯(cuò)誤的一個(gè)問(wèn)題，那就是空格，于是，我再次查詢直方圖信息：

沒(méi)錯(cuò)，就是空格，其實(shí)在轉(zhuǎn)化成字符串后，發(fā)現(xiàn)，兩者還是有區(qū)別的，我們?cè)僮屑?xì)對(duì)比的話，其實(shí)兩表直方圖的 endpoint_value 確實(shí)是不一樣的；我們又通過(guò)對(duì)比同表的其他字段直方圖信息確認(rèn)了，一般如果實(shí)際值一樣，在信息里的 endpoint_value 應(yīng)該是一樣的：

最后，通過(guò)多次確認(rèn)測(cè)試，最終定位到只要列的類(lèi)型為 char 類(lèi)型，而且字段長(zhǎng)度低于 8 ，那么會(huì)出現(xiàn)在 11.2.0.3 （及更低版本）與 11.2.0.4 的直方圖信息 endpoint_value 不一致；測(cè)試過(guò)程此處不表；

基本上能確認(rèn)是 oracle 的一個(gè)變化，至少是 11.2.0.3 到 11.2.0.4 之間的一個(gè)變化；接下來(lái)的任務(wù)就是找到 ORACLE 官方的說(shuō)明來(lái)，之前老 K 也查了幾次 MOS ，也許是因?yàn)槎ㄎ坏倪€不夠精準(zhǔn)，導(dǎo)致在 MOS 查找的關(guān)鍵字不夠 “ 關(guān)鍵 ” ，每次都是搜出一大堆結(jié)果卻無(wú)法逐一細(xì)細(xì)閱讀而毫無(wú)收獲，這次老 K 上 MOS 使用關(guān)鍵詞 “char endpoint_value different” 進(jìn)行搜索，很快就找到了文章 “ Bug 18550628 : AFTER UPGRADE TO 11.2.0.4QUERIES USING CHAR FIELDS CAN PERFORM POORLY ” ，看起來(lái)與我們發(fā)現(xiàn)的情況非常符合，然而打開(kāi)文章卻并沒(méi)有什么實(shí)際內(nèi)容，看起來(lái)像是因?yàn)殚_(kāi) SR 而形成的 bug 文章；然而，仔細(xì)看該文章，可以注意到它實(shí)際指向了另一篇文章：

查找 18255105 ，找到的文章是“ Patch for upgrade scripts to identify histograms affected by fix ofbug 15898932 ” ;

描述如下：

各位觀眾，讀完獲得了什么呢？反正，老K是獲得了許多，累了就不多說(shuō)了。

本文轉(zhuǎn)載于中亦安圖