一：背景

1. 講故事

在我分析的眾多dump中，有一些CPU爆高是因為高頻的拋 Exception 導致，比如下面這張圖，有 19 個線程都在拋 xxxResultException 異常。

從卦中雖知大量異常的痕跡，但從嚴謹的角度來說，最好再卜一卦，就是用 perfview 或者 dottrace 在 cpu 爆高的時段記錄下異常的數量，這樣就穩了，這篇我們就來解決這個棘手的問題。

二：異常診斷 和 Request慢處理

1. 程序異常診斷

有一個項目平時CPU的利用率都是幾個點，突然在某段時間CPU明顯升高，高達20多個點，我想知道此時程序在干什么？截圖如下：

這種問題除了抓dump，還有一個輕量級的途徑就是用 dottrace，開啟 timeline 模式跟蹤，收集一段時間之后，打開跟蹤文件。

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

• 大量的線程池線程正在 Running （灰藍色）
• Exceptions 事件個數高達 341w。
• 產生異常最多的是 ThrowHighFrequencyException 方法。
• 追蹤周期僅為 15s

以上四個信息就能非常確認，程序的CPU爆高就是因為大量拋出異常所致，接下來選擇Filters面板中的 Exceptions 進行下鉆觀察 異常類型 和 異常消息 的分布，截圖如下：

從卦中可以看到 InvalidOperationException 異常拋的是最多的，高達 273w，并且還是定位在 ThrowHighFrequencyException 方中，接下來對父子方法 Show Code，代碼參考如下：

    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("高頻異常：無效操作");
    }

到此問題真相大白，有些朋友可能想知道每個異常發生的時點，這就需要你放大 時間軸 了哈，圖中的黑色便是。

還有一種方式就是打開 Event 面板 View -> Events，然后觀察左側的偏移時間(Timestamp)，非常清楚加明細，截圖如下：

2. Request慢處理

在給web程序做性能優化時，經常要做的一件事情就是查找慢請求，這也是 dotrace 的強項，它用一個 Incoming HTTP Requests 提供了獨家支持，剛好手里有一個 dtp 文件，直接打開。

從卦中可以看到當前程序涉及到的 http 請求總時間為 12s，那 12s 都被哪些request 請求分攤著呢？ 繼續下鉆即可，選擇 Incoming HTTP Requests，截圖如下：

從卦中可以看到當前 WeatherForecast/slow-random 累計時間是最高的，其次是 WeatherForecast/slow-fixed，這里有一個誤區，累計時間最高不見得單次時間就高，這是一個很顯然的道理。

接下來觀察下 WeatherForecast/slow-random 請求的分布情況，觀察時間軸可知有兩次請求，截圖如下：

接下來的問題是這兩個請求來自于哪兩個方法呢？選中一個時間稍微長的，放大時間軸之后，點擊 Plain List 觀察 Total Time 最高的一列即可，截圖如下：

最后就是 Show Code 觀察 GetWithRandomDelay 方法的源代碼，參考如下：

        // 2. 隨機慢速接口 - 延遲2-5秒隨機
        [HttpGet("slow-random")]
        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[Random.Shared.Next(Summaries.Length)]
            });
        }

當然其他接口的調查也可以參考同樣的方式。

三：總結

dotrace 非常強大，在觀測 異常 和 慢Request 處理方面表現優秀，作為一位 .NET高級調試分析師 ，這款工具不可或缺！

作為JetBrains社區內容合作者，如有購買jetbrains的產品，可以用我的折扣碼 HUANGXINCHENG，有25%的內部優惠哦。