[原創]DebugTools系列(3):AQTime實踐

導讀

通過前兩篇文章，大家應該對AQTime已經有了一定的理論認識了吧！[上一篇]文章最後埋了幾顆地雷在Demo裡面，希望感興趣的同學自己挖挖看！因為對地雷的反饋不多，所以不知道有多少同學真正親自動手實驗了，如果你動手做了希望能告訴我，我會感到非常欣慰的！OK，不管怎麼樣，這次我們就是要示範挖地雷的過程了，有了AQTime這個超級探雷器，其實這是個非常簡單愉快的過程，希望您能樂在其中！
記得留下寶貴意見哦！！！ 原始碼下載： 

首先，我們開啟AQTime，建立一個項目，然後先將Bin目錄中的Justin.UILibrary.dll載入到Modules列表裡，然後我們選擇Profile Entire .NET Code，將項目類型選擇為ASP.NET,然後在Run Parameters裡設定Start Page是http://localhost/Justin/Default.aspx(根據自己環境IIS虛擬目錄的配置而定)，然後我們就可以開始挖雷了！

如所示，這裡有兩個問題(基於[上一篇]文章介紹的配置分析範圍和粒度)，第一個，為什麼在開始沒有設定成狀態？第二個，為什麼我們要使用Profile Entire .NET Code 這個預設的Area？第一個問題的答案是因為我們現在不知道地雷在那裡，所以我們要跟蹤剖析器的整個生命週期；第二個問題的答案是因為我們不明確載入的Module是否足夠，和具體要載入那些Module，所以我們先使用預設的Area設定，剖析器載入的所有Module；其實也可以認為這兩個問題的答案都是因為我們一開始沒有明確的目標，所以我們只能靠“廣撒網多撈魚”的笨方法了。

如所示，當第一次Run的時候，會先後彈出上面三個視窗，你可以完全不去管它們，全部斷行符號過去就行了，當然也可以分別選擇"Don't..."複選框，讓它們下次不會再彈出來。

OK!程式執行起來以後，我們依次分別執行了一遍“類比提交”、“類比瀏覽”、“類比修改”，發現都比較慢，看來效能問題是比較嚴重。全部執行過後，我們通過來收集程式這段生命週期裡的效能資料，可以說這是最完整的整個生命週期的所有操作的分析資料了。

【大圖】

如所示，這次我們收穫頗豐啊！這就是我們用AQTime收集到的Demo的完整生命週期(不包括關閉頁面部分)的效能資料結果了，其中同時包含了所有底層架構(.NET)的方法，所有這些資料我已經打包在下載Demo的壓縮包裡了，這次收集的結果對應壓縮包裡的AQTimeTestJustinDemo_01.aqr檔案，大家可以通過AQTime開啟查看。下面就基於這個結果，開始挖雷了！我們先介紹一下挖雷的最最基本的技巧，那就是清楚地理解Report頁簽裡的Grid中最基本的下面三列表示的意思：

表述的已經非常清楚了，這三列是我們日常使用AQTime剖析器效能問題時，最需要關注的三列(還有很多其他列，沒有這三列實用，不過也不是一點用沒有！)，首先，如果一個方法的執行時間過長，那麼[Time]列的值就會很大，這也是最傻瓜的地雷了，因為已經清楚地告訴你，這個方法執行時間過長，它就是你要找的瓶頸，剩下的就是具體分析這個方法為什麼時間過長，能不能最佳化一下，不能的話請高高手再來看看；其次，如果一個方法中調用了很多子方法，而且它的[Time with Children]列的值很大，那麼要通過[Call Tree]或[Call Graph]頁簽來逐層尋找瓶頸到底發生在那個子方法上，一般使用[Call Tree]可以很容易定位到耗時最多的子方法上，AQtime會自動將耗時最多的節點展開加粗顯示，可以說是非常清晰明了的；最後，如果一個方法是[HitCount]列的值非常大，那麼也要提高警惕了，有可能存在問題，如果是底層基類的方法HitCount次數比較高還比較容易接受，如果是一個自訂比較靠前端的方法，那麼就要檢查一下程式的邏輯，是不是跟預想的一樣，有沒有多執行了幾次迴圈，這些都是完全有可能的事情。

基於前面介紹的基本排雷技巧，如，這是按[Time with Children]倒排後的結果，從上到下我們可以發現，_Default::Page_Load 以前的結果都是底層架構自身的，這部分不在我們排雷的範圍內，因為我們開始收集效能資料時候使用了“廣撒網多撈魚”的笨方法，所以在分析結果的時候就需要靠自己來分離過濾掉底層架構的方法才行了。那麼我們這裡重點分析一下為什麼_Default::Page_Load 這個方法耗時最長，我們通過[Call Tree]展開其子方法，看看瓶頸到底在哪裡：

