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

CSDN热搜

程序园 精品问答 技术交流 资源下载
返回列表 发新帖
首页 › 业界区 › 业界 ›DotTrace系列：6. 程序异常诊断 和 Request慢处理 ...

DotTrace系列：6. 程序异常诊断 和 Request慢处理

皮仪芳 2025-6-28 08:40:16
一：背景

1. 讲故事

在我分析的众多dump中，有一些CPU爆高是因为高频的抛 Exception 导致，比如下面这张图，有 19 个线程都在抛 xxxResultException 异常。
1.png

从卦中虽知大量异常的痕迹，但从严谨的角度来说，最好再卜一卦，就是用 perfview 或者 dottrace 在 cpu 爆高的时段记录下异常的数量，这样就稳了，这篇我们就来解决这个棘手的问题。
二：异常诊断 和 Request慢处理

1. 程序异常诊断

有一个项目平时CPU的利用率都是几个点，突然在某段时间CPU明显升高，高达20多个点，我想知道此时程序在干什么？截图如下：
2.png

这种问题除了抓dump，还有一个轻量级的途径就是用 dottrace，开启 timeline 模式跟踪，收集一段时间之后，打开跟踪文件。
3.png

从卦中可以看出如下信息：

  • 大量的线程池线程正在 Running （灰蓝色）
  • Exceptions 事件个数高达 341w。
  • 产生异常最多的是 ThrowHighFrequencyException 方法。
  • 追踪周期仅为 15s
以上四个信息就能非常确认，程序的CPU爆高就是因为大量抛出异常所致，接下来选择Filters面板中的 Exceptions 进行下钻观察 异常类型 和 异常消息 的分布，截图如下：
4.png

从卦中可以看到 InvalidOperationException 异常抛的是最多的，高达 273w，并且还是定位在 ThrowHighFrequencyException 方中，接下来对父子方法 Show Code，代码参考如下：
  1.     private static void WorkerThreadProc()
  2.     {
  3.         Random random = new Random(Thread.CurrentThread.ManagedThreadId);
  5.         while (running)
  6.         {
  7.             try
  8.             {
  9.                 // 80%概率抛出高频异常，20%概率抛出其他异常
  10.                 if (random.Next(100) < 80)
  11.                 {
  12.                     ThrowHighFrequencyException();
  13.                 }
  14.                 else
  15.                 {
  16.                     ThrowLowFrequencyException(random);
  17.                 }
  18.             }
  19.             catch (InvalidOperationException)
  20.             {
  21.                 Interlocked.Increment(ref highFrequencyExceptions);
  22.                 Interlocked.Increment(ref totalExceptions);
  23.             }
  24.             catch
  25.             {
  26.                 Interlocked.Increment(ref totalExceptions);
  27.             }
  28.         }
  29.     }
  31.     // 高频异常方法
  32.     private static void ThrowHighFrequencyException()
  33.     {
  34.         throw new InvalidOperationException("高频异常：无效操作");
  35.     }
复制代码
到此问题真相大白，有些朋友可能想知道每个异常发生的时点，这就需要你放大 时间轴 了哈，图中的黑色便是。
5.png

还有一种方式就是打开 Event 面板 View -> Events，然后观察左侧的偏移时间(Timestamp)，非常清楚加明细，截图如下：
6.png

2. Request慢处理

在给web程序做性能优化时，经常要做的一件事情就是查找慢请求，这也是 dotrace 的强项，它用一个 Incoming HTTP Requests 提供了独家支持，刚好手里有一个 dtp 文件，直接打开。
7.png

从卦中可以看到当前程序涉及到的 http 请求总时间为 12s，那 12s 都被哪些request 请求分摊着呢？ 继续下钻即可，选择 Incoming HTTP Requests，截图如下：
8.png

从卦中可以看到当前 WeatherForecast/slow-random 累计时间是最高的，其次是 WeatherForecast/slow-fixed，这里有一个误区，累计时间最高不见得单次时间就高，这是一个很显然的道理。
接下来观察下 WeatherForecast/slow-random 请求的分布情况，观察时间轴可知有两次请求，截图如下：
9.png

接下来的问题是这两个请求来自于哪两个方法呢？选中一个时间稍微长的，放大时间轴之后，点击 Plain List 观察 Total Time 最高的一列即可，截图如下：
10.png

最后就是 Show Code 观察 GetWithRandomDelay 方法的源代码，参考如下：
  1.         // 2. 随机慢速接口 - 延迟2-5秒随机
  2.         [HttpGet("slow-random")]
  3.         public async Task<IEnumerable<WeatherForecast>> GetWithRandomDelay()
  4.         {
  5.             // 随机等待2-5秒
  6.             var delay = Random.Shared.Next(2000, 5000);
  7.             await Task.Delay(delay);
  9.             return GenerateRandomForecasts(5);
  10.         }
  11.         // 辅助方法：生成随机天气预报数据
  12.         private IEnumerable<WeatherForecast> GenerateRandomForecasts(int count)
  13.         {
  14.             return Enumerable.Range(1, count).Select(index => new WeatherForecast
  15.             {
  16.                 Date = DateOnly.FromDateTime(DateTime.Now.AddDays(index)),
  17.                 TemperatureC = Random.Shared.Next(-20, 55),
  18.                 Summary = Summaries[Random.Shared.Next(Summaries.Length)]
  19.             });
  20.         }
复制代码
当然其他接口的调查也可以参考同样的方式。
三：总结

dotrace 非常强大，在观测 异常 和 慢Request 处理方面表现优秀，作为一位 .NET高级调试分析师 ，这款工具不可或缺！
11.jpg
作为JetBrains社区内容合作者，如有购买jetbrains的产品，可以用我的折扣码 HUANGXINCHENG，有25%的内部优惠哦。

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

使用道具 举报
B Color Image Link Quote Code Smilies
您需要登录后才可以回帖 登录 | 立即注册
发帖
皮仪芳
2025-6-28 08:40:16

0

粉丝关注

15

主题发布

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