PerfView專題 (第十五篇)：如何洞察 C# 中的慢速方法

一：背景

1. 講故事

在 dump 分析旅程中，經常會遇到很多朋友反饋一類問題，比如：

方法平時都執行的特別快，但有時候會特別慢，怎麼排查？
我的方法第一次執行特別慢，能看到慢在哪裡嗎？

相信有朋友肯定說，加些紀錄檔不就好了，大方向肯定是沒問題的，但加紀錄檔的顆粒度會比較粗而且侵入性也比較大，比如說這個方法不是你的，或者說這個方法是作業系統的，一般情況下對他們無法干涉，那如何洞察在你作用域之外的方法效能呢？作為 CLR團隊首推的 PerfView 效能分析工具，必須要 KO 這些問題，接下來我們就簡單聊一聊。

二：PerfView 洞察慢速方法

1. 測試程式碼

為了方便講述，我們模擬這樣的一種情況，一個方法第一次執行會特別慢（5s），後面執行都很快(3s)，測試程式碼如下：


    internal class Program
    {
        static void Main(string[] args)
        {
            mytest1(5000);

            for (int i = 0; i < int.MaxValue; i++) { };
            
            mytest1(3000);

            Console.ReadLine();
        }

        static void mytest1(int senconds)
        {
            Console.WriteLine("mytest1 start...");
            Thread.Sleep(senconds);
            Console.WriteLine("mytest1 end...");
        }
    }

那如何用 perfview 來洞察呢？玩過 perfview 的朋友都知道它是帶時間軸的，我們可以對上面的慢速方法 mytest1 適當的放大，一直找到那一次的慢速呼叫，為了能夠記錄到 Thread 使用 CPU 的情況，需要開啟 ThreadTime 選項，截圖如下：

完整的 Command 命令如下：


PerfView.exe  "/DataFile:PerfViewData.etl" /BufferSizeMB:256 /StackCompression /CircularMB:500 /KernelEvents:ThreadTime /ClrEvents:GC,Binder,Security,AppDomainResourceManagement,Contention,Exception,Threading,JITSymbols,Type,GCHeapSurvivalAndMovement,GCHeapAndTypeNames,Stack,ThreadTransfer,Codesymbols,Compilation /NoGui /NoNGenRundown /Merge:True /Zip:True collect

有了這些基礎之後，先用 perfview 開啟收集，然後執行應用程式，程式執行完成之後停止 perfview 收集，稍等片刻之後就有一個生成好的 zip 檔案。

2. perfview 洞察

這裡選擇 Thread Time Stacks 檢視，在彈框中選擇我們的應用程式 ConsoleApp2，截圖如下：

從卦象上看，當前的 ConsoleApp2 耗費了 3.2s 的CPU時間，總跟蹤時間 17.19s。

既然說了方法慢那必然是知道方法名的，只不過不知道慢在方法哪裡，對應程式碼就是 mytest1() 方法，在 perfview 面板的 Find 輸入框上搜尋一下 mytest1 方法就可以找到，截圖如下：

那這一行怎麼解讀呢？我稍微說一下吧。

First：表示 mytest1 第一次被呼叫的時間戳
Last: 表示 myttest1 最後一次被釋放的時間戳
when：這裡面是 32 個時間間隔的桶，每個桶的值是資源消化的比重。
TimeBucket: 一個桶的時間刻度，比如上圖中的 633.8 ms

有了這些基礎接下來就可以放大時間軸了，依次點選： First列 -> 右鍵選單 -> Set Time Range ，放大後的截圖如下：

從 When 列的 999999999999992________599999999 可以看到，當前這 11s 的掛鐘時間內大概有兩次 mytest1 呼叫，其實的 9 表示這個桶內消耗的單個資源的90%，我們要調查的就是其中 999999999999992 段，雙擊 When 列的 999999999999992 ，右鍵選擇 Set Time Range 即可，截圖如下：

放大到這裡就差不多了，我們已經進入了第一次 mytest1 方法呼叫的作用域內，接下來依次點選 右鍵 -> Goto -> Goto Item in Callee 來觀察下這個方法的下層到底都是寫什麼。

從卦中的 Inc 列來看，當前的 mytest1 方法耗費了 5.01s，其內部的 Thread.Sleep() 耗費了 5.005s ，這和測試程式碼中的 mytest1(5000); 不約而同。

哈哈，這不就找到了問題所在，在你的真實場景下，你可以繼續觀察底層的呼叫棧，找到問題所在。

三：總結

相信這篇能夠給一些在慢速方法查詢上有困惑的朋友找到一些靈感，還是那句話，CLR團隊首推的 PerfView 在執行期監控方面是王者般的存在，與 WinDbg 優勢互補。