awr_plan_change.sql腳本是Kerry Osborne的一個腳本,這個腳本也是我非常喜歡并且經常使用的一個腳本。腳本如下所示

set?lines?155
col?execs?for?999,999,999
col?avg_etime?for?999,999.999
col?avg_lio?for?999,999,999.9
col?sql_id?for?a16
col?begin_interval_time?for?a30
col?node?for?99999
break?on?plan_hash_value?on?startup_time?skip?1
select?ss.snap_id
?????,?ss.instance_number?node
?????,?begin_interval_time
?????,?sql_id
?????,?plan_hash_value
?????,?nvl(executions_delta,0)?execs
?????,(elapsed_time_delta/decode(nvl(executions_delta,0),0,1,executions_delta))/1000000?avg_etime
?????,(buffer_gets_delta/decode(nvl(buffer_gets_delta,0),0,1,executions_delta))?avg_lio
from?DBA_HIST_SQLSTAT?S,?DBA_HIST_SNAPSHOT?SS
where?sql_id?=?nvl('&sql_id','799tsyjq9p1r6')
and?ss.snap_id?=?S.snap_id
and?ss.instance_number?=?S.instance_number
and?executions_delta?>?0
order?by?1,?2,?3
/

正常情況下，這個腳本并沒有什么問題，但是這個腳本在某些場景下，它計算SQL語句的平均執(zhí)行時間（avg_etime）是有問題的（avg_etime在有些場景是不準確的）。下面以一個案例來簡單分析一下。如下所示，SQL_ID=799tsyjq9p1r6是數(shù)據倉庫中的一個SQL語句，使用awr_plan_change.sql分析這個SQL，發(fā)現(xiàn)它的平均執(zhí)行時間（AVG_ETIME）有非常大的波動，如下所示，我們以2023-10-04為起點，如下所示，你會發(fā)現(xiàn)它的平均執(zhí)行時間多的時候為1559.825秒，短的時侯為25.080秒，這個SQL并沒有使用綁定變量，它的執(zhí)行計劃從2023-10-04號到2023-10-08號沒有變化過（PLAN_HASH_VALUE沒有變化），那么這個SQL的平均執(zhí)行時間為什么有這么大的波動呢？

其實，確切來說，就是awr_plan_change.sql中計算的平均執(zhí)行時間（AVG_ETIME）有誤，首先要說明的是數(shù)據庫的快照間隔(SNAP_INTERVAL)是30分鐘，而這個SQL的執(zhí)行時間超過AWR的快照間隔了。這個SQL的開始執(zhí)行時間和結束時間，跨越了幾個snap_id，我們可以使用sqlstat.sql分析如下所示：

DBW1:SYS>select
??2??sql_id,
??3??plan_hash_value,
??4??TO_CHAR(BEGIN_INTERVAL_TIME,'yyyy-mm-dd?hh24:mi:ss')?AS?BEGIN_INTERVAL_TIME,
??5??TO_CHAR(END_INTERVAL_TIME,'yyyy-mm-dd?hh24:mi:ss')?AS?END_INTERVAL_TIME,
??6??executions_delta,
??7??ROUND(ELAPSED_TIME_DELTA/(nonzeroexecutions*1000000),1)?"Elapsed?Average",
??8??ROUND(CPU_TIME_DELTA/(nonzeroexecutions*1000000),1)?"CPU?Average",
??9??ROUND(IOWAIT_DELTA/(nonzeroexecutions*1000000),1)?"IO?Average",
?10??ROUND(CLWAIT_DELTA/(nonzeroexecutions*1000000),1)?"Cluster?Average",
?11??ROUND(APWAIT_DELTA/(nonzeroexecutions*1000000),1)?"Application?Average",
?12??ROUND(CCWAIT_DELTA/(nonzeroexecutions*1000000),1)?"Concurrency?Average",
?13??BUFFER_GETS_DELTA/nonzeroexecutions?"Average?buffer?gets",
?14??DISK_READS_DELTA/nonzeroexecutions?"Average?disk?reads",
?15??trunc(PHYSICAL_WRITE_BYTES_DELTA/(1024*1024*nonzeroexecutions))?"Average?disk?write?megabytes",
?16??ROWS_PROCESSED_DELTA/nonzeroexecutions?"Average?rows?processed"
?17??from
?18??(select
?19??ss.snap_id,
?20??ss.sql_id,
?21??ss.plan_hash_value,
?22??sn.BEGIN_INTERVAL_TIME,
?23??sn.END_INTERVAL_TIME,
?24??ss.executions_delta,
?25??case?ss.executions_delta?when?0?then?1?else?ss.executions_delta?end?nonzeroexecutions,
?26??ELAPSED_TIME_DELTA,
?27??CPU_TIME_DELTA,
?28??IOWAIT_DELTA,
?29??CLWAIT_DELTA,
?30??APWAIT_DELTA,
?31??CCWAIT_DELTA,
?32??BUFFER_GETS_DELTA,
?33??DISK_READS_DELTA,
?34??PHYSICAL_WRITE_BYTES_DELTA,
?35??ROWS_PROCESSED_DELTA
?36??from?DBA_HIST_SQLSTAT?ss,DBA_HIST_SNAPSHOT?sn
?37??where?ss.sql_id?=?'&sql_id'
?38??and?ss.snap_id=sn.snap_id
?39??and?ss.INSTANCE_NUMBER=sn.INSTANCE_NUMBER)
?40??where?ELAPSED_TIME_DELTA?>?0
?41??order?by?snap_id,sql_id;
Enter?value?for?sql_id:?799tsyjq9p1r6

