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

逍遥老汉 發表於 2025-6-25 12:20:00

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

<h2 id="一背景">一：背景</h2>
<h3 id="1-讲故事">1. 讲故事</h3>
写这一篇是因为昨天看 dottrace 官方文档时，在评论区看到了一条不友好的评论，截图如下：
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121918987-1617078350.png" alt="" loading="lazy">
虽然语气上带有些许愤怒，但说实话人家也不是无中生有，作为 dottrace 的忠实粉丝我还是能够理解他的心情的，所以这篇我用最新的 2025.01 版 dottrace 来演示一下，时过境迁有些功能和性能基准虽然已经不一样了。
话不多说我们开始吧。
<h2 id="二程序变卡分析">二：程序变卡分析</h2>
<h3 id="1-现象描述">1. 现象描述</h3>
案例代码是一个窗体程序，它可以将上传文件的内容按行反转，比如说 <code>abcd -> dcba</code>，我准备了一个 1G 的日志文件，在程序运行过程中我发现程序特别吃内存，而且在处理过程中明显发现程序卡卡的，能否帮我分析下到底怎么回事，案例代码可下载：https://github.com/DarthWeirdo/dotTrace_Timeline_Get_Started
上面的项目下载好之后，一定要改成 x64 位的，运行之后截图如下：
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121918997-1229713910.png" alt="" loading="lazy">
因果论中的 <code>果</code>，现在我们知道了，接下来就是<code>由果推因</code>，那怎么推呢？使用 dotTrace 哈。
<h3 id="2-dottrace-分析">2. dotTrace 分析</h3>
使用 timeline 模式对 MassFileProcessing 程序进行性能数据收集，最后的性能图表如下：
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121919024-678139461.png" alt="" loading="lazy">
这里面有几个概念要解释：
<ol>
<li>UI Freeze</li>
</ol>
简而言之就是如果 UI 超过 200ms 都不响应用户，就属于 <code>Freeze</code>，可能有些朋友比较懵，上一段代码参考如下：
<pre><code class="language-C#">
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;
}

</code></pre>
这里的 Freeze 原因有很多，常见的有如下三种：
<ul>
<li>由于queue队列积压，导致用户投送过来的消息，GetMessage 在 200ms 内无法及时取到。</li>
<li>由于用户投送过来的是长耗时任务，导致 DispatchMessage 在 200ms 内无法处理完。</li>
<li>由于gc触发，导致 UI 被 Suspend >200 ms。</li>
</ul>
再回头观察上面的面板，可以看到冻结时间高达 <code>UI Freeze =11.4s</code>。
<ol start="2">
<li>子模块条状时间分布</li>
</ol>
从<code>条状图</code>上可以看到，11s 的时间主要被 <code>GCWait</code> 和 <code>WPF</code> 这块吃掉了，前者占比50%，后者占比43%，接下来稍微解释下这两个词的概念:
<ul>
<li>GCWait 当前线程等待其他线程GC操作完成而处于的一种等待状态，比如下面的截图：</li>
</ul>
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121919002-2121555970.png" alt="" loading="lazy">
<ul>
<li>WPF UI处理相关的业务逻辑，比如UI更新等等。</li>
</ul>
接下来我们就要逐个分析这两块了。
<h3 id="3-为什么gc-wait-高达-50">3. 为什么GC Wait 高达 50%</h3>
观察 Main 时间轴上可以看到有很多间断的 <code>灰色区域</code>，这些灰色区域即是所谓的暂停(GC wait)，截图如下：
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121918984-1462688326.png" alt="" loading="lazy">
根据CLR的相关知识，只有两种原因会导致 GC Wait 产生。
<ul>
<li>完整的 blocking GC，即著名的 STW 机制。</li>
<li>background gc 三阶段中的 blocking 阶段，这块我的训练营里说的很细。</li>
</ul>
有了这个思路，接下来就是观察到底是哪个线程触发的，在 <code>Visible Threads</code> 中按需选择线程，这里我就勾上 <code>CLR Worker</code>和 <code>Garbage Collection</code> 线程，这里稍微提一下，2025版的 dottrace 新增了多tab页模式，这个太方便了，现在我可以多tab分析了，因为我用windbg 的时候也是这么玩的，非常利于分析加速，截图如下：
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121918997-218498979.png" alt="" loading="lazy">
<code>Gargage Collection</code> 和 <code>CLR Worker</code> 都出来后，缩小时间轴，宏观的观测下Main灰色和其他线程的深蓝色，截图如下：
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121919023-1557878480.png" alt="" loading="lazy">
从卦中可以清晰的看到很多的Main阻塞看起来是 <code>CLR Worker</code> 触发GC导致的，那是不是的呢？观察一下便知哈，将时间轴稍微调整下，选择 <code>Flame Graph</code> 火焰图，从中就有 <code>plan_phase</code>，这是GC三阶段中经典的计划阶段，截图如下：
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121919024-344862005.png" alt="" loading="lazy">
接下来就要思考了，为什么会触发那么多次GC，这些GC是大GC还是小GC呢？要调查这个原因，可以单独勾选 <code>CLR Worker</code> 线程，可以看到如下信息：阻塞式GC高达 <code>92.7%</code> 同时 1代GC 高达 <code>71.7%</code>，截图如下：
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121918970-638505328.png" alt="" loading="lazy">
根据dump分析经验，看样子 UI 卡卡的和过频的GC有关。GC触发本质是要到gc堆上捞垃圾，所以肯定有人在不断的丢垃圾，所以从这个角度继续突破，选择 <code>.NET Memory Allocation</code> 事件，然后观察 hotspots 区域，可以看到总计 12G 的内存分配，<code>Reverse</code>方法就独吞 4.9G，说明还是非常吃内存的，截图如下：
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121919010-782275370.png" alt="" loading="lazy">
点击源代码观察，参考如下：
<pre><code class="language-C#">
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);
 }
}

