.Net Core中的診斷日誌DiagnosticSource講解

前言

    近期由於需要進行分散式鏈路跟蹤系統的技術選型，所以一直在研究鏈路跟蹤相關的框架。作為能在.Net Core中使用的APM，SkyWalking自然成為了首選。SkyAPM-dotnet是SkyWalking在.Net Core端的探針實現，其主要的收集日誌的手段就是基於DiagnosticSource來進行診斷跟蹤的。不得不說SkyAPM-dotnet的設計還是非常優秀的，它本身定義了一套非常規範的標準，而且提供了非常良好的擴充套件性，雖然框架本身可支援的採集端有限，但是基於這套標準擴充套件起來還是非常方便的。

概念介紹

    關於DiagnosticSource它本身是一個基於釋出訂閱模式的工作模式，由於它本身的實現方式是非同步的，所以不僅僅可以把它用到日誌上，還可以用它實現非同步操作，或者用它簡化實現釋出訂閱的功能。DiagnosticSource本身是一個抽象類，我們最常用到的是它的子類DiagnosticListener，通過DiagnosticSource的Write方法實現釋出一條有具體名稱的訊息，然後通過IObserver去訂閱訊息。DiagnosticListener可以實現不同的例項，每個例項可以有自己的名稱，每個例項還可以釋出不同名稱的訊息，好比一個在寫程式碼的時候我們可以定義多個程式集，一個程式集下面可以包含多個名稱空間。

使用方式

上面我們大致的介紹了關於DiagnosticSource相關的概念，相信大家已經有了初步的瞭解，接下來我們就來看一下在程式碼中如何使用DiagnosticSource，還說到了它一個重要的子類DiagnosticListener，基本上關於DiagnosticSource的工作方式都是圍繞著DiagnosticListener實現的，首先我們來看一下如何釋出一條訊息

//宣告DiagnosticListener並命名為MyTest
DiagnosticSource diagnosticSource = new DiagnosticListener("MyTest");
string pubName = "MyTest.Log";
//判斷是否存在MyTest.Log的訂閱者
if (diagnosticSource.IsEnabled(pubName))
{
    //傳送名為MyTest.Log的訊息，包含Name，Address兩個屬性
    diagnosticSource.Write(pubName, new { Name = "old王", Address="隔壁" });
}

通過這種方式，我們就可以完成針對訊息的釋出，其中用到了IsEnabled方法，這個方法是在實際使用DiagnosticSource過程中比較常用的方法，用於判斷是夠存在對應名稱的消費者，這樣可以有效的避免傳送訊息浪費。
傳送相對還是比較簡單的，接下來我們看一下如何訂閱釋出的訊息。上面我們提到了訂閱訊息是通過IObserver介面實現的，IObserver代表了訂閱者。雖然我們通過DiagnosticSource去釋出訊息，但是真正描述釋出者身份的是IObservable介面，IObservable的唯一方法Subscribe是用來註冊訂閱者IObserver，但是預設系統並沒有為我們提供一個具體的實現類，所以我們需要定義一個IObserver訂閱者的實現類

public class MyObserver<T>:IObserver<T>
{
    private Action<T> _next;
    public MyObserver(Action<T> next)
    {
        _next = next;
    }

    public void OnCompleted()
    {
    }

    public void OnError(Exception error)
    {
    }

    public void OnNext(T value) => _next(value);
}

有了具體的訂閱者實現類，我們就可以為釋出者註冊訂閱者了,同樣是使用DiagnosticListener，個人認為雖然操作都是通過DiagnosticSource來完成的，但它只是一個外觀類，但是並不能直接描述釋出者和訂閱者本身。接下來我們看一下具體實現

