記一條500行執行計劃的SQL問題分析-從應急處理到根因分析-技術人生系列第十八期

4 月 24 日，早上七點，老 K 為迎接某國有大型銀行批次投產后開門營業作現場支持該行運維團隊的工作；根據以往的經驗，該行每次批次投產會有數十套系統的軟件 / 環境版本變化、系統遷移等操作，在投產后的第一個工作日開門營業后，多少會有一些問題；而 ORACLE 數據庫作為各業務系統中的重要一環，往往是領導們關注的重點。

時間大約在 8 點左右，應用維護團隊報出問題來：某套系統的某關鍵業務在開門前，需要先上送報表到某國家監管機構，報表主要就是通過在數據庫中執行 SQL 語句生成的；以往這個報表的生成時間只需要 2 分鐘，而今跑了二十分鐘也沒有動靜，重提了好幾次也沒有效果，而前端柜臺業務開門時間是在 8 點半，必須要馬上解決，避免影響到業務開門時間；

通過現場快速查看，系統整體無異常，只是業務報表的 SQL 執行時間偏長，主要運行在 CPU 上，看起來可能是邏輯讀過大了，在分析間，老 K 也了解到該系統在這次批次投產過程中的變化；

雖然這個報表 SQL 以前也運行過，奈何這是新的環境，原環境也已經不在，沒法對比，看起來需要從頭開始分析了；

老 K 首先通過 dbms_workload_repository.create_snapshot 做了一個 snapshot ，然后抓一下 awrsqrpt 對語句進行分析；

語句邏輯讀確實非常大：

可以看到：

語句執行了將近 1300 秒，仍未執行完成；

邏輯讀達到 4.5 億；

通常來說，對于 SQL 性能問題，只需要理解 SQL 業務邏輯，分析一下 SQL 執行計劃，然后充分了解相關各表的數據分布，就可以給出相應的解決方案；只不過，這一次留給老 K 時間似乎有些短，壓力山大。

不過沒有關系，按套路來，先看看語句內容和執行計劃，然而，事情是這個樣子的：

這樣，老 K 就有幾分方了，光是執行計劃就達到了 568 行；再去看 SQL 語句內容，語句密密麻麻，操作終端上的 SQL 工具根本無法格式化 SQL 內容，基本也不具備可讀性；簡單看一眼執行計劃，稍微能總結一些執行計劃的特點：

如果是你，你將如何進一步分析呢？

說話間，從開始查問題，到與應用溝通，大致看語句，了解執行計劃，十分鐘已經過去了，時間已經來到了 8 點 10 分，留給老 K 的時間已經不多了；除了執行計劃，其他思考結果如下：

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

OK ，思考歸來，老 K 的思路是，語句的邏輯讀非常大，而以前執行較快，正常來說邏輯讀不會太大，如果這里真的是某個表的統計信息不準的話， 應該該表或者與該表關聯的表的邏輯讀會比較大 （這一句很重要），而該段時間內主要就是這條 SQL 在執行，那么我們為什么不看看這段時間的 AWR 報告，看看是哪個表或者哪些表的邏輯讀比較大呢？

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

XXDEALS_IDX7 的邏輯讀也達到了 1600 萬；

所屬用戶也正是運行報表 SQL 的用戶；

進一步檢查可以知道，執行計劃中的該表是存在的， 查看表的信息，大小大約 700M 左右，不算大，而且表的上次統計信息收集時間已經是 4 月 7 日，看上去距離當前時間也較久了 ；說干就干，開 8 個并行收集該表的統計信息；一分鐘時間就收集完成，再重提批量任務，執行計劃已經發生變化，執行完整個批量需要的時間大約就在 5 分鐘左右 ;

最終，報表順利上報，業務也基本準時開門，皆大歡喜。

我們看到，在這里的問題處理過程中，老 K 取巧了一下，在 SQL 語句和執行計劃都非常長，無法在短時間內直接定位執行計劃中所存在的問題的情況下，基于 SQL 執行時邏輯讀非常高的特點，借助 AWR 報告中邏輯讀 top 分布的情況，大致定位到可能存在導致執行計劃不正確的表，并收集統計信息，最終解決了問題； ORACLE 提供了很多工具和方法來定位不同的問題，關鍵看我們能不能利用這些已有信息，發現信息中的特征來找到解決方法；

