如何獲取GC(垃圾回收器)的STW(暫停)時間?

2022 年 6 月 27 日
筆記
.NET, .Net GC, c#, gc

前言

在現代的容器化和微服務應用中，因為分散式的環境和錯綜複雜的調用關係，APM（Application Performance Monitoring 應用性能監控）顯得尤為重要，它通過採集應用程式各種指標和請求鏈路，讓你知道系統當前的狀態和值得優化的點，另外能幫助你發現應用程式的異常，幫助你更方便的定位問題。
對於.NET這樣帶GC（Garbage Collector 垃圾回收器）的平台來說，GC的指標也尤為重要，採集可以幫助我們分析記憶體泄漏、優化系統性能等等。在公司內部已經可以採集比較全面的.NET GC指標，如下圖所示。

在絕大多數場景它能滿足要求，但是如果遇到某時某刻P95延時突然增大，非同步任務突然超時，我們想排查這些異常是否因為GC的STW Time（Stop The World Time 指GC運行過程中所有執行緒被掛起的時間）過長導致的，就沒有辦法了，因為目前沒有採集這些指標。
所以本文就帶大家了解一下，如何採集.NET GC STW Time。

方法

如.NET記憶體性能分析指南中提到的一樣，.NET Runtime在運行過程中會發布很多事件，這些事件代表了當前Runtime的運行狀態，同樣GC在運行過程中也會發布很多事件，我們可以使用PerfView工具來收集這樣的一些事件。下面是WorkStationGC發生GC時的一個事件序列。

Microsoft-Windows-DotNETRuntime/GC/SuspendEEStart	//開始暫停託管執行緒運行
Microsoft-Windows-DotNETRuntime/GC/SuspendEEStop	//暫停託管執行緒完成
Microsoft-Windows-DotNETRuntime/GC/Start	// GC開始回收
Microsoft-Windows-DotNETRuntime/GC/Stop		// GC回收結束
Microsoft-Windows-DotNETRuntime/GC/RestartEEStart	//恢復之前暫停的託管執行緒
Microsoft-Windows-DotNETRuntime/GC/RestartEEStop	//恢復託管執行緒運行完成

PS: 所有的事件都可以在.NET文檔官方中找到，非常的全面。
而SuspendEEStart(暫停託管執行緒運行)到RestartEEStop(恢復託管執行緒運行完成)中經過的時間就是STW Time，我們只需要記錄這兩個事件的差值，就可以知道本次GC STW的時間有多長。
BGC的過程比WorkStationGC複雜的很多，但是一樣是測量這兩個事件花費的時間來採集STW Time，本文不做過多介紹。

使用EventSource採集

那麼我們知道通過計算哪兩個指標的差值來獲得STW時間，那麼應該如何通過程式碼來採集呢？
這裡就需要知道EventSource和EventListener兩個類，顧名思義我們可以通過EventSource來發布事件，使用EventListener來監聽事件，在本文中我們也主要使用EventListener來收集GC事件，對於這EventSource類的使用大家可以看下面給出的微軟文檔鏈接，這裡不做過多介紹。

EventSource
EventListener
我們來看一看如何使用EventListener類監聽GC事件，程式碼如下所示：

using System.Diagnostics.Tracing;  
  
// 開啟GC事件監聽  
var gc = new GcStwMetricsCollector();  
// 創建一些對象  
var array = Enumerable.Range(0, 1000).Select(s => (decimal)s).ToArray();  
// 手動執行GC  
GC.Collect();  
Console.ReadLine();  
  
public class GcStwMetricsCollector : EventListener  
{  
    // GC關鍵字  
    private const int GC_KEYWORD = 0x0000001;  
    // 我們要關注的GC事件  
    private const int GCSuspendEEBegin = 9;  
    private const int GCRestartEEEnd = 3;  
  
    private EventSource? _eventSource;  
    public void Stop()  
    {  
        if (_eventSource == null)  
            return;  
  
        DisableEvents(_eventSource);  
    }  
  
    protected override void OnEventSourceCreated(EventSource eventSource)  
    {  
        _eventSource = eventSource;  
        // GC 事件在 Microsoft-Windows-DotNETRuntime 名稱空間下   
if (eventSource.Name.Equals("Microsoft-Windows-DotNETRuntime"))  
        {  
            // 啟用事件，事件級別為Informational， 只監聽GC事件  
            EnableEvents(eventSource, EventLevel.Informational, (EventKeywords) (GC_KEYWORD));  
        }  
    }  
  
    private long _currentStwStartTime = 0;  
    protected override void OnEventWritten(EventWrittenEventArgs e)  
    {  
        switch (e.EventId)  
        {  
            // 凍結託管執行緒開始，記錄當前時間  
            case GCSuspendEEBegin:  
                _currentStwStartTime = e.TimeStamp.Ticks;  
                break;  
            // 恢復託管執行緒結束，計算當前時間與凍結託管執行緒開始時間的差值  
            case GCRestartEEEnd:  
                if (_currentStwStartTime > 0)  
                {  
                    var ms = TimeSpan.FromTicks(e.TimeStamp.Ticks - _currentStwStartTime).TotalMilliseconds;  
                    _currentStwStartTime = 0;  
                    // 輸出結果  
                    Console.WriteLine($"STW: {ms}ms");  
                }  
                break;  
        }  
    }  
}

運行結果：

STW: 0.2568ms

至於GC事件對應的枚舉值，大家可以在我上文中給出的文檔中找到。

.NET7新API

在實現這個需求時，我注意到.NET7有一個新的issue，直接提供了一個API，讓我們可以獲取到總的GC STW Time，我把重點的資訊摘抄和翻譯了一下。

背景和動機

今天我們已經在GetGCMemoryInfo 公開了獲取GC處理時間和暫停時間的百分比值的API。
具體來說是通過GCMemoryInfo的PauseTimePercentage欄位。
這個很有用，但是如果我只想要一個分子(即：程式運行以來總的GC暫停時間)。現在沒有辦法獲取到。

API 提案

我建議在System.GC上添加一個下面這樣的API：

TimeSpan System.GC.GetTotalPauseDuration()

它會返回GC總的暫停時間。

API 使用

TimeSpan start = System.GC.GetTotalPauseDuration();
// ... Perform some work ...
TimeSpan end= System.GC.GetTotalPauseDuration();
Console.WriteLine(end - start + " was spent pausing in GC");

我看到這個API已經和最新的.NET7預覽版一起發布，我們下載最新的.NET7 SDK，然後把項目改成.NET7，來試試這個API，程式碼如下所示：

using System.Diagnostics.Tracing;  
  
// 開啟GC事件監聽  
var gc = new GcStwMetricsCollector();  
// 創建一些對象  
var array = Enumerable.Range(0, 1000).Select(s => (decimal)s).ToArray();  
// 手動執行GC  
GC.Collect();  
Console.WriteLine($"API STW:{GC.GetTotalPauseDuration().TotalMilliseconds}ms");  
Console.ReadLine();
// 省略上文中一樣的程式碼

運行結果：

API STW: 0.223ms
Event STW: 0.296ms

API統計的應該會更加準確，我們通過事件來獲取多多少少有一點額外的開銷，不過誤差在可接受的範圍內。

總結

上文中提到了兩種方式來獲取.NET GC STW Time，我們只需要稍加改造，就可以將STW監控的功能加入APM中，如下圖表就是本地測試時採集的一些數據。

當然通過EventListener還可以實現更多的APM資訊的採集，大家有興趣也可以研究看看。

本文程式碼鏈接Github: //github.com/InCerryGit/BlogCodes/tree/main/Get-GC-STW-Time

Tags: .NET .Net GC c# gc