//AllListeners獲取所有釋出者，Subscribe為釋出者註冊訂閱者MyObserver
DiagnosticListener.AllListeners.Subscribe(new MyObserver<DiagnosticListener>(listener =>
{
    //判斷髮布者的名字
    if (listener.Name == "MyTest")
    {
        //獲取訂閱資訊
        listener.Subscribe(new MyObserver<KeyValuePair<string, object>>(listenerData =>
        {
            System.Console.WriteLine($"監聽名稱:{listenerData.Key}");
            dynamic data = listenerData.Value;
            //列印發布的訊息
            System.Console.WriteLine($"獲取的資訊為:{data.Name}的地址是{data.Address}");
        }));

        listener.SubscribeWithAdapter(new MyDiagnosticListener());
    }
}));

具體實現可總結為兩步，首先為釋出者註冊訂閱者，然後獲取訂閱者獲取釋出的訊息。這種寫法還是比較複雜的，首先需要實現訂閱者類，然後通過一系列複雜的操作，才能完成訊息訂閱，然後還要自己獲取釋出的訊息，解析具體的訊息值，總之操作流程非常繁瑣。微軟似乎也意識到了這個問題，於是乎給我提供了一個關於實現訂閱者的便利方法，編輯專案檔案引入DiagnosticAdapter包

<PackageReference Include="Microsoft.Extensions.DiagnosticAdapter" Version="3.1.7" />

或者通過包管理器直接搜尋安裝，道路千萬條都是通羅馬。通過這個包解決了我們兩個痛點，首先是關於訂閱者的註冊難問題，其次解決了關於釋出訊息解析難的痛點。我們可以直接訂閱一個適配類來充當訂閱者的載體，其次我們可以定義方法模擬訂閱去訂閱訊息，而這個方法的引數就是我們釋出的訊息內容。說了這麼多，不如直接上程式碼

public class MyDiagnosticListener
{
    //釋出的訊息主題名稱
    [DiagnosticName("MyTest.Log")]
    //釋出的訊息引數名稱和釋出的屬性名稱要一致
    public void MyLog(string name,string address)
    {
        System.Console.WriteLine($"監聽名稱:MyTest.Log");
        System.Console.WriteLine($"獲取的資訊為:{name}的地址是{address}");
    }
}

我們可以隨便定義一個類來充當訂閱者載體,類裡面可以自定義方法來實現獲取解析訊息的實現。想要讓方法可以訂閱訊息，需要在方法上宣告DiagnosticName，然後名稱就是你要訂閱訊息的名稱，而方法的引數就是你釋出訊息的欄位屬性名稱，這裡需要注意的是訂閱的引數名稱需要和釋出宣告屬性名稱一致。
然後我們直接可以通過這個類去接收訂閱訊息

DiagnosticListener.AllListeners.Subscribe(new MyObserver<DiagnosticListener>(listener =>
{
    if (listener.Name == "MyTest")
    {
        //適配訂閱
        listener.SubscribeWithAdapter(new MyDiagnosticListener());
    }
}));

可能你覺得這樣還是不夠好，因為還是沒有脫離需要自定義訂閱者，這裡還有更簡潔的實現方式。細心的你可能已經發現了SubscribeWithAdapter是DiagnosticListener的擴充套件方法，而我們宣告DiagnosticSource就是使用的DiagnosticListener例項，所以上面的程式碼可以簡化為一下方式

DiagnosticListener diagnosticListener = new DiagnosticListener("MyTest");
DiagnosticSource diagnosticSource = diagnosticListener;
//直接去適配訂閱者
diagnosticListener.SubscribeWithAdapter(new MyDiagnosticListener());

string pubName = "MyTest.Log";
if (diagnosticSource.IsEnabled(pubName))
{
    diagnosticSource.Write(pubName, new { Name = "old王", Address="隔壁" });
}

這種方式也是我們比較推薦的使用方式，極大的節省了工作的方式，而且程式碼非常的簡潔。但是存在唯一的不足，這種寫法只能針對特定的DiagnosticListener進行訂閱處理，如果你需要監聽所有釋出者，就需要使用DiagnosticListener.AllListeners.Subscribe的方式。

DotNetCore原始碼中診斷日誌的埋點