SQL_ID?????????????PLAN_HASH_VALUE?BEGIN_INTERVAL_TIME???????????????????????????????????????END_INTERVAL_TIME?????????EXECUTIONS_DELTA?Elapsed?Average?CPU?Average?IO?Average?Cluster?Average?Application?Average?Concurrency?Average?Average?buffer?gets?Average?disk?reads?Average?disk?write?megabytes?Average?rows?processed
------------------?---------------?---------------------------------------------------------?-------------------------?----------------?---------------?-----------?----------?---------------?-------------------?-------------------?-------------------?------------------?----------------------------?----------------------
799tsyjq9p1r6???????????1879238228?2023-09-24?14:00:37???????????????????????????????????????2023-09-24?14:30:44??????????????????????0??????????1312.3????????56.3?????1283.1???????????????0???????????????????0???????????????????0?????????????2983520?????????????621742????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-09-24?14:30:44???????????????????????????????????????2023-09-24?15:00:50??????????????????????1???????????968.7????????33.2????????950???????????????0???????????????????0??????????????????.1?????????????2522751?????????????328654????????????????????????????0??????????????????31635
799tsyjq9p1r6???????????1879238228?2023-09-25?14:30:16???????????????????????????????????????2023-09-25?15:00:23??????????????????????0??????????1581.8????????52.1?????1556.6???????????????0???????????????????0???????????????????0?????????????2216777?????????????523756????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-09-25?15:00:23???????????????????????????????????????2023-09-25?15:30:30??????????????????????1??????????1238.1????????49.7?????1211.7???????????????0???????????????????0???????????????????0?????????????2457976?????????????547253????????????????????????????0??????????????????26778
799tsyjq9p1r6???????????1879238228?2023-09-26?14:00:40???????????????????????????????????????2023-09-26?14:30:47??????????????????????0?????????????182?????????6.6??????178.9???????????????0???????????????????0???????????????????0??????????????249644??????????????63126????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-09-26?14:30:47???????????????????????????????????????2023-09-26?15:00:54??????????????????????0??????????1806.2????????61.5?????1775.5???????????????0???????????????????0???????????????????0?????????????2761065?????????????665285????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-09-26?15:00:54???????????????????????????????????????2023-09-26?15:30:01??????????????????????1???????????421.8????????18.2??????411.3???????????????0???????????????????0??????????????????.1?????????????1123432?????????????243842????????????????????????????0??????????????????23641
799tsyjq9p1r6???????????1879238228?2023-09-27?14:00:09???????????????????????????????????????2023-09-27?14:30:16??????????????????????0???????????922.4????????33.9??????905.8???????????????0???????????????????0???????????????????0?????????????1579540?????????????335758????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-09-27?14:30:16???????????????????????????????????????2023-09-27?15:00:23??????????????????????1??????????1753.4??????????58?????1722.9???????????????0???????????????????0???????????????????0?????????????3440756?????????????593153????????????????????????????0??????????????????28687
799tsyjq9p1r6???????????1879238228?2023-09-28?14:00:39???????????????????????????????????????2023-09-28?14:30:46??????????????????????0???????????948.9????????32.6??????933.9???????????????0???????????????????0???????????????????0?????????????1237907?????????????301664????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-09-28?14:30:46???????????????????????????????????????2023-09-28?15:00:53??????????????????????1??????????1794.8????????61.5?????1764.1???????????????0???????????????????0???????????????????0?????????????2946573?????????????637203????????????????????????????0??????????????????23879
799tsyjq9p1r6???????????1879238228?2023-09-29?14:00:10???????????????????????????????????????2023-09-29?14:30:18??????????????????????1???????????337.1????????21.6??????323.9???????????????0???????????????????0???????????????????0?????????????1693956?????????????273991????????????????????????????0???????????????????9581
799tsyjq9p1r6???????????1879238228?2023-09-30?14:00:39???????????????????????????????????????2023-09-30?14:30:46??????????????????????0??????????1034.6????????39.3?????1015.1???????????????0???????????????????0???????????????????0?????????????1833993?????????????405250????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-09-30?14:30:46???????????????????????????????????????2023-09-30?15:00:53??????????????????????0????????????1804????????57.5?????1771.7???????????????0???????????????????0???????????????????0?????????????4533708?????????????541639????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-09-30?15:00:53???????????????????????????????????????2023-09-30?15:31:00??????????????????????1????????????72.9?????????3.7???????70.5???????????????0???????????????????0???????????????????0??????????????369115??????????????31273????????????????????????????0??????????????????38389
799tsyjq9p1r6???????????1879238228?2023-10-01?14:00:09???????????????????????????????????????2023-10-01?14:30:17??????????????????????0???????????118.9?????????4.3??????116.8???????????????0???????????????????0???????????????????0??????????????179510??????????????44841????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-01?14:30:17???????????????????????????????????????2023-10-01?15:00:24??????????????????????0??????????1806.4????????53.9?????1780.9???????????????0???????????????????0???????????????????0?????????????2070104?????????????543732????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-01?15:00:24???????????????????????????????????????2023-10-01?15:30:31??????????????????????0??????????1806.2????????56.2???????1779???????????????0???????????????????0??????????????????.1?????????????2234512?????????????470020????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-01?15:30:31???????????????????????????????????????2023-10-01?16:00:38??????????????????????1??????????1027.9????????33.4?????1010.2???????????????0???????????????????0???????????????????0?????????????1920920?????????????339045????????????????????????????0??????????????????36342
799tsyjq9p1r6???????????1879238228?2023-10-02?14:00:40???????????????????????????????????????2023-10-02?14:30:47??????????????????????0??????????1447.3????????46.4?????1426.4???????????????0???????????????????0???????????????????0?????????????1699747?????????????415567????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-02?14:30:47???????????????????????????????????????2023-10-02?15:00:54??????????????????????0????????????1806????????59.1?????1775.6???????????????0???????????????????0??????????????????.1?????????????3280821?????????????595508????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-02?15:00:54???????????????????????????????????????2023-10-02?15:30:01??????????????????????1???????????221.6?????????9.1????????216???????????????0???????????????????0??????????????????.1??????????????742730??????????????96869????????????????????????????0??????????????????32297
799tsyjq9p1r6???????????1879238228?2023-10-03?14:00:10???????????????????????????????????????2023-10-03?14:30:17??????????????????????0???????????720.1????????26.9??????706.8???????????????0???????????????????0???????????????????0?????????????1153872?????????????262211????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-03?14:30:17???????????????????????????????????????2023-10-03?15:00:24??????????????????????1??????????1399.9??????????47?????1372.8???????????????0???????????????????0???????????????????0?????????????3553183?????????????437388????????????????????????????0??????????????????26545
799tsyjq9p1r6???????????1879238228?2023-10-04?14:00:38???????????????????????????????????????2023-10-04?14:30:45??????????????????????0??????????1146.6????????47.3?????1121.8???????????????0???????????????????0???????????????????0?????????????2332277?????????????545996????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-04?14:30:45???????????????????????????????????????2023-10-04?15:00:51??????????????????????1??????????1042.1????????36.9?????1020.6???????????????0???????????????????0???????????????????0?????????????2892948?????????????368538????????????????????????????0??????????????????29540
799tsyjq9p1r6???????????1879238228?2023-10-05?14:00:05???????????????????????????????????????2023-10-05?14:30:12??????????????????????0???????????939.4????????35.5??????921.7???????????????0???????????????????0???????????????????0?????????????1556583?????????????360616????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-05?14:30:12???????????????????????????????????????2023-10-05?15:00:19??????????????????????0??????????1802.9????????59.5?????1768.4???????????????0???????????????????0??????????????????.1?????????????4668380?????????????553976????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-05?15:00:19???????????????????????????????????????2023-10-05?15:30:26??????????????????????1????????????25.1?????????1.3???????24.2???????????????0???????????????????0???????????????????0??????????????103952??????????????11067????????????????????????????0??????????????????35528
799tsyjq9p1r6???????????1879238228?2023-10-06?14:00:31???????????????????????????????????????2023-10-06?14:30:38??????????????????????0??????????1059.1??????????44?????1036.6???????????????0???????????????????0???????????????????0?????????????2127809?????????????447816????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-06?14:30:38???????????????????????????????????????2023-10-06?15:00:45??????????????????????1??????????1559.8????????60.8?????1524.6???????????????0???????????????????0???????????????????0?????????????4663034?????????????562076????????????????????????????0??????????????????38124
799tsyjq9p1r6???????????1879238228?2023-10-07?14:00:58???????????????????????????????????????2023-10-07?14:30:05??????????????????????0??????????1101.6????????47.7?????1077.5???????????????0???????????????????0???????????????????0?????????????2064020?????????????547169????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-07?14:30:05???????????????????????????????????????2023-10-07?15:00:12??????????????????????0??????????1806.2????????66.7?????1771.2???????????????0???????????????????0???????????????????0?????????????3817811?????????????694678????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-07?15:00:12???????????????????????????????????????2023-10-07?15:30:19??????????????????????1????????????88.3?????????3.3???????86.3???????????????0???????????????????0???????????????????0??????????????244627??????????????25431????????????????????????????0??????????????????34400
799tsyjq9p1r6???????????1879238228?2023-10-08?14:30:31???????????????????????????????????????2023-10-08?15:00:38??????????????????????0????????????1638????????42.5?????1617.2???????????????0???????????????????0???????????????????0?????????????1728020?????????????412431????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-08?15:00:38???????????????????????????????????????2023-10-08?15:30:45??????????????????????0??????????1808.6????????57.1?????1780.4???????????????0???????????????????0???????????????????0?????????????2167202?????????????498306????????????????????????????0??????????????????????0
799tsyjq9p1r6???????????1879238228?2023-10-08?15:30:45???????????????????????????????????????2023-10-08?16:00:52??????????????????????1??????????1187.7????????32.4?????1171.5???????????????0???????????????????0???????????????????0?????????????1682580?????????????297268????????????????????????????0??????????????????31062

