登录/ 注册
 找回密码
 立即注册
关闭

CSDN热搜

程序园 精品问答 技术交流 资源下载
返回列表 发新帖
首页 › 业界区 › 业界 ›DotTrace系列：4. 诊断窗体程序变卡之原因分析 ...

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

陶田田 2025-6-25 10:34:03
一：背景

1. 讲故事

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

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

1. 现象描述

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

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

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

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

  • UI Freeze
简而言之就是如果 UI 超过 200ms 都不响应用户，就属于 Freeze，可能有些朋友比较懵，上一段代码参考如下：
  1. int APIENTRY wWinMain(_In_ HINSTANCE hInstance,
  2.                      _In_opt_ HINSTANCE hPrevInstance,
  3.                      _In_ LPWSTR    lpCmdLine,
  4.                      _In_ int       nCmdShow)
  5. {
  6.     MSG msg;
  8.     // Main message loop:
  9.     while (GetMessage(&msg, nullptr, 0, 0))
  10.     {
  11.         if (!TranslateAccelerator(msg.hwnd, hAccelTable, &msg))
  12.         {
  13.             TranslateMessage(&msg);
  14.             DispatchMessage(&msg);
  15.         }
  16.     }
  18.     return (int) msg.wParam;
  19. }
复制代码
这里的 Freeze 原因有很多，常见的有如下三种：

  • 由于queue队列积压，导致用户投送过来的消息，GetMessage 在 200ms 内无法及时取到。
  • 由于用户投送过来的是长耗时任务，导致 DispatchMessage 在 200ms 内无法处理完。
  • 由于gc触发，导致 UI 被 Suspend >200 ms。
再回头观察上面的面板，可以看到冻结时间高达 UI Freeze =11.4s。

  • 子模块条状时间分布
从条状图上可以看到，11s 的时间主要被 GCWait 和 WPF 这块吃掉了，前者占比50%，后者占比43%，接下来稍微解释下这两个词的概念:

  • GCWait 当前线程等待其他线程GC操作完成而处于的一种等待状态，比如下面的截图：
4.png


  • WPF UI处理相关的业务逻辑，比如UI更新等等。
接下来我们就要逐个分析这两块了。
3. 为什么GC Wait 高达 50%

观察 Main 时间轴上可以看到有很多间断的 灰色区域，这些灰色区域即是所谓的暂停(GC wait)，截图如下：
5.png

根据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灰色和其他线程的深蓝色，截图如下：
7.png

从卦中可以清晰的看到很多的Main阻塞看起来是 CLR Worker 触发GC导致的，那是不是的呢？观察一下便知哈，将时间轴稍微调整下，选择 Flame Graph 火焰图，从中就有 plan_phase，这是GC三阶段中经典的 计划阶段，截图如下：
8.png

接下来就要思考了，为什么会触发那么多次GC，这些GC是大GC还是小GC呢？要调查这个原因，可以单独勾选 CLR Worker 线程，可以看到如下信息：阻塞式GC高达 92.7% 同时 1代GC 高达 71.7%，截图如下：
9.png

根据dump分析经验，看样子 UI 卡卡的和过频的GC有关。GC触发本质是要到gc堆上捞垃圾，所以肯定有人在不断的丢垃圾，所以从这个角度继续突破，选择 .NET Memory Allocation 事件，然后观察 hotspots 区域，可以看到 总计 12G 的内存分配，Reverse方法就独吞 4.9G，说明还是非常吃内存的，截图如下：
10.png

点击源代码观察，参考如下：
  1.     internal class StringReverser
  2.     {
  3.         private readonly string _original;
  5.         public StringReverser(string original)
  6.         {
  7.             _original = original;
  8.         }
  10.         public string Reverse()
  11.         {
  12.             char[] charArray = _original.ToCharArray();
  13.             Array.Reverse(charArray);
  14.             return new string(charArray);
  15.         }
  16.     }
复制代码
从卦中可以看到这块会产生很多的临时 char[] 和 string 对象，在1G日志的加持下导致GC频繁触发，在后续版本优化中这块是一个非常重要的点，可能你需要用 ArrayPool 或者 Span 等机制来减少临时对象的过多产生。
4. 为什么 WPF 高达 42%

WPF占比过高其实也意味着更新UI的操作比较频繁，这种情况也会导致程序在响应UI方面会有所延迟，那到底是谁在频繁的更新 UI呢？
可以勾选上 Running , WPF 等选项，然后观察 火焰图，截图如下：
11.png

从卦中的火焰图中的 Dispatcher.ProcessQueue() 方法可以判断当前真的是频繁的更新UI，因为WPF在忙碌的处理队列，而它的发起者正是 ProcessInProgress 方法，观察方法的源码，参考如下：
  1.         private void ProcessInProgress(object sender, ProgressChangedEventArgs e)
  2.         {
  3.             var upd = (ProgressUpdater)e.UserState;
  4.             lblProgress.Content = $"File {upd.CurrentFileNmb} of {upd.TotalFiles}: {e.ProgressPercentage}%";
  5.         }
  7.         private void ProcessFiles(object sender, DoWorkEventArgs evts)
  8.         {
  9.             try
  10.             {
  11.                 _updater.TotalFiles = FilePaths.Count;
  13.                 for (var i = 0; i < FilePaths.Count; i++)
  14.                 {
  15.                     EmKeyPress();
  17.                     _updater.CurrentFileNmb = i + 1;
  19.                     var path = FilePaths[i];
  20.                     _lines = File.ReadAllLines(path);
  22.                     for (var j = 0; j < _lines.Length; j++)
  23.                     {
  24.                         var line = _lines[j];
  25.                         var stringReverser = new StringReverser(line);
  26.                         _lines[j] = stringReverser.Reverse();
  28.                         if (j % 5 == 0)
  29.                         {
  30.                             var p = (float)(j + 1) / _lines.Length * 100;
  31.                             Worker.ReportProgress((int)p, _updater);
  32.                         }
  33.                     }
  35.                     File.WriteAllLines(path, _lines);
  36.                 }
  37.             }
  38.             catch (Exception e)
  39.             {
  40.                 MessageBox.Show(e.ToString());
  41.             }
  42.         }
复制代码
从卦中代码可以看到，原来 if (j % 5 == 0) 就会通过 Worker.ReportProgress((int)p, _updater); 报告进度进而触发 ProcessInProgress 方法。
找到问题之后，优化就相对简单了，将 if (j % 5 == 0) 5 改成更大一些即可，比如 1000，5000。
三：总结

用 dottrace 分析这类程序变慢的问题，真的再适合不过，这篇文章主要还是对那个不友好评论的回应和修正吧。
作为JetBrains社区内容合作者，如有购买jetbrains的产品，可以用我的折扣码 HUANGXINCHENG，有25%的内部优惠哦。
12.jpg

来源：程序园用户自行投稿发布，如果侵权，请联系站长删除
免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！
DotTrace系列DotTrace

使用道具 举报
B Color Image Link Quote Code Smilies
您需要登录后才可以回帖 登录 | 立即注册
发帖
陶田田
2025-6-25 10:34:03

0

粉丝关注

16

主题发布

板块介绍填写区域，请于后台编辑
微信扫一扫