[Oracle維護工程師手記系列]一次升級後運行變慢的分析
阿新 • • 發佈:2018-04-29
設置 增加 整體 dex classes 並不是 select 統計 系列
***遷移前
Load Profile
Per Second Per Transaction Per Exec Per Call
DB Time(s): 1.1 0.0 0.00 0.00
DB CPU(s): 0.3 0.0 0.00 0.00
Parses: 158.3 4.8
Hard parses: 8.8 0.3 <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
Executes: 620.2 18.2
***遷移後
Load Profile
Per Second Per Transaction Per Exec Per Call
DB Time(s): 0.8 0.0 0.00 0.00
DB CPU(s): 0.6 0.0 0.00 0.00
Parses (SQL): 375.8 14.7
Hard parses (SQL): 75.2 3.0 <<<<<<<<<<<<<<<<<<<<<<<<< hard parse 大幅度增加
Executes (SQL): 702.7 28.3
客戶報告,在新環境裏,設置了 對 應用中的所有的 SQL文 都追加了 類似於
"SELECT /*+ OPTIMIZER_FEATURES_ENABLE(‘11.1.0.7‘) ORDERED INDEX(T0001 T0001_001) NO_USE_HASH(FBM10) */" 的hint之後,
發現性能基本回到了遷移前的水平。
從這一點來考慮,OPTIMIZER_FEATURES_ENABLE,可能是影響到了 optimizer_adaptive_features 功能。這一功能會在SQL文執行
的時候,動態地判斷有沒有更好的執行計劃。而很可能對客戶程序的一部分SQL文,反而動態調整執行計劃產生了大量的Hard Parse,
整體上拖延了執行時間。
客戶也懷疑 是 文檔 2312911.1 所提到的 12.1 的 optimizer_adaptive_features 功能不夠完善導致出現問題。文檔 2312911.1
提及,12.1 的 optimizer_adaptive_features 功能不夠完善,可以特殊處理,以達到12.2的效果(12.2中, optimizer_adaptive_
features 有所改善,被拆分成為了兩個參數)。
那麽,到底是不是這樣呢,客戶希望進一步進行分析調查。
從拿到了遷移前後的AWR來對比,發現了有趣的狀況:實際上從Top N SQL來看,遷移前的SQL文,遷移後執行時間其實都大幅度縮短了。
***遷移前環境
========================
SQL ordered by Elapsed Time
Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
% Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100
Total DB Time (s): 2,597
Captured SQL account for 58.8% of Total <<<<<<<<<<<<Top 10 的SQL文,占據了整體執行時間的 59%(1532秒)
Total DB Time (s): 2,597
Captured PL/SQL account for 0.3% of Total
========================
***遷移後(未追加 OPTIMIZER_FEATURES_ENABLE hint 的時候)
========================
SQL ordered by Elapsed Time ★
Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
% Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100
%Total - Elapsed Time as a percentage of Total DB time
%CPU - CPU Time as a percentage of Elapsed Time
%IO - User I/O Time as a percentage of Elapsed Time
Captured SQL account for 27.9% of Total DB Time (s): 1,771 <<<<<<<<<<<<Top 10 的SQL文,占據了整體執行時間的 28%(500秒)
Captured PL/SQL account for 1.3% of Total DB Time (s): 1,771
========================
從具體的top 10 SQL文執行時間上,也可以看出來:
++++++++++++++++++++++++++++++++++++++++++++++
2ac8g6tagg67x 遷移後>>17,122 回執行 CPU Time 13.27s、Elapsed Time 139.03s
遷移前>>21,018 回執行 CPU Time 16s、Elapsed Time 839s
5mt3dyz3r6af8 遷移後>>425 回執行 CPU Time 25.28s、Elapsed Time 33.10s
遷移前>>509回執行 CPU Time 44s、Elapsed Time 105s
7tjhsnk6ruw6m 遷移後>>165 回執行 CPU Time 16.67s、Elapsed Time 21.69s
遷移前>>165 回執行 CPU Time 25s、Elapsed Time 50s
......
baq2zs9gns3co 遷移後>>51,730 回執行 CPU Time 9.92s、Elapsed Time 16.57s
遷移前>>67,66 4回執行 CPU Time 10s、Elapsed Time 26s
++++++++++++++++++++++++++++++++++++++++++++++
那麽,問題到底處在哪裏呢? 我的猜測是: 雖然TopN 那些SQL文的執行時間減小了。但是還有很多執行很短暫的SQL文,由於動態執行
計劃調整,導致事件增加了。
這也很容易理解:
如果一條SQL語句的執行時間原本是200ms,如果動態執行計劃調整花5ms,使得因執行更好的執行計劃而較少了執行時間20ms,總體上來說
就是賺到了。
可是如果你一條小SQL執行語句,本來執行時間才20ms,如果動態執行計劃調整花5ms,使得因執行更好的執行計劃而較少了執行時間2ms,
反而執行時間增加了。
如果這條小SQL執行語句,反復多次執行呢?那問題就惡化了。
就好比:雖說磨刀不誤砍柴功,但是如果每砍一個小樹杈,都要磨一次刀,那是不是有點浪費時間啊。
對於這個推測,客戶仍然想要了解更詳細的細節,那麽好吧,我們來看看ASH的情況:
遷移前
"In Hard Parse" ==> 15 行 "In Hard Parse" 的比例:37.5%
2018/03/12 15:26:36 ---> 2018/03/12 15:37:25.693000000
SQL_ID: 30 個
遷移後
"In Hard Parse" ==> 252 行 "In Hard Parse" 的比例:76.6%
2018/03/20 11:33:50 ---> 2018/03/20 12:25:58.591000000
SQL_ID: 292 個
遷移後的總體時間不但大幅度延長了,而且ASH中統計出來的sql_id 明顯增多。所以可以推測很多原本執行時間很短的sql語句,因為執行計劃
調整的原因,話費時間進行了 Hard Parse,所以當ASH采樣的時候,因為沒有執行完畢,更多的出現在ASH履歷中。
那麽,作為結論, 12c的執行計劃調整並不是適合所有sql文的,對效果不佳的語句,不妨添加 OPTIMIZER_FEATURES_ENABLE 進行微調。
客戶報告,
當他從 Oracle 11.1.0.7 ,遷移到雲環境,並且升級到12.1.0.2。
運行客戶的應用程序測試,發現比以前更慢了。
從AWR report 的"Top 10 Foreground Events by Total Wait Time"和"Wait Classes by Total Wait Time"等信息,
可以看到 CPU 值升高了。
初步思考,懷疑由於環境的不同,導致性能不同。但是客戶說,這兩個環境的CPU數目/內存大小等各方面情況都完全一樣。
那麽就的考慮其他的原因了。
遷移前的環境和遷移後的環境對比,從AWR report 中,可以看到,遷移後的 "Hard parse" 的比例明顯偏高。
***遷移前
Load Profile
Per Second Per Transaction Per Exec Per Call
DB Time(s): 1.1 0.0 0.00 0.00
DB CPU(s): 0.3 0.0 0.00 0.00
Parses: 158.3 4.8
Hard parses: 8.8 0.3 <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
Executes: 620.2 18.2
***遷移後
Load Profile
Per Second Per Transaction Per Exec Per Call
DB CPU(s): 0.6 0.0 0.00 0.00
Parses (SQL): 375.8 14.7
Hard parses (SQL): 75.2 3.0 <<<<<<<<<<<<<<<<<<<<<<<<< hard parse 大幅度增加
Executes (SQL): 702.7 28.3
客戶報告,在新環境裏,設置了 對 應用中的所有的 SQL文 都追加了 類似於
"SELECT /*+ OPTIMIZER_FEATURES_ENABLE(‘11.1.0.7‘) ORDERED INDEX(T0001 T0001_001) NO_USE_HASH(FBM10) */" 的hint之後,
從這一點來考慮,OPTIMIZER_FEATURES_ENABLE,可能是影響到了 optimizer_adaptive_features 功能。這一功能會在SQL文執行
的時候,動態地判斷有沒有更好的執行計劃。而很可能對客戶程序的一部分SQL文,反而動態調整執行計劃產生了大量的Hard Parse,
整體上拖延了執行時間。
客戶也懷疑 是 文檔 2312911.1 所提到的 12.1 的 optimizer_adaptive_features 功能不夠完善導致出現問題。文檔 2312911.1
提及,12.1 的 optimizer_adaptive_features 功能不夠完善,可以特殊處理,以達到12.2的效果(12.2中, optimizer_adaptive_
features 有所改善,被拆分成為了兩個參數)。
那麽,到底是不是這樣呢,客戶希望進一步進行分析調查。
從拿到了遷移前後的AWR來對比,發現了有趣的狀況:實際上從Top N SQL來看,遷移前的SQL文,遷移後執行時間其實都大幅度縮短了。
***遷移前環境
========================
SQL ordered by Elapsed Time
Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
% Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100
Total DB Time (s): 2,597
Captured SQL account for 58.8% of Total <<<<<<<<<<<<Top 10 的SQL文,占據了整體執行時間的 59%(1532秒)
Total DB Time (s): 2,597
Captured PL/SQL account for 0.3% of Total
========================
***遷移後(未追加 OPTIMIZER_FEATURES_ENABLE hint 的時候)
========================
SQL ordered by Elapsed Time ★
Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
% Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100
%Total - Elapsed Time as a percentage of Total DB time
%CPU - CPU Time as a percentage of Elapsed Time
%IO - User I/O Time as a percentage of Elapsed Time
Captured SQL account for 27.9% of Total DB Time (s): 1,771 <<<<<<<<<<<<Top 10 的SQL文,占據了整體執行時間的 28%(500秒)
Captured PL/SQL account for 1.3% of Total DB Time (s): 1,771
========================
從具體的top 10 SQL文執行時間上,也可以看出來:
++++++++++++++++++++++++++++++++++++++++++++++
2ac8g6tagg67x 遷移後>>17,122 回執行 CPU Time 13.27s、Elapsed Time 139.03s
遷移前>>21,018 回執行 CPU Time 16s、Elapsed Time 839s
5mt3dyz3r6af8 遷移後>>425 回執行 CPU Time 25.28s、Elapsed Time 33.10s
遷移前>>509回執行 CPU Time 44s、Elapsed Time 105s
7tjhsnk6ruw6m 遷移後>>165 回執行 CPU Time 16.67s、Elapsed Time 21.69s
遷移前>>165 回執行 CPU Time 25s、Elapsed Time 50s
......
baq2zs9gns3co 遷移後>>51,730 回執行 CPU Time 9.92s、Elapsed Time 16.57s
遷移前>>67,66 4回執行 CPU Time 10s、Elapsed Time 26s
++++++++++++++++++++++++++++++++++++++++++++++
那麽,問題到底處在哪裏呢? 我的猜測是: 雖然TopN 那些SQL文的執行時間減小了。但是還有很多執行很短暫的SQL文,由於動態執行
計劃調整,導致事件增加了。
這也很容易理解:
如果一條SQL語句的執行時間原本是200ms,如果動態執行計劃調整花5ms,使得因執行更好的執行計劃而較少了執行時間20ms,總體上來說
就是賺到了。
可是如果你一條小SQL執行語句,本來執行時間才20ms,如果動態執行計劃調整花5ms,使得因執行更好的執行計劃而較少了執行時間2ms,
反而執行時間增加了。
如果這條小SQL執行語句,反復多次執行呢?那問題就惡化了。
就好比:雖說磨刀不誤砍柴功,但是如果每砍一個小樹杈,都要磨一次刀,那是不是有點浪費時間啊。
對於這個推測,客戶仍然想要了解更詳細的細節,那麽好吧,我們來看看ASH的情況:
遷移前
"In Hard Parse" ==> 15 行 "In Hard Parse" 的比例:37.5%
2018/03/12 15:26:36 ---> 2018/03/12 15:37:25.693000000
SQL_ID: 30 個
遷移後
"In Hard Parse" ==> 252 行 "In Hard Parse" 的比例:76.6%
2018/03/20 11:33:50 ---> 2018/03/20 12:25:58.591000000
SQL_ID: 292 個
遷移後的總體時間不但大幅度延長了,而且ASH中統計出來的sql_id 明顯增多。所以可以推測很多原本執行時間很短的sql語句,因為執行計劃
調整的原因,話費時間進行了 Hard Parse,所以當ASH采樣的時候,因為沒有執行完畢,更多的出現在ASH履歷中。
那麽,作為結論, 12c的執行計劃調整並不是適合所有sql文的,對效果不佳的語句,不妨添加 OPTIMIZER_FEATURES_ENABLE 進行微調。
[Oracle維護工程師手記系列]一次升級後運行變慢的分析