</code></pre>
从卦中可以看到这块会产生很多的临时 char[] 和 string 对象，在1G日志的加持下导致GC频繁触发，在后续版本优化中这块是一个非常重要的点，可能你需要用 ArrayPool 或者 Span 等机制来减少临时对象的过多产生。
<h3 id="4-为什么-wpf-高达-42">4. 为什么 WPF 高达 42%</h3>
WPF占比过高其实也意味着更新UI的操作比较频繁，这种情况也会导致程序在响应UI方面会有所延迟，那到底是谁在频繁的更新 UI呢？
可以勾选上 <code>Running , WPF</code> 等选项，然后观察 <code>火焰图</code>，截图如下：
<img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250625121918985-1512549739.png" alt="" loading="lazy">
从卦中的火焰图中的 <code>Dispatcher.ProcessQueue()</code> 方法可以判断当前真的是频繁的更新UI，因为WPF在忙碌的处理队列，而它的发起者正是 <code>ProcessInProgress</code> 方法，观察方法的源码，参考如下：
<pre><code class="language-C#">
 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;
 _lines = File.ReadAllLines(path);

 for (var j = 0; j < _lines.Length; j++)
 {
 var line = _lines;
 var stringReverser = new StringReverser(line);
 _lines = 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());
 }
 }
</code></pre>
从卦中代码可以看到，原来 <code>if (j % 5 == 0)</code> 就会通过 <code>Worker.ReportProgress((int)p, _updater);</code> 报告进度进而触发 ProcessInProgress 方法。
找到问题之后，优化就相对简单了，将 <code>if (j % 5 == 0)</code> 5 改成更大一些即可，比如 1000，5000。
<h2 id="三总结">三：总结</h2>
用 dottrace 分析这类程序变慢的问题，真的再适合不过，这篇文章主要还是对那个不友好评论的回应和修正吧。
<blockquote>
作为JetBrains社区内容合作者，如有购买jetbrains的产品，可以用我的折扣码 HUANGXINCHENG，有25%的内部优惠哦。
</blockquote>
<img src="https://images.cnblogs.com/cnblogs_com/huangxincheng/345039/o_210929020104最新消息优惠促销公众号关注二维码.jpg" width="700" height="300" alt="图片名称" align="center"> 
来源：https://www.cnblogs.com/huangxincheng/p/18947774

頁: [1]

琼殿技术论坛's Archiver

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