可以清晰的看到2023-10-07號，這個SQL的執(zhí)行時間在快照2023-10-07 14:00和2023-10-07 15:00AWR快照區(qū)間內完成，而在14：00-14：30， 14：30-15：00內，SQL沒有執(zhí)行完成，所以它的執(zhí)行次數(shù)為0，在15：00-15：30這個快照區(qū)間內，它的ELAPSED_TIME_DELTA為88.3，所以這樣統(tǒng)計時，它的"Elapsed Average"（它等價于awr_plan_change.sql腳本中的AVG_ETIME）為88.3秒，而這個SQL的實際執(zhí)行時間為1101.6+ 1806.2+ 88.3 ~= 2996.1秒，而2023-10-08號的執(zhí)行時長為1638 +1808.6 + 1187.7~= 4634.3秒。那么awr_plan_change.sql統(tǒng)計出錯的原因是啥呢？因為腳本里面有一個條件：and executions_delta > 0，它排除了那些正在執(zhí)行，但是快照間隔內沒有執(zhí)行完的記錄數(shù)據（因為這些記錄的executions_delta為0），正確的做法是要匯總這些數(shù)據然后除以執(zhí)行次數(shù)才是SQL正在的平均執(zhí)行時間。所以awr_plan_change.sql對于哪些執(zhí)行時間超過AWR采樣間隔的SQL，它的統(tǒng)計數(shù)據就會不正確。

其實DBA_HIST_SQLSTAT的elapsed_time_delta這個字段，它統(tǒng)計的是AWR采樣間隔內，SQL語句（執(zhí)行一次或多次）的執(zhí)行時間，也就是說它是這個采樣間隔內差值，一個變化值，而不是SQL語句的完整累加值。Delta本身就是第4個希臘字母，其實delta也表示微積分中的曲率，在數(shù)學和科學中表示單位時間內，指標的的變化量。所以，你分析AWR報告時，也要注意一個問題，如果你生成AWR報告的快照開始時間和結束時間不能覆蓋SQL語句的開始執(zhí)行時間和結束執(zhí)行時間，那么AWR報告中的SQL語句的Elapsed Time per Exec (s)也是不正確的。這個也是很多人沒有特別留意的地方。文章來源地址http://www.zghlxwxcb.cn/news/detail-710537.html