在.Net Core的原始碼中，微軟預設在涉及到網路請求或處理請求等許多重要的節點都使用了DiagnosticListener來發布攔截的訊息，接下來就羅列一些我知道的比較常見的埋點，通過這些操作我們就可以看出，診斷日誌還是很便利的，而且微軟在.Net Core中也非常重視它的使用。

在ASP.NET Core中

當我們通過ConfigureWebHostDefaults配置Web主機的時候，程式就已經預設給我們注入了診斷名稱為Microsoft.AspNetCore的DiagnosticListener和DiagnosticSource，這樣我們就可以很方便的在程式中直接獲取DiagnosticListener例項去釋出訊息或者監聽釋出的內部訊息，具體注入邏輯位於可以去GenericWebHostBuilder類中檢視[點選檢視原始碼?]

var listener = new DiagnosticListener("Microsoft.AspNetCore");
services.TryAddSingleton<DiagnosticListener>(listener);
services.TryAddSingleton<DiagnosticSource>(listener);

然後在Server啟動的時候傳遞了DiagnosticListener例項[點選檢視原始碼?]

var httpApplication = new HostingApplication(application, Logger, DiagnosticListener, HttpContextFactory);
await Server.StartAsync(httpApplication, cancellationToken);

這樣在Server執行期間我們可以通過DiagnosticListener診斷跟蹤請求相關的資訊，我們可以看下在處理請求的過程中DiagnosticListener都發布了哪些訊息，我們找到傳送診斷跟蹤的位置位於HostingApplicationDiagnostics中[點選檢視原始碼?]，這事集中處理請求相關的診斷跟蹤，接下來我們就大致檢視一下它釋出了哪些事件訊息，首先找到定義釋出名稱的屬性

private const string ActivityName = "Microsoft.AspNetCore.Hosting.HttpRequestIn";
private const string ActivityStartKey = ActivityName + ".Start";
private const string ActivityStopKey = ActivityName + ".Stop";

private const string DeprecatedDiagnosticsBeginRequestKey = "Microsoft.AspNetCore.Hosting.BeginRequest";
private const string DeprecatedDiagnosticsEndRequestKey = "Microsoft.AspNetCore.Hosting.EndRequest";
private const string DiagnosticsUnhandledExceptionKey = "Microsoft.AspNetCore.Hosting.UnhandledException";

通過這些釋出訊息的名稱我們就可以看出，在請求開始、請求進入、請求結束、請求停止、請求異常等都發布了診斷訊息，我們以BeginRequest為例檢視一下具體傳送的訊息

if (_diagnosticListener.IsEnabled(DeprecatedDiagnosticsBeginRequestKey))
{
    startTimestamp = Stopwatch.GetTimestamp();
    RecordBeginRequestDiagnostics(httpContext, startTimestamp);
}

找到RecordBeginRequestDiagnostics方法的實現

[MethodImpl(MethodImplOptions.NoInlining)]
private void RecordBeginRequestDiagnostics(HttpContext httpContext, long startTimestamp)
{
    _diagnosticListener.Write(
        DeprecatedDiagnosticsBeginRequestKey,
        new
        {
            httpContext = httpContext,
            timestamp = startTimestamp
        });
}

從這裡我們可以看出在BeginRequest中診斷日誌發出的訊息中包含了HttpContext和開始時間戳資訊，然後再來看一下請求結束髮布的診斷訊息

[MethodImpl(MethodImplOptions.NoInlining)]
private void RecordEndRequestDiagnostics(HttpContext httpContext, long currentTimestamp)
{
    _diagnosticListener.Write(
        DeprecatedDiagnosticsEndRequestKey,
        new
        {
            httpContext = httpContext,
            timestamp = currentTimestamp
        });
}

通過釋出的這些跟蹤日誌我們可以獲取請求資訊,請求時間並且能得到輸出資訊和結束時間，有了這些關鍵資訊，我們就可以監聽請Asp.Net Core處理請求的情況，我們上面提到過SkyAPM-dotnet正是通過這些發出診斷跟蹤日誌，來實現對程式無入侵的方式來處理應用系統監控的，具體我們可以檢視相關實現，我們找到訂閱這些訊息的地方
[點選檢視原始碼?],拿出來類的結構，大致如下