如所示，通過[Call Tree]，我們已經清楚的看到，耗時最多的是FormLoadUtils::LoadUI和_Default::InitData兩個方法，而且這兩個方法是[Time]本身就很大，所以它們都是傻瓜型地雷(我這次埋的都是傻瓜型的)，OK!既然已經準確定位到了地雷，下面就是該看看地雷裡面有什麼了，是否能動個小手術把這個地雷拆除了呢？

通過Editor頁簽，我們可以直接查看程式的原始碼，而且Editor頁簽的內容還是跟Grid動態同步的，酷！簡直太方便了！如所示，我們可以清楚地看到，在LoadUI方法裡面，最後有一句：“System.Threading.Thread.Sleep(3000);”，是的，就是它，它是地雷2，我們找到它了！哈哈！

同理，如所示，我們很容易找到了地雷3，破壞力都是3秒，呵呵！
哦可！地雷2和地雷3我們都已經找到了，現在我可以透露一下，其實我就埋了3顆地雷，所以我們就差地雷1還沒有找到了！按照上面的方法，仔細分析Grid列表，配合[Call Tree]，應該很快就能發現地雷1的，這個我們就不介紹了。我想說的是，其實聰明的同學早應該會想到，地雷1肯定也同樣是傻瓜型的，而對於傻瓜型地雷，最好的方法是一開始就將Grid按[Time]列倒排，那樣就可以直接暴露傻瓜型地雷的位置了！

如是按[Time]倒排後的結果，果然不出所料，UI::InitPage很明顯地暴露了出來，沒錯，它就是地雷1，通過Editor可以看到，它同樣是一個破壞力為3秒的傻瓜雷！呵呵！
那麼到此為止，我們的地雷就都挖完了，恩，起碼我有意埋下的都挖完了，無意埋下的就不知道還有沒有了！那麼肯定有人聰明地同學要問了，為什麼我們不一開始就使用[Time]倒排呢？這是個好問題，在本文中，作者為了給大家示範Grid和[Call Tree]配合的神奇力量，所以一開始使用了[Time with Children]倒排的方式，其實在實際最佳化程式效能的過程中，用的比較多的也是這種方法，因為一般很少有那麼多傻瓜型地雷可挖的。但是，我這裡想強調的是，任何時候，建議大家都能按照“先[Time]再[Time with Children]最後[HitCount]”的方式來分析定位問題，這樣是最合理，最高效的組合了，比如在這個Demo裡用這個方法，只分析一遍[Time]倒排就搞定了！

最後，再補充一點，關於我們上面用到的“廣撒網多撈魚”的笨方法，這個方法在這個Demo裡很好用，因為畢竟我們的Demo比較小，所以執行起來速度也比較快，收集到的結果資料也不會多得讓人恐怖，但是一般在分析大型項目的時候，我們一般最好是有針對性地分析局部某段生命週期裡的具體功能點，這個時候就需要我們明確載入那些Module,然後把掃雷的範圍縮小，以協助更快更準確地定位瓶頸的位置，具體可以進一步參考[上一篇]所述。那麼以這個Demo來說，就像[第一篇]裡描述的一樣，如果想收集所有我們自訂程式的效能資料，除了需要載入Justin.UILibrary.dll以外，還要載入由ISAPI動態產生的aspx檔案對應的類的DLL，具體請參考第一篇文章所述，那麼這裡我們最後重新設定一下AQTime的Modules，重新收集一遍資料。

如所示，這次我們載入了必要的Module，然後再Area裡設定成“Full Check”選項，只跟蹤分析Modules列表的Module。

【大圖】

如所示，這次收集到的結果比上次清晰了很多(對應壓縮包裡的AQTimeTestJustinDemo_02.aqr檔案)，而且沒有包含任何底層架構的方法，所有收集的資料都是Modules列表裡的Module的範圍內的，這樣我們分析定位問題的時間，就不需要像上面那樣需要靠自己來分離過濾掉底層架構的方法了，是不是清爽了很多啊！配置分析範圍的優點在這個Demo裡並不明顯，因為全生命週期分析下來，這個Demo也沒有多少資料，但是在那種大型的項目裡，掛上AQTime以後，點一下儲存要等半小時的應用中，一開始就很好的控制分析的範圍還是非常關鍵的，否則會收集到很多“垃圾”不說，最恐怖的是有可能等了半天什麼也沒收集到，Why？！：kao！死機了！

總結，這篇文章非常詳細的介紹了使用AQTime在一般情況下的排雷過程，結合前兩篇文章，相信大家現在應該可以使用AQTime熟練地解決一些效能分析的問題了！如果有什麼問題，儘管在此留言，我會儘力解答。這個系列的文章關於AQTime的部分，我可能還會再寫一篇，內容是一些AQTime的Tips，都是實際使用過程中的經驗總結。

-歡迎加入部落格園.Debug探索團隊 Copyright Justin