最近在優化數據庫服務器上高消耗語句/過程,發現一個存儲過程優化後依舊出如今Profiler跟蹤裏。將Profiler跟蹤文件中過程執行語句取出,打開一個查詢窗口(SPID=144),set statistics io on,同時開啓Profiler跟蹤SPID=144中的語句執行狀況。
下面是在查詢窗口的執行結果,邏輯讀只有17:
咱們再看Profiler跟蹤窗口的結果:
此處的CPU(1216)、Reads(160206)相比查詢窗口中的邏輯讀高出不少。查看存儲過程相應部分對應的語句,僅僅是兩個表關聯查詢而已:
若是直接執行存儲過程當中的語句會是怎樣的呢?首先,按照過程參數傳遞的形式,將必要的參數Declare,執行:
其次,將參數用具體數值代替,再次執行:
以上兩圖中邏輯讀沒發現什麼區別,但咱們轉到Profiler跟蹤窗口,單獨執行存儲過程當中的查詢語句,若是top N 是以參數形式傳入其cpu、reads與執行存儲過程的消耗差很少,但比top 具體值的cpu、reads高不少:
此時咱們應該想到它們的執行計劃是不一樣的,從Profiler結果能夠看出這塊的消耗能夠經過具體值,或在語句結尾+option(recompile)來下降。
下面咱們將@typeid=2這一段封裝到測試存儲過程,而後分別查看語句末尾有無+option(recompile),執行此存儲過程並查看執行計劃。首先,咱們對@typeid=2中的語句不作任何修改,模擬原過程執行狀況:
而後,咱們在查詢語句的末尾加上+option(recompile),讓其執行到此語句時,重編譯:
注意到了沒有,二者使用的索引徹底同樣,但它們在Profiler跟蹤裏的消耗卻相差甚大。重編譯在排序操做返回的記錄數(228)較原過程的排序操做返回的記錄數(47331)少不少,它直接影響對錶u上idx_userID的執行次數。推測就是對u的執行次數,致使兩個語句在Profiler跟蹤裏的消耗懸殊。
實際上無論是執行存儲過程仍是單獨執行語句,在查詢窗口的消息信息中沒有表u的邏輯讀取信息:
依據執行計劃,確定有對u表的讀取操做,爲何在set statistics io on時,它沒有出現?什麼狀況下會出現這種狀況呢?
優化心得
使用RML分析.TRC文件真的很方便,咱們能夠按照下面的步驟來分析數據庫服務器上高消耗的語句:
一、開啓服務器端跟蹤收集一段時間的數據(例如18:00~第二天06:00,cpu>=33,根據狀況調整)
二、使用RML工具分析跟蹤數據(.TRC),不少存儲過程調用或動態語句整體是同樣的,只是帶的參數會有不一樣,這個工具會把它們歸類
三、根據歸類,優先將總消耗大的語句優化
四、RML分析報表以圖表展現,支持導出到execl、word、pdf;也能夠用語句直接從庫下獲取符合需求的語句
下面代碼提取[按照同一類型的語句,統計最昂貴的語句]:html
--使用RML Cmd Prompt導入跟蹤數據 ReadTrace -I"F:\TroubleShooting\Trace\HostName_InstanceName_HighCPU33_after.trc" -o"F:\TroubleShooting\Trace\output" -S"127.0.0.1,7777" -d"PerfAnalysis" -E USE PerfAnalysis GO --查詢跟蹤 select MIN(StartTime),MAX(EndTime),COUNT(*) from fn_trace_gettable(N'F:\TroubleShooting\Trace\HostName_InstanceName_HighCPU33_after.trc', default) where cpu is not null select * from ReadTrace.tblTimeIntervals select top 10 * from ReadTrace.tblBatchPartialAggs select top 10 * from ReadTrace.tblUniqueBatches --最初是按HashID獲得總消耗CPU、Duration、Reads、Writes前N的語句 --後期根據需求添加DBID、LoginNameID,還能夠計算平均消耗 select *, row_number() over(order by sum_CPU_ms desc) as QueryNumber from ( select --a.HashID, sum(CompletedEvents) as Executes, sum(TotalCPU) as sum_CPU_ms, sum(TotalCPU)/sum(CompletedEvents) as avg_CPU_ms,--add sum(TotalDuration)/1000 as sum_Duration_ms, sum(TotalDuration)/(sum(CompletedEvents)*1000) as avg_Duration_ms,--add sum(TotalReads) as sum_Reads, sum(TotalReads)/sum(CompletedEvents) as avg_Reads,--add sum(TotalWrites) as sum_Writes, sum(TotalWrites)/sum(CompletedEvents) as avg_Writes,--add --sum(AttentionEvents) as sum_Attentions, --(select StartTime from ReadTrace.tblTimeIntervals i where TimeInterval = @StartTimeInterval) as [StartTime], --(select EndTime from ReadTrace.tblTimeIntervals i where TimeInterval = @EndTimeInterval) as [EndTime], --add DatabaseName、LoginName (select distinct DatabaseName from fn_trace_gettable(N'F:\TroubleShooting\Trace\HostName_InstanceName_HighCPU33_after.trc', default) where DatabaseID=a.DBID) as DatabaseName, (select LoginName from ReadTrace.tblUniqueLoginNames where iID=a.LoginNameID) as LoginName, (select cast(NormText as nvarchar(4000)) from ReadTrace.tblUniqueBatches b where b.HashID = a.HashID) as [NormText], row_number() over(order by sum(TotalCPU) desc) as CPUDesc, row_number() over(order by sum(TotalCPU) asc) as CPUAsc, row_number() over(order by sum(TotalDuration) desc) as DurationDesc, row_number() over(order by sum(TotalDuration) asc) as DurationAsc, row_number() over(order by sum(TotalReads) desc) as ReadsDesc, row_number() over(order by sum(TotalReads) asc) as ReadsAsc, row_number() over(order by sum(TotalWrites) desc) as WritesDesc, row_number() over(order by sum(TotalWrites) asc) as WritesAsc from ReadTrace.tblBatchPartialAggs a --where TimeInterval @StartTimeInterval and @EndTimeInterval --and a.AppNameID = isnull(@iAppNameID, a.AppNameID) --and a.LoginNameID = isnull(@iLoginNameID, a.LoginNameID) --and a.DBID = isnull(@iDBID, a.DBID) group by a.HashID,a.DBID,a.LoginNameID ) as Outcome where (CPUDesc <= 20 --or CPUAsc <= @TopN or DurationDesc <= 20 --or DurationAsc <= @TopN or ReadsDesc <= 20 --or ReadsAsc <= @TopN or WritesDesc <= 20 --or WritesAsc <= @TopN ) order by sum_CPU_ms desc option (recompile) select top 100 EventClass,TextData,DatabaseName,DatabaseID,Duration/1000 Duration_ms,CPU CPU_ms,Reads,Writes,StartTime,EndTime,HostName,LoginName,ApplicationName from fn_trace_gettable(N'F:\TroubleShooting\Trace\HostName_InstanceName_HighCPU33_after.trc', default) where TextData like '%GAMEWEB_ADMIN_GAMESCORE_LOG%'
代碼對應的是RML報表的Top Unique Batches頁面,同時增長對數據庫、應用程序分組,以及平均消耗值信息。部分組件導出到execl、word、pdf時報錯,可使用語句直接從數據庫下提取消耗列表。數據庫