在.NET中使用DiagnosticSource

2020 年 10 月 5 日
筆記
.NET, .NET 5

前言

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 */ });

參考

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

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

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

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

Tags: .NET .NET 5