DotTrace系列：4. 诊断窗体程序变卡之原因分析

2025年6月25日
| 没有评论

一：背景

1. 讲故事

写这一篇是因为昨天看 dottrace 官方文档时，在评论区看到了一条不友好的评论，截图如下：

虽然语气上带有些许愤怒，但说实话人家也不是无中生有，作为 dottrace 的忠实粉丝我还是能够理解他的心情的，所以这篇我用最新的 2025.01 版 dottrace 来演示一下，时过境迁有些功能和性能基准虽然已经不一样了。

话不多说我们开始吧。

二：程序变卡分析

1. 现象描述

案例代码是一个窗体程序，它可以将上传文件的内容按行反转，比如说 abcd -> dcba，我准备了一个 1G 的日志文件，在程序运行过程中我发现程序特别吃内存，而且在处理过程中明显发现程序卡卡的，能否帮我分析下到底怎么回事，案例代码可下载：https://github.com/DarthWeirdo/dotTrace_Timeline_Get_Started

上面的项目下载好之后，一定要改成 x64 位的，运行之后截图如下：

因果论中的 果，现在我们知道了，接下来就是由果推因，那怎么推呢？使用 dotTrace 哈。

2. dotTrace 分析

使用 timeline 模式对 MassFileProcessing 程序进行性能数据收集，最后的性能图表如下：

这里面有几个概念要解释：

  1. 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。

  1. 子模块条状时间分布

从条状图上可以看到，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%的内部优惠哦。

.net, abp