DotTrace系列：6. 程序异常诊断 和 Request慢处理
<h2 id="一背景">一：背景</h2><h3 id="1-讲故事">1. 讲故事</h3>
<p>在我分析的众多dump中，有一些CPU爆高是因为高频的抛 Exception 导致，比如下面这张图，有 19 个线程都在抛 <code>xxxResultException</code> 异常。</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250628101536491-280021888.png" alt="" loading="lazy"></p>
<p>从卦中虽知大量异常的痕迹，但从严谨的角度来说，最好再卜一卦，就是用 perfview 或者 dottrace 在 cpu 爆高的时段记录下异常的数量，这样就稳了，这篇我们就来解决这个棘手的问题。</p>
<h2 id="二异常诊断-和-request慢处理">二：异常诊断 和 Request慢处理</h2>
<h3 id="1-程序异常诊断">1. 程序异常诊断</h3>
<p>有一个项目平时CPU的利用率都是几个点，突然在某段时间CPU明显升高，高达20多个点，我想知道此时程序在干什么？截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250628101536473-3272325.png" alt="" loading="lazy"></p>
<p>这种问题除了抓dump，还有一个轻量级的途径就是用 dottrace，开启 timeline 模式跟踪，收集一段时间之后，打开跟踪文件。</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250628101536501-1938288261.png" alt="" loading="lazy"></p>
<p>从卦中可以看出如下信息：</p>
<ul>
<li>大量的线程池线程正在 Running （灰蓝色）</li>
<li>Exceptions 事件个数高达 341w。</li>
<li>产生异常最多的是 ThrowHighFrequencyException 方法。</li>
<li>追踪周期仅为 15s</li>
</ul>
<p>以上四个信息就能非常确认，程序的CPU爆高就是因为<code>大量抛出异常</code>所致，接下来选择Filters面板中的 <code>Exceptions</code> 进行下钻观察 <code>异常类型</code> 和 <code>异常消息</code> 的分布，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250628101536479-132361065.png" alt="" loading="lazy"></p>
<p>从卦中可以看到 <code>InvalidOperationException</code> 异常抛的是最多的，高达 <code>273w</code>，并且还是定位在 ThrowHighFrequencyException 方中，接下来对父子方法 <code>Show Code</code>，代码参考如下：</p>
<pre><code class="language-C#">
private static void WorkerThreadProc()
{
Random random = new Random(Thread.CurrentThread.ManagedThreadId);
while (running)
{
try
{
// 80%概率抛出高频异常，20%概率抛出其他异常
if (random.Next(100) < 80)
{
ThrowHighFrequencyException();
}
else
{
ThrowLowFrequencyException(random);
}
}
catch (InvalidOperationException)
{
Interlocked.Increment(ref highFrequencyExceptions);
Interlocked.Increment(ref totalExceptions);
}
catch
{
Interlocked.Increment(ref totalExceptions);
}
}
}
// 高频异常方法
private static void ThrowHighFrequencyException()
{
throw new InvalidOperationException("高频异常：无效操作");
}
</code></pre>
<p>到此问题真相大白，有些朋友可能想知道每个异常发生的<code>时点</code>，这就需要你放大 <code>时间轴</code> 了哈，图中的黑色便是。</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250628101536475-1977053177.png" alt="" loading="lazy"></p>
<p>还有一种方式就是打开 Event 面板 <code>View -> Events</code>，然后观察左侧的偏移时间(Timestamp)，非常清楚加明细，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250628101536494-320013680.png" alt="" loading="lazy"></p>
<h3 id="2-request慢处理">2. Request慢处理</h3>
<p>在给web程序做性能优化时，经常要做的一件事情就是查找<code>慢请求</code>，这也是 dotrace 的强项，它用一个 <code>Incoming HTTP Requests</code> 提供了独家支持，刚好手里有一个 dtp 文件，直接打开。</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250628101536457-1074135074.png" alt="" loading="lazy"></p>
<p>从卦中可以看到当前程序涉及到的 http 请求总时间为 <code>12s</code>，那 12s 都被哪些request 请求分摊着呢？ 继续下钻即可，选择 <code>Incoming HTTP Requests</code>，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250628101536487-654715060.png" alt="" loading="lazy"></p>
<p>从卦中可以看到当前 <code>WeatherForecast/slow-random</code> 累计时间是最高的，其次是 <code>WeatherForecast/slow-fixed</code>，这里有一个误区，累计时间最高不见得单次时间就高，这是一个很显然的道理。</p>
<p>接下来观察下 <code>WeatherForecast/slow-random</code> 请求的分布情况，观察时间轴可知有两次请求，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250628101536492-122159087.png" alt="" loading="lazy"></p>
<p>接下来的问题是这两个请求来自于哪两个方法呢？选中一个时间稍微长的，放大时间轴之后，点击 <code>Plain List</code> 观察 Total Time 最高的一列即可，截图如下：</p>
<p><img src="https://img2024.cnblogs.com/blog/214741/202506/214741-20250628101536455-1999199130.png" alt="" loading="lazy"></p>
<p>最后就是 Show Code 观察 <code>GetWithRandomDelay</code> 方法的源代码，参考如下：</p>
<pre><code class="language-C#">
// 2. 随机慢速接口 - 延迟2-5秒随机
public async Task<IEnumerable<WeatherForecast>> GetWithRandomDelay()
{
// 随机等待2-5秒
var delay = Random.Shared.Next(2000, 5000);
await Task.Delay(delay);
return GenerateRandomForecasts(5);
}
// 辅助方法：生成随机天气预报数据
private IEnumerable<WeatherForecast> GenerateRandomForecasts(int count)
{
return Enumerable.Range(1, count).Select(index => new WeatherForecast
{
Date = DateOnly.FromDateTime(DateTime.Now.AddDays(index)),
TemperatureC = Random.Shared.Next(-20, 55),
Summary = Summaries
});
}
</code></pre>
<p>当然其他接口的调查也可以参考同样的方式。</p>
<h2 id="三总结">三：总结</h2>
<p>dotrace 非常强大，在观测 <code>异常</code> 和 <code>慢Request</code> 处理方面表现优秀，作为一位 <code>.NET高级调试分析师</code> ，这款工具不可或缺！</p>
<blockquote>
<p>作为JetBrains社区内容合作者，如有购买jetbrains的产品，可以用我的折扣码 HUANGXINCHENG，有25%的内部优惠哦。</p>
</blockquote>
<img src="https://images.cnblogs.com/cnblogs_com/huangxincheng/345039/o_210929020104最新消息优惠促销公众号关注二维码.jpg" width="700" height="300" alt="图片名称" align="center"><br><br>
来源：https://www.cnblogs.com/huangxincheng/p/18953339
頁:
[1]