当前位置 : 主页 > 编程语言 > 其它开发 >

如何获取GC(垃圾回收器)的STW(暂停)时间?

来源:互联网 收集:自由互联 发布时间:2022-06-29
前言 在现代的容器化和微服务应用中,因为分布式的环境和错综复杂的调用关系,APM(Application Performance Monitoring 应用性能监控)显得尤为重要,它通过采集应用程序各种指标和请求链
前言

在现代的容器化和微服务应用中,因为分布式的环境和错综复杂的调用关系,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时间,那么应该如何通过代码来采集呢?
这里就需要知道EventSourceEventListener两个类,顾名思义我们可以通过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: https://github.com/InCerryGit/BlogCodes/tree/main/Get-GC-STW-Time

往期文章:
.NET性能优化-推荐使用Collections.Pooled(补充)
.NET性能优化-使用ValueStringBuilder拼接字符串
.NET性能优化-使用结构体替代类

网友评论