問題是解決了，但是因為差點影響到業務開門，上面的領導還是比較關切，需要一個解釋，或者說需要一個團隊來承擔這個責任，這中間幾個關鍵點：

然而時間已經過了 8 點半，業務也均已開門，各新投系統和升級的系統也陸陸續續出現了一些小問題，需要在數據庫方面進行排查；要給出這個解釋暫時只能是口頭上的，也許沒有足夠的時間進行驗證。

通常來說，通過統計信息收集解決的問題，那無非就是統計信息過舊導致的；

但是這里有一個問題無法用統計信息過舊來解釋：為什么以往一直沒有問題，這次遷移到新的環境了，上來就有問題？是不是導入過程中有什么不該做的操作呢？

這里就需要仔細看看表的統計信息的收集時間了 :

可以看到，除最新收集的統計信息外， XXDEALS 表曾經收集過兩次，一次收集時間是 4 月 7 日，一次收集時間是 4 月 22 日（也就是數據導入當天），然而在我們最近一次收集之前表的最新統計信息收集時間是 4 月 7 日，那么意味著表的統計信息分析時間軸是這樣的：

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

是不是很奇怪，老 K 頓感疑惑，不過通過數據導入日志確認了 4 月 22 日 18:04 這個時間點其實正是在 dump 的導入過程中之后，老 K 的疑惑也就解開了。

在確認完這個統計信息分析的時間軸后，老 K 就有理由做出下述完美的猜想了：

我們通過腳本查看 SQL 涉及的表的統計信息的最新時間，發現確實有部分表的統計信息分析時間是在導入完成之后，部分表的分析時間是在導入完成之前；這樣看來，上述假設是極有可能的，基于上述可能，我們再次重申了我們對 ORACLE 數據庫數據導入后對應用維護團隊的操作要求也是我們的結論：

在導入完成后，需要重新收集表的統計信息（可以按表或者按用戶收集），其中， method_opt 參數建議指定為 repeat ；

在與領導匯報完后，這口老鍋算是甩的非常完美了 ^_^ ，老 K 繼續匆匆投入到其他問題的處理當中，驗證的事情可能需要留待后續來實現了。

到目前為止，我們分析到的問題可以捋一下：

時間空下來，想到如此完美的猜想，老 K 立即開始驗證起來；現在，我們有了針對 SQL 前后的兩個執行計劃，可以通過對比結果來分析原因了；語句依然還是太長，基本沒法直接讀，但是確認了一點， 語句確實是由 unionall 組合了大量的較簡單的多表連接來完成的 。

我們收集了表 XXDEALS 的統計信息，那么我們主要關注執行計劃中 XXDEALS 相關的部分的變化即可，然而， 568 行的執行計劃，與 XXDEALS 相關的部分也有幾十處，我們又如何能快速定位出導致邏輯讀劇增的那部分呢？

較差執行計劃:

較好的執行計劃：

從執行計劃分析，符合我們上述的小技巧，如果使用 hash join ，原則上兩表只需要執行一次掃描，而如果是 NL ，則可能會因為驅動表估算的行數不準而導致被驅動表的邏輯讀大增；

從變態的 SQL 語句中搜索出對應這段執行計劃的 SQL 大致如下：

并通過使用加 hint 的方式執行該語句讓其跑出兩個執行計劃對比起邏輯讀和執行計劃，可以驗證這段 SQL 確實是導致整個 SQL 執行效率大大下降的原因； 就這樣，我們通過執行計劃的分析，將紛繁的 SQL 分析化解為簡短的兩表關聯的分析；

根據上述分析，這里我們又可以進一步簡化；兩個執行計劃中，驅動表的位置和評估行數都沒有變化，那么我們唯一需要關注的是在較差的執行計劃中，為什么會使用 NL 呢？

即，我們需要關注的就只剩下表 XXDEALS 在相關 maturitydate 條件和 flagofdeal 條件下，為什么一個會走索引，而另一個卻沒有走索引，與統計信息的關系又如何?

要精確定位問題，在這里可能需要重現問題。這里其實要重現問題比較簡單，老 K 通過 dbms_stats.restore_table_stats 恢復表的統計信息，并將新舊表的定義（包含了統計信息又不用導數據）各導出一份，導入到 11.2.0.4 的測試環境中去，分別命名為 DEALS_0407 和 DEALS_0424 ，兩表分別使用的是 4 月 7 日的統計信息和 4 月 24 日的統計信息，也可以基本反映兩個日期中表的數據分布情況。

通過簡單測試，我們又把 maturitydate 字段的影響給排除掉了，現在唯一的區別就在與使用 flagofdeal=‘O’ 時，兩表評估的行數不一致；

那么這里 317 和 455K 都是怎么算出來的呢？我們試著看看 10053 能不能給我們一些幫助 ;

DEALS_0407 的 10053 關鍵評估信息：

DEALS_0424 的 10053 關鍵評估信息：

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

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

而 DEALS_0424 中，最終估算的 455K 條記錄則像是其 popular value 中估算出來的了；如果真的是這樣的話，那么基本是可以確認是因為數據變化，即 DEALS_0407 表中沒有 ’O’ 值記錄，而在 DEALS_0424 中則大量插入 / 修改了 ’O’ 值記錄了。

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

首先，我們來驗證 DEALS_0424 的估算值是否準確：

其中 get_external_value 數據來為自定義的轉換 endpoint_value 為實際字符串的函數，已經發布在 “ 中亦安圖”公眾賬號中，有需要的朋友可以關注中亦安圖公眾號，回復 “ 直方圖函數 ” 獲取；

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

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

與 10053 trace 和執行計劃中的都一致；

另一方面， DEALS_0407 直方圖桶的個數是 5 個，那么它又是些什么值呢，我們不妨也簡單看一下，確認一下是否確實是缺少了 ‘O’ 值：

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

看起來，確實在遷移升級期間沒有那么大的數據的變化；

那到這里，問題又是什么呢？

考慮到在之前環境中，原 SQL 的執行是沒有問題的，那么是不是說在原環境中對 flagofdeal=‘O’ 的記錄數評估應該是準確的呢？不如我們再來驗證一下：

沒錯，我們看到，如果我們再 SQL 中增加 OPTIMIZER_FEATURES_ENABLE('10.2.0.5') 的 hint 讓數據庫使用 10.2.0.5 的優化器的話，是能正確的評估出該 ’O’ 值記錄的行數；

同樣，即使是 11.2.0.3 的優化器，也同樣能正確的評估出 ’O’ 值記錄的行數：

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

我們還是要回到評估行數的問題上來，為什么明明我們看到的直方圖的記錄中有 ‘O’ 值， 11.2.0.4 的優化器卻認為直方圖信息中沒有 ‘O’ 值呢？難道是老 K 給出的 get_external_value 函數存在問題？這時，老 K 想起了在處理字符串的問題是經常會給我們帶來視覺錯誤的一個問題，那就是空格，于是，我再次查詢直方圖信息：

沒錯，就是空格，其實在轉化成字符串后，發現，兩者還是有區別的，我們再仔細對比的話，其實兩表直方圖的 endpoint_value 確實是不一樣的；我們又通過對比同表的其他字段直方圖信息確認了，一般如果實際值一樣，在信息里的 endpoint_value 應該是一樣的：

最后，通過多次確認測試，最終定位到只要列的類型為 char 類型，而且字段長度低于 8 ，那么會出現在 11.2.0.3 （及更低版本）與 11.2.0.4 的直方圖信息 endpoint_value 不一致；測試過程此處不表；

基本上能確認是 oracle 的一個變化，至少是 11.2.0.3 到 11.2.0.4 之間的一個變化；接下來的任務就是找到 ORACLE 官方的說明來，之前老 K 也查了幾次 MOS ，也許是因為定位的還不夠精準，導致在 MOS 查找的關鍵字不夠 “ 關鍵 ” ，每次都是搜出一大堆結果卻無法逐一細細閱讀而毫無收獲，這次老 K 上 MOS 使用關鍵詞 “char endpoint_value different” 進行搜索，很快就找到了文章 “ Bug 18550628 : AFTER UPGRADE TO 11.2.0.4QUERIES USING CHAR FIELDS CAN PERFORM POORLY ” ，看起來與我們發現的情況非常符合，然而打開文章卻并沒有什么實際內容，看起來像是因為開 SR 而形成的 bug 文章；然而，仔細看該文章，可以注意到它實際指向了另一篇文章：

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

描述如下：

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

本文轉載于中亦安圖