在.NET中使用DiagnosticSource

HueiFeng發表於2020-10-05

前言

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

相關文章