在.NET中使用DiagnosticSource

前言

DiagnosticSource是一个非常有意思的且非常有用的API，对于这些API它们允许不同的库发送命名事件，并且它们也允许应用程序订阅这些事件并处理它们，它使我们的消费者可以在运行时动态发现数据源并且订阅与其相关的数据源。

DiagnosticSource在AspNetCore、EntityFrameworkCore、HttpClient、SqlClient中被使用，在我们实际的开发过程中他使我们能够进行拦截请求与响应的http请求、数据库查询、对HttpContext、DbConnection、DbCommand、HttpRequestMessageand等对象的访问，甚至说在需要的时候我们可以进行修改这些对象来处理我们的业务。

下面我们将通过如下的简单示例来了解它.

DiagnosticSource和EventSource区别

DiagnosticSource和EventSource在架构设计上很相似，他们的主要区别是EventSource它记录的数据是可序列化的数据，会被进程外消费，所以要求记录的对象必须是可以被序列化的。而DiagnosticSource被设计为在进程内处理数据，所以我们通过它拿到的数据信息会比较丰富一些，它支持非序列化的对象，比如HttpContext、HttpResponseMessage等。另外如果想在EventSource中获取DiagnosticSource中的事件数据，可以通过DiagnosticSourceEventSource这个对象来进行数据桥接。

需求来了

为了更好的理解DiagnosticSource的工作方式，如下这个示例将拦截数据库请求，假设我们有一个简单的控制台应用程序，它向数据库发出请求并将结果输出到控制台。

class Program
{
    public const string ConnectionString =
        @"Server=localhost;Database=master;Trusted_Connection=True;";
    static async Task Main(string[] args)
    {
        var result = await Get();
        Console.WriteLine(result);

    }
    public static async Task<int> Get() {
        using (var connection=new SqlConnection(ConnectionString))  
        {
            return await connection.QuerySingleAsync<int>("SELECT 42;");
        }
    }
}

我们再来思考一下，假设来了一个需求：我们需要获取到所有数据库查询的执行时间，或者说我们要进行获取执行的一些sql语句或者数据进行存储作为记录我们该如何处理？
好了下面我们将尝试使用DiagnosticSource来实现该需求。

使用System.Diagnostics.DiagnosticSource

来吧，我们先来创建一个类作为该事件的处理程序或者说作为该事件的消费者。

public sealed class ExampleDiagnosticObserver
{}

下面我们将处理该事件，我们需要将这个类进行实例化，并且将它注册到静态对象中的观察器中DiagnosticListener.AllListeners，代码如下所示：

static async Task Main(string[] args)
{
    var observer = new ExampleDiagnosticObserver();
    IDisposable subscription = DiagnosticListener.AllListeners.Subscribe(observer);
    var result = await Get();
    Console.WriteLine(result);
}

下面我们再来修改我们的ExampleDiagnosticObserver类，其实如上代码片段中编译器已经提醒我们要实现接口IObserver<diagnosticsListener>，下面我们实现它

public sealed class ExampleDiagnosticObserver : IObserver<DiagnosticListener>
{
    public void OnCompleted()
    {  
    }

    public void OnError(Exception error)
    {  
    }

    public void OnNext(DiagnosticListener value)
    {
        Console.WriteLine(value.Name);
    }
}

接下来我们运行该程序，结果将在控制台进行打印如下所示：

SqlClientDiagnosticListener
SqlClientDiagnosticListener
42

看如上结果，这意味着在我们当前这个应用程序中的某个地方注册了两个类型为DiagnosticListener的对象，名字为SqlClientDiagnosticListener。

对于应用程序中创建的每个实例diagnosticsListener，在第一次使用时将调用IObserver<DiagnosticListener>.OnNext方法一次，现在我们只是将实例的名称输出到了控制台中，但实际情况中我们想一下，我们应该对这个实例名称做什么？对，没错，我们要对这些实例名称做检查，那么我们如果要对这个实例中某些事件，我们只需要使用subscribe方法去订阅它。

下面我们来实现IObserver<DiagnosticListener>：

public class ExampleDiagnosticObserver1 : IObserver<DiagnosticListener>,
         IObserver<KeyValuePair<string, object>>
{
    private readonly List<IDisposable> _subscriptions = new List<IDisposable>();

    public void OnCompleted()
    {
    }

    public void OnError(Exception error)
    {
    }

    public void OnNext(KeyValuePair<string, object> value)
    {
        Write(value.Key, value.Value);
    }

    public void OnNext(DiagnosticListener value)
    {
        if (value.Name == "SqlClientDiagnosticListener")
        {
            var subscription = value.Subscribe(this);
            _subscriptions.Add(subscription);
        }
    }

    private void Write(string name, object value)
    {
        Console.WriteLine(name);
        Console.WriteLine(value);
        Console.WriteLine();
    }
}

在如上代码片段中我们实现了接口IObserver<KeyValuePair<string, object>>的IObserver<KeyValuePair<string，object>>.OnNext的方法，参数为KeyValuePair<string，object>，其中Key是事件的名称，而Value是一个匿名对象.

运行程序输出结果如下所示：

System.Data.SqlClient.WriteConnectionOpenBefore
{ OperationId = f5f4d4f0-7aa1-46e6-bd48-78acca3dac0a, Operation = OpenAsync, Connection = System.Data.SqlClient.SqlConnection, Timestamp = 1755845041766 }

System.Data.SqlClient.WriteCommandBefore
{ OperationId = 3d8617d1-0317-4f75-bffd-5b0fddf5cc12, Operation = ExecuteReaderAsync, ConnectionId = 554f4ee4-47c3-44ff-a967-cc343d1d5019, Command = System.Data.SqlClient.SqlCommand }

System.Data.SqlClient.WriteConnectionOpenAfter
{ OperationId = f5f4d4f0-7aa1-46e6-bd48-78acca3dac0a, Operation = OpenAsync, ConnectionId = 554f4ee4-47c3-44ff-a967-cc343d1d5019, Connection = System.Data.SqlClient.SqlConnection, Statistics = System.Data.SqlClient.SqlStatistics+StatisticsDictionary, Timestamp = 1755851869508 }

System.Data.SqlClient.WriteCommandAfter
{ OperationId = 3d8617d1-0317-4f75-bffd-5b0fddf5cc12, Operation = ExecuteReaderAsync, ConnectionId = 554f4ee4-47c3-44ff-a967-cc343d1d5019, Command = System.Data.SqlClient.SqlCommand, Statistics = System.Data.SqlClient.SqlStatistics+StatisticsDictionary, Timestamp = 1755853467664 }

System.Data.SqlClient.WriteConnectionCloseBefore
{ OperationId = ed240163-c43a-4394-aa2d-3fede4b27488, Operation = Close, ConnectionId = 554f4ee4-47c3-44ff-a967-cc343d1d5019, Connection = System.Data.SqlClient.SqlConnection, Statistics = System.Data.SqlClient.SqlStatistics+StatisticsDictionary, Timestamp = 1755854169373 }

System.Data.SqlClient.WriteConnectionCloseAfter
{ OperationId = ed240163-c43a-4394-aa2d-3fede4b27488, Operation = Close, ConnectionId = 554f4ee4-47c3-44ff-a967-cc343d1d5019, Connection = System.Data.SqlClient.SqlConnection, Statistics = System.Data.SqlClient.SqlStatistics+StatisticsDictionary, Timestamp = 1755854291040 }

42

如上结果可以清楚的看到里面存在6个事件，我们可以看到两个是在打开数据库之前和之后执行的，两个是在执行命令之前和之后执行的，还有两个是在关闭数据库连接之前和之后执行的。

另外可以看到每个事件中都包含一组参数，如OperationId、Operation、ConnectionId等，这些参数通常作为匿名对象属性传输，我们可以通过反射来获取这些属性的类型化的值。

现在我们解决了我们最初的需求，获取数据库中所有查询的执行时间，并将其输出到控制台中，我们需要进行修改，代码如下所示：

private readonly AsyncLocal<Stopwatch> _stopwatch = new AsyncLocal<Stopwatch>();

private void Write(string name, object value)
{
    switch (name)
    {
        case "System.Data.SqlClient.WriteCommandBefore":
        {
            _stopwatch.Value = Stopwatch.StartNew();
            break;
        }
        case "System.Data.SqlClient.WriteCommandAfter":
        {
        var stopwatch = _stopwatch.Value;
        stopwatch.Stop();
        var command = GetProperty<SqlCommand>(value, "Command");
        Console.WriteLine($"CommandText: {command.CommandText}");
        Console.WriteLine($"Elapsed: {stopwatch.Elapsed}");
        Console.WriteLine();
        break;
        }
    }
}

private static T GetProperty<T>(object value, string name)
{
    return (T)value.GetType()
                .GetProperty(name)
                .GetValue(value);
}

在这我们将拦截数据库中查询的开始和结束事件，在执行之前我们创建并且启动stopwatch，将其存储在AsyncLocal<stopwatch>中，以后面将其返回，在执行完成后，我们获取之前启动的stopwatch，停止它，通过反射从参数值中获取执行命令，并将结果输出到控制台。

执行结果如下所示：

CommandText: SELECT 42;
Elapsed: 00:00:00.1509086

42

现在我们已经解决了我们的需求，但是目前还存在一个小的问题，当我们订阅事件diagnosticListener时，我们从它里面将接收到所有的事件，包括我们不需要的事件，但是呢发送的每个事件都会创建一个带有参数的匿名对象，这会在GC上造成额外的压力。

我们需要解决如上的问题，避免我们去处理所有的事件，我们需要指定Predicate<string>这个特殊的委托类型，我们声明IsEnabled方法，在此筛选对应名称的消费者。

下面我们修改一下方法IObserver<DiagnosticListener>.OnNext

public void OnNext(DiagnosticListener value)
{
    if (value.Name == "SqlClientDiagnosticListener")
    {
        var subscription = value.Subscribe(this, IsEnabled);
        _subscriptions.Add(subscription);
    }
}
        
private bool IsEnabled(string name)
{
    return name == "System.Data.SqlClient.WriteCommandBefore"
        || name == "System.Data.SqlClient.WriteCommandAfter";
}

现在我们只会对事件System.Data.SqlClient.WriteCommandBefore和System.Data.SqlClient.WriteCommandAfter调用Write方法。

使用Microsoft.Extensions.DiagnosticAdapter

上面虽然我们实现了需求，但是我们也可以发现我们从DiagnosticListener接收到的事件参数通常作为匿名对象传递，因此通过反射去处理这些参数这样给我们造成了比较昂贵的消耗，不过开发团队也考虑到了该问题向我们提供了Microsoft.Extensions.DiagnosticAdapter来完成我们的操作。

下面我们需要将Subscribe改为SubscribeWithAdapter,另外在这种情况下我们不需要实现IObserver<KeyValuePair<string, object>>接口，相反的是我们需要为每个事件声明一个单独的方法，并且使用[DiagnosticNameAttribute]特性去标注

如下所示：

public class ExampleDiagnosticObserver4 : IObserver<DiagnosticListener>
{
    private readonly List<IDisposable> _subscriptions = new List<IDisposable>();
    private readonly AsyncLocal<Stopwatch> _stopwatch = new AsyncLocal<Stopwatch>();

    public void OnCompleted()
    {
    }

    public void OnError(Exception error)
    {
    }

    public void OnNext(DiagnosticListener value)
    {
        if (value.Name == "SqlClientDiagnosticListener")
        {
            var subscription = value.SubscribeWithAdapter(this);
            _subscriptions.Add(subscription);
        }
    }

    [DiagnosticName("System.Data.SqlClient.WriteCommandBefore")]
    public void OnCommandBefore()
    {
        _stopwatch.Value = Stopwatch.StartNew();
    }

    [DiagnosticName("System.Data.SqlClient.WriteCommandAfter")]
    public void OnCommandAfter(DbCommand command)
    {
        var stopwatch = _stopwatch.Value;
        stopwatch.Stop();
        Console.WriteLine($"CommandText: {command.CommandText}");
        Console.WriteLine($"Elapsed: {stopwatch.Elapsed}");
        Console.WriteLine();
    }
}

现在我们实现了对数据执行的监控或者说拦截功能，同时也能为我们的数据库执行时间做记录，并且特别注意的是我们并没有对应用程序本身做修改，这样也减轻了很多的冗余，同时节省了大量的编码时间。这是一个很不错的编程体验。

创建DiagnosticListener实例

在大多数情况下，我们对DiagnosticSource都会去订阅已经存在的事件，基本我们都不需要去创建自己的DiagnosticListener去发送事件，当然去了解一下这一特性也是比较好的，请继续往下看

创建自己的实例

private static readonly DiagnosticSource  diagnosticSource =
    new DiagnosticListener("MyLibraty");

发送事件，我们将调用Write进行写入事件

if (diagnosticSource.IsEnabled("MyEvent"))
    diagnosticSource.Write("MyEvent", new { /* parameters */ });

参考

https://github.com/dotnet/corefx/blob/master/src/System.Diagnostics.DiagnosticSource/src/DiagnosticSourceUsersGuide.md

https://sudonull.com/post/3671-Using-the-DiagnosticSource-in-NET-Core-Theory

https://github.com/dotnet/runtime/issues/20992

https://github.com/hueifeng/BlogSample/tree/master/src/DiagnosticDemo

posted @ 2020-10-05 12:56 HueiFeng 阅读(2252) 评论(3) 编辑收藏举报

刷新页面返回顶部