public class HostingTracingDiagnosticProcessor : ITracingDiagnosticProcessor
{
    public string ListenerName { get; } = "Microsoft.AspNetCore";

    [DiagnosticName("Microsoft.AspNetCore.Hosting.BeginRequest")]
    public void BeginRequest([Property] HttpContext httpContext)
    {
    }

    [DiagnosticName("Microsoft.AspNetCore.Hosting.EndRequest")]
    public void EndRequest([Property] HttpContext httpContext)
    {
    }

    [DiagnosticName("Microsoft.AspNetCore.Diagnostics.UnhandledException")]
    public void DiagnosticUnhandledException([Property] HttpContext httpContext, [Property] Exception exception)
    {
    }

    [DiagnosticName("Microsoft.AspNetCore.Hosting.UnhandledException")]
    public void HostingUnhandledException([Property] HttpContext httpContext, [Property] Exception exception)
    {
    }

    //[DiagnosticName("Microsoft.AspNetCore.Mvc.BeforeAction")]
    public void BeforeAction([Property] ActionDescriptor actionDescriptor, [Property] HttpContext httpContext)
    {
    }

    //[DiagnosticName("Microsoft.AspNetCore.Mvc.AfterAction")]
    public void AfterAction([Property] ActionDescriptor actionDescriptor, [Property] HttpContext httpContext)
    {
    }
}

不得不承認SkyAPM-dotnet非常巧妙的利用了系統內部發出的診斷跟蹤日誌，實現了對請求的處理跟蹤，真的是非常優秀。

在HttpClient中

上面我們看到的是AspNetCore處理請求的診斷日誌埋點，在發出請求的HttpClient中，微軟也做了埋點處理。我們在之前的文章.NET Core HttpClient原始碼探究中提到過HttpClient通過HttpClientHandler傳送請求的，在HttpClientHandler SendAsync方法中我們可以看到如下實現

protected internal override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
            CancellationToken cancellationToken)
{
    return DiagnosticsHandler.IsEnabled() && _diagnosticsHandler != null ?
        _diagnosticsHandler.SendAsync(request, cancellationToken) :
        _underlyingHandler.SendAsync(request, cancellationToken);
}

也就是說如果滿足DiagnosticsHandler.IsEnabled()並且_diagnosticsHandler不為空的情況下將會使用DiagnosticsHandler傳送請求，關於DiagnosticsHandler.IsEnabled()的大致實現邏輯如下

if (AppContext.TryGetSwitch("System.Net.Http.EnableActivityPropagation", out bool enableActivityPropagation))
{
    return enableActivityPropagation;
}

string? envVar = Environment.GetEnvironmentVariable("DOTNET_SYSTEM_NET_HTTP_ENABLEACTIVITYPROPAGATION");
if (envVar != null && (envVar.Equals("false", StringComparison.OrdinalIgnoreCase) || envVar.Equals("0")))
{
    return false;
}
return true;

通過這個邏輯可以看出，預設情況下我們不做特殊處理返回的就是true，也就是說傳送請求會通過DiagnosticsHandler，我們找到DiagnosticsHandler的實現[點選檢視原始碼?]，抽離出來SendAsyncCore方法中關於診斷跟蹤的核心實現邏輯，大致如下

DiagnosticListener diagnosticListener = new DiagnosticListener("HttpHandlerDiagnosticListener");
if (diagnosticListener.IsEnabled("System.Net.Http.Request"))
{
    long timestamp = Stopwatch.GetTimestamp();
    loggingRequestId = Guid.NewGuid();
    //請求開始之前傳送診斷日誌
    diagnosticListener.Write("System.Net.Http.Request",new RequestData(request, loggingRequestId, timestamp));
}
HttpResponseMessage? response = null;
TaskStatus taskStatus = TaskStatus.RanToCompletion;
try
{
    response = async ?
        await base.SendAsync(request, cancellationToken).ConfigureAwait(false) :
        base.Send(request, cancellationToken);
    return response;
}
catch (OperationCanceledException)
{
    taskStatus = TaskStatus.Canceled;
    throw;
}
catch (Exception ex)
{
    taskStatus = TaskStatus.Faulted;
    if (diagnosticListener.IsEnabled("System.Net.Http.Exception"))
    {  
        //如果請求出現異常發出異常訊息診斷日誌
        diagnosticListener.Write("System.Net.Http.Exception", new ExceptionData(ex, request));
    }
    throw;
}
finally
{
    if (activity != null)
    {
        diagnosticListener.StopActivity(activity, new ActivityStopData(response,request,taskStatus));
    }
    if (diagnosticListener.IsEnabled("System.Net.Http.Response"))
    {
        long timestamp = Stopwatch.GetTimestamp();
        //得到輸出結果後傳送診斷日誌
        diagnosticListener.Write("System.Net.Http.Response",new ResponseData(response,loggingRequestId,timestamp,taskStatus));
    }
}

同樣的思路HttpClient會在傳送請求之前發出請求資訊相關的診斷跟蹤，會在得到相應之後傳送響應相關診斷跟蹤，通過這些資訊我們可以捕獲到由程式發出的Http請求相關的資訊，從而監控請求相關的資料，我們來看一下SkyAPM-dotnet訂閱Http請求相關的實現，在HttpClientTracingDiagnosticProcessor類中[點選檢視原始碼?]，抽離實現的框架大致如下

public class HttpClientTracingDiagnosticProcessor : ITracingDiagnosticProcessor
{
    public string ListenerName { get; } = "HttpHandlerDiagnosticListener";

    [DiagnosticName("System.Net.Http.Request")]
    public void HttpRequest([Property(Name = "Request")] HttpRequestMessage request)
    {
    }

    [DiagnosticName("System.Net.Http.Response")]
    public void HttpResponse([Property(Name = "Response")] HttpResponseMessage response)
    {
    }

    [DiagnosticName("System.Net.Http.Exception")]
    public void HttpException([Property(Name = "Request")] HttpRequestMessage request,
        [Property(Name = "Exception")] Exception exception)
    {
    }
}

這裡正是監聽的HttpClient發出的診斷日誌。假如存在系統A和系統B，系統A通過HttpClient傳送請求呼叫Asp.Net Core系統B，通過訂閱他們發出的診斷跟蹤日誌，而這些資料正是實現系統監控和鏈路跟蹤重要依據。

其他

    在.Net Core相關的原始碼中還有許多其他關於DiagnosticListener的埋點資訊比如請求執行到Action的時候或者出現全域性異常的時候都有類似的處理。同樣在EFCore中也存在這些埋點資訊，有興趣的可以自行查閱相關原始碼和SkyAPM-dotnet原始碼，瞭解DiagnosticSource工作方式，以及如何通過這些資訊實現APM系統。雖然SkyAPM-dotnet本身實現的框架個數有限，但是它給我們實現了良好的擴充套件性，我們可以通過DiagnosticSource和DiagnosticListener自行實現SkyAPM-dotnet的擴充套件，比如你可以擴充套件Redis MongoDb等其它中介軟體。比如SkyApm.Diagnostics.CAP是CAP納入SkyAPM中程式包，正是楊總參與了相關程式碼的實現。

總結

    DiagnosticSource診斷跟蹤涉及到的概念雖然不是很多，但是在.Net Core相關的框架中使用的還是非常廣泛的，通過這些資訊我們可以拿到框架執行過程中關鍵節點得到的資訊，為我們提供了很大的便利。加上SkyAPM-dotnet巧妙的使用了這一特點使得DiagnosticSource更變得強大而且通用。上面我們講述的只是冰山一角，還有更多更深的應用，比如Azure監控.Net Core應用程式也是利用了這些。有興趣的可以檢視相關原始碼，也可以學習一下SkyAPM-dotnet相關原始碼，體會一下DiagnosticSource精髓所在。

?歡迎掃碼關注我的公眾號?