DotTrace系列：4. 診斷窗體程序變卡之原因分析

一：背景

1. 講故事

寫這一篇是因為昨天看 dottrace 官方文檔時，在評論區看到了一條不友好的評論，截圖如下：

雖然語氣上帶有些許憤怒，但說實話人家也不是無中生有，作為 dottrace 的忠實粉絲我還是能夠理解他的心情的，所以這篇我用最新的 2025.01 版 dottrace 來演示一下，時過境遷有些功能和性能基準雖然已經不一樣了。

話不多說我們開始吧。

二：程序變卡分析

1. 現象描述

案例代碼是一個窗體程序，它可以將上傳文件的內容按行反轉，比如說 abcd -> dcba，我準備了一個 1G 的日志文件，在程序運行過程中我發現程序特別吃內存，而且在處理過程中明顯發現程序卡卡的，能否幫我分析下到底怎么回事，案例代碼可下載：https://github.com/DarthWeirdo/dotTrace_Timeline_Get_Started

上面的項目下載好之后，一定要改成 x64 位的，運行之后截圖如下：

因果論中的 果，現在我們知道了，接下來就是由果推因，那怎么推呢？使用 dotTrace 哈。

2. dotTrace 分析

使用 timeline 模式對 MassFileProcessing 程序進行性能數據收集，最后的性能圖表如下：

這里面有幾個概念要解釋：

UI Freeze

簡而言之就是如果 UI 超過 200ms 都不響應用戶，就屬于 Freeze，可能有些朋友比較懵，上一段代碼參考如下：


int APIENTRY wWinMain(_In_ HINSTANCE hInstance,
                     _In_opt_ HINSTANCE hPrevInstance,
                     _In_ LPWSTR    lpCmdLine,
                     _In_ int       nCmdShow)
{
    MSG msg;

    // Main message loop:
    while (GetMessage(&msg, nullptr, 0, 0))
    {
        if (!TranslateAccelerator(msg.hwnd, hAccelTable, &msg))
        {
            TranslateMessage(&msg);
            DispatchMessage(&msg);
        }
    }

    return (int) msg.wParam;
}

這里的 Freeze 原因有很多，常見的有如下三種：

由于queue隊列積壓，導致用戶投送過來的消息，GetMessage 在 200ms 內無法及時取到。
由于用戶投送過來的是長耗時任務，導致 DispatchMessage 在 200ms 內無法處理完。
由于gc觸發，導致 UI 被 Suspend >200 ms。

再回頭觀察上面的面板，可以看到凍結時間高達 UI Freeze =11.4s。

子模塊條狀時間分布

從條狀圖上可以看到，11s 的時間主要被 GCWait 和 WPF 這塊吃掉了，前者占比50%，后者占比43%，接下來稍微解釋下這兩個詞的概念:

GCWait 當前線程等待其他線程GC操作完成而處于的一種等待狀態，比如下面的截圖：

WPF UI處理相關的業務邏輯，比如UI更新等等。

接下來我們就要逐個分析這兩塊了。

3. 為什么GC Wait 高達 50%

觀察 Main 時間軸上可以看到有很多間斷的 灰色區域，這些灰色區域即是所謂的暫停(GC wait)，截圖如下：

根據CLR的相關知識，只有兩種原因會導致 GC Wait 產生。

完整的 blocking GC，即著名的 STW 機制。
background gc 三階段中的 blocking 階段，這塊我的訓練營里說的很細。

有了這個思路，接下來就是觀察到底是哪個線程觸發的，在 Visible Threads 中按需選擇線程，這里我就勾上 CLR Worker和 Garbage Collection 線程，這里稍微提一下，2025版的 dottrace 新增了多tab頁模式，這個太方便了，現在我可以多tab分析了，因為我用windbg 的時候也是這么玩的，非常利于分析加速，截圖如下：

Gargage Collection 和 CLR Worker 都出來后，縮小時間軸，宏觀的觀測下Main灰色和其他線程的深藍色，截圖如下：

從卦中可以清晰的看到很多的Main阻塞看起來是 CLR Worker 觸發GC導致的，那是不是的呢？觀察一下便知哈，將時間軸稍微調整下，選擇 Flame Graph 火焰圖，從中就有 plan_phase，這是GC三階段中經典的計劃階段，截圖如下：

接下來就要思考了，為什么會觸發那么多次GC，這些GC是大GC還是小GC呢？要調查這個原因，可以單獨勾選 CLR Worker 線程，可以看到如下信息：阻塞式GC高達 92.7% 同時 1代GC 高達 71.7%，截圖如下：

根據dump分析經驗，看樣子 UI 卡卡的和過頻的GC有關。GC觸發本質是要到gc堆上撈垃圾，所以肯定有人在不斷的丟垃圾，所以從這個角度繼續突破，選擇 .NET Memory Allocation 事件，然后觀察 hotspots 區域，可以看到總計 12G 的內存分配，Reverse方法就獨吞 4.9G，說明還是非常吃內存的，截圖如下：

點擊源代碼觀察，參考如下：


    internal class StringReverser
    {
        private readonly string _original;

        public StringReverser(string original)
        {
            _original = original;
        }

        public string Reverse()
        {
            char[] charArray = _original.ToCharArray();
            Array.Reverse(charArray);
            return new string(charArray);
        }
    }

從卦中可以看到這塊會產生很多的臨時 char[] 和 string 對象，在1G日志的加持下導致GC頻繁觸發，在后續版本優化中這塊是一個非常重要的點，可能你需要用 ArrayPool 或者 Span 等機制來減少臨時對象的過多產生。

4. 為什么 WPF 高達 42%

WPF占比過高其實也意味著更新UI的操作比較頻繁，這種情況也會導致程序在響應UI方面會有所延遲，那到底是誰在頻繁的更新 UI呢？

可以勾選上 Running , WPF 等選項，然后觀察 火焰圖，截圖如下：

從卦中的火焰圖中的 Dispatcher.ProcessQueue() 方法可以判斷當前真的是頻繁的更新UI，因為WPF在忙碌的處理隊列，而它的發起者正是 ProcessInProgress 方法，觀察方法的源碼，參考如下：


        private void ProcessInProgress(object sender, ProgressChangedEventArgs e)
        {
            var upd = (ProgressUpdater)e.UserState;
            lblProgress.Content = $"File {upd.CurrentFileNmb} of {upd.TotalFiles}: {e.ProgressPercentage}%";
        }

        private void ProcessFiles(object sender, DoWorkEventArgs evts)
        {
            try
            {
                _updater.TotalFiles = FilePaths.Count;

                for (var i = 0; i < FilePaths.Count; i++)
                {
                    EmKeyPress();

                    _updater.CurrentFileNmb = i + 1;

                    var path = FilePaths[i];
                    _lines = File.ReadAllLines(path);

                    for (var j = 0; j < _lines.Length; j++)
                    {
                        var line = _lines[j];
                        var stringReverser = new StringReverser(line);
                        _lines[j] = stringReverser.Reverse();

                        if (j % 5 == 0)
                        {
                            var p = (float)(j + 1) / _lines.Length * 100;
                            Worker.ReportProgress((int)p, _updater);
                        }
                    }

                    File.WriteAllLines(path, _lines);
                }
            }
            catch (Exception e)
            {
                MessageBox.Show(e.ToString());
            }
        }

從卦中代碼可以看到，原來 if (j % 5 == 0) 就會通過 Worker.ReportProgress((int)p, _updater); 報告進度進而觸發 ProcessInProgress 方法。

找到問題之后，優化就相對簡單了，將 if (j % 5 == 0) 5 改成更大一些即可，比如 1000，5000。

三：總結

用 dottrace 分析這類程序變慢的問題，真的再適合不過，這篇文章主要還是對那個不友好評論的回應和修正吧。

作為JetBrains社區內容合作者，如有購買jetbrains的產品，可以用我的折扣碼 HUANGXINCHENG，有25%的內部優惠哦。

posted @ 2025-06-25 12:20 一線碼農閱讀(523) 評論(3) 收藏舉報

刷新頁面返回頂部