診斷日志知多少 | DiagnosticSource 在.NET上的應用


1. 引言

最近為了解決ABP集成CAP時無法通過攔截器啟用工作單元的問題,從小伙伴那里學了一招。借助DiagnossticSource,可以最小改動完成需求。關於DiagnosticSource曉東大佬18年在文章 在 .NET Core 中使用 Diagnostics (Diagnostic Source) 記錄跟蹤信息就有介紹,文章開頭就說明了Diagnostics 一直是一個被大多數開發者忽視的東西。是的,我也忽略了,這個好東西,有必要學習一下,下面就和大家簡單聊一聊System.Diagnostics.DiagnosticSource在.NET上的應用。

2. System.Diagnostics.DiagnosticSource

Diagnostics位於System命名空間下,由此可見Diagnostics在.NET 運行時中的地位不可小覷。其中System.Diagnostics命名空間下又包含不同類庫,提供了允許與系統進程,事件日志和性能計數器進行交互的類。如下圖所示:

Diagnostic Namespace

其中System.Diagnostics.DiagnosticSource模塊,它允許對代碼進行檢測,以在生產時記錄豐富的數據負載(可以傳遞不可序列化的數據類型),以便在進程內進行消耗。消費者可以在運行時動態發現數據源並訂閱感興趣的數據源。

在展開之前,有必要先梳理下涉及的以下核心概念:

  • IObservable:可觀測對象
  • IObserver:觀察者
  • DiagnosticSource :診斷來源
  • DiagnosticListener:診斷監聽器
  • Activity:活動

3. 觀察者模式(IObservable & IObserver)

IObservable IObserver位於System命名空間下,是.NET中對觀察者模式的抽象。

觀察者設計模式使觀察者能夠從可觀察對象訂閱並接收通知。 它適用於需要基於推送通知的任何方案。 此模式定義可觀察對象,以及零個、一個或多個觀察者。 觀察者訂閱可觀察對象,並且每當預定義的條件、事件或狀態發生更改時,該可觀察對象會通過調用其方法之一來自動通知所有觀察者。 在此方法調用中,該可觀察對象還可向觀察者提供當前狀態信息。 在 .NET Framework 中,通過實現泛型 System.IObservable  和 System.IObserver  接口來應用觀察者設計模式。 泛型類型參數表示提供通知信息的類型。

第一次學習觀察者模式,應該是大學課本中基於事件燒水的例子,咱們就基於此實現個簡單的Demo吧。首先執行dotnet new web -n Dotnet.Diagnostic.Demo創建示例項目。

3.1. 定義可觀察對象(實現IObservable接口)

對於燒水的示例,主要關注水溫的變化,因此先定義Temperature來表示溫度變化:

public class Temperature
{
    public Temperature(decimal temperature, DateTime date)
    {
        Degree = temperature;
        Date = date;
    }
    public decimal Degree { get;  }
    public DateTime Date { get;  }
}

接下來通過實現IObservable<T>接口來定義可觀察對象。

public interface IObservable<out T>
{
  IDisposable Subscribe(IObserver<T> observer);
}

從接口申明來看,只定義了一個Subscribe方法,從觀察者模式講,觀察者應該既能訂閱又能取消訂閱消息。為什么沒有定義一個UnSubscribe方法呢?其實這里方法申明已經說明,期望通過返回IDisposable對象的Dispose方法來達到這個目的。

/// <summary>
/// 熱水壺
/// </summary>
public class Kettle : IObservable<Temperature>
{
    private List<IObserver<Temperature>> observers;
    private decimal temperature = 0;

    public Kettle()
    {
        observers = new List<IObserver<Temperature>>();
    }

    public decimal Temperature
    {
        get => temperature;
        private set
        {
            temperature = value;
            observers.ForEach(observer => observer.OnNext(new Temperature(temperature, DateTime.Now)));
            
            if (temperature == 100)
                observers.ForEach(observer => observer.OnCompleted());
        }
    }
    public IDisposable Subscribe(IObserver<Temperature> observer)
    {
        if (!observers.Contains(observer))
        {
            Console.WriteLine("Subscribed!");
            observers.Add(observer);
        }
        //使用UnSubscriber包裝,返回IDisposable對象,用於觀察者取消訂閱
        return new UnSubscriber<Temperature>(observers, observer);
    }
    /// <summary>
    /// 燒水方法
    /// </summary>
    public async Task StartBoilWaterAsync()
    {
        var random = new Random(DateTime.Now.Millisecond);
        while (Temperature < 100)
        {
            Temperature += 10;
            await Task.Delay(random.Next(5000));
        }
    }
}

//定義泛型取消訂閱對象,用於取消訂閱
internal class UnSubscriber<T> : IDisposable
{
    private List<IObserver<T>> _observers;
    private IObserver<T> _observer;
    internal UnSubscriber(List<IObserver<T>> observers, IObserver<T> observer)
    {
        this._observers = observers;
        this._observer = observer;
    }
    public void Dispose()
    {
        if (_observers.Contains(_observer))
        {
            Console.WriteLine("Unsubscribed!");
            _observers.Remove(_observer);
        }
    }
}

以上代碼中List<IObserver >存在線程安全問題,因為簡單Demo,就不予優化了。

3.2. 定義觀察者(實現IObserver 接口)

比如定義一個報警器,實時播報溫度。

public class Alter : IObserver<Temperature>
{
    public void OnCompleted()
    {
        Console.WriteLine("du du du !!!");
    }
    public void OnError(Exception error)
    {
        //Nothing to do
    }
    public void OnNext(Temperature value)
    {
        Console.WriteLine($"{value.Date.ToString()}: Current temperature is {value.Degree}.");
    }
}

添加測試代碼,訪問localhost:5000/subscriber控制台輸出結果如下:

endpoints.MapGet("/subscriber", async context =>
{
    var kettle = new Kettle();//初始化熱水壺
    var subscribeRef = kettle.Subscribe(new Alter());//訂閱
    
    var boilTask = kettle.StartBoilWaterAsync();//啟動開始燒水任務
    var timoutTask = Task.Delay(TimeSpan.FromSeconds(15));//定義15s超時任務
    //等待,如果超時任務先返回則取消訂閱
    var firstReturnTask = await Task.WhenAny(boilTask, timoutTask);
    if (firstReturnTask == timoutTask)
        subscribeRef.Dispose();
    await context.Response.WriteAsync("Hello subscriber!");
});

------------------------------------------------------------------

Subscribed!
10/2/2020 4:53:20 PM: Current temperature is 10.
10/2/2020 4:53:20 PM: Current temperature is 20.
10/2/2020 4:53:21 PM: Current temperature is 30.
10/2/2020 4:53:21 PM: Current temperature is 40.
10/2/2020 4:53:24 PM: Current temperature is 50.
10/2/2020 4:53:25 PM: Current temperature is 60.
10/2/2020 4:53:26 PM: Current temperature is 70.
10/2/2020 4:53:30 PM: Current temperature is 80.
Unsubscribed!

4. DiagnosticSource & DiagnosticListener

4.1. 概念講解

DiagnosticSource直譯就是診斷源,也就是它是診斷日志的來源入口。DiagnosticSource其是一個抽象類主要定義了以下方法:

//Provides a generic way of logging complex payloads
public abstract void Write(string name, object value);
//Verifies if the notification event is enabled.
public abstract bool IsEnabled(string name);

DiagnosticListener直譯就是診斷監聽器,繼承自DiagnosticSource,同時實現了IObservable<KeyValuePair<string, object>>接口,因此其本質是一個可觀察對象。小結以下:

  1. DiagnosticSource 作為診斷日志來源,提供接口,用於寫入診斷日志。
  2. 診斷日志的可觀察數據類型為KeyValuePair<string, object>
  3. DiagnosticListener 繼承自DiagnosticSource,作為可觀察對象,可由其他觀察者訂閱,以獲取診斷日志。

DiagnosticListener 其構造函數接收一個name參數。

private static DiagnosticSource httpLogger = new DiagnosticListener("System.Net.Http");

可以通過下面這種方式記錄診斷日志:

if (httpLogger.IsEnabled("RequestStart"))
    httpLogger.Write("RequestStart", new { Url="http://clr", Request=aRequest });

然后需要實現IObserver<KeyValuePair<string, object>>接口,以便消費診斷數據。定義DiagnosticObserver,進行診斷日志消費:

public class DiagnosticObserver : IObserver<KeyValuePair<string, object>>
{
    public void OnCompleted()
    {
        //Noting to do
    }
    public void OnError(Exception error)
    {
        Console.WriteLine($"{error.Message}");
    }
    public void OnNext(KeyValuePair<string, object> pair)
    { 
        // 這里消費診斷數據
        Console.WriteLine($"{pair.Key}-{pair.Value}");
    }
}

ASP.NET Core 項目中默認就依賴了System.Diagnostics.DiagnosticSourceNuget包,同時在構建通用Web主機時,就注入了名為Microsoft.AspNetCoreDiagnosticListener

//GenericWebHostBuilder.cs
DiagnosticListener instance = new DiagnosticListener("Microsoft.AspNetCore");
services.TryAddSingleton<DiagnosticListener>(instance);
services.TryAddSingleton<DiagnosticSource>((DiagnosticSource) instance);

因此我們可以直接通過注入DiagnosticListener進行診斷日志的訂閱:

public void Configure(IApplicationBuilder app, IWebHostEnvironment env, DiagnosticListener diagnosticListener)
{
    diagnosticListener.Subscribe(new DiagnosticObserver());//訂閱診斷日志
}

當然也可以直接使用DiagnosticListener.AllListeners.Subscribe(IObserver<DiagnosticListener> observer);進行訂閱,不過區別是,接收的參數類型為IObserver<DiagnosticListener>

運行項目輸出:

Microsoft.AspNetCore.Hosting.HttpRequestIn.Start-Microsoft.AspNetCore.Http.DefaultHttpContext
Microsoft.AspNetCore.Hosting.BeginRequest-{ httpContext = Microsoft.AspNetCore.Http.DefaultHttpContext, timestamp = 7526300014352 }
Microsoft.AspNetCore.Routing.EndpointMatched-Microsoft.AspNetCore.Http.DefaultHttpContext
Microsoft.AspNetCore.Hosting.EndRequest-{ httpContext = Microsoft.AspNetCore.Http.DefaultHttpContext, timestamp = 7526300319214 }
Microsoft.AspNetCore.Hosting.HttpRequestIn.Stop-Microsoft.AspNetCore.Http.DefaultHttpContext

從中可以看出,ASP.NET Core Empty Web Project在一次正常的Http請求過程中分別在請求進入、請求處理、路由匹配都埋了點,除此之外還有請求異常、Action處理都有埋點。因此,根據需要,可以實現比如請求攔截、耗時統計等系列操作。

4.2. 耗時統計

基於以上知識,下面嘗試完成一個簡單的耗時統計。從上面的內容可知,ASP.NET Core在BeginRequest和EndRequest返回的診斷數據類型如下所示:

Microsoft.AspNetCore.Hosting.BeginRequest-{ httpContext = Microsoft.AspNetCore.Http.DefaultHttpContext, timestamp = 7526300014352 }
Microsoft.AspNetCore.Hosting.EndRequest-{ httpContext = Microsoft.AspNetCore.Http.DefaultHttpContext, timestamp = 7526300319214 }

因此只要拿到兩個timestamp就可以直接計算耗時,修改DiagnosticObserverOnNext方法如下:

private ConcurrentDictionary<string, long> startTimes = new ConcurrentDictionary<string, long>();
public void OnNext(KeyValuePair<string, object> pair)
{
    //Console.WriteLine($"{pair.Key}-{pair.Value}");
    //獲取httpContext
    var context = pair.Value.GetType().GetTypeInfo().GetDeclaredProperty("httpContext")
        ?.GetValue(pair.Value) as DefaultHttpContext;
    //獲取timestamp
    var timestamp = pair.Value.GetType().GetTypeInfo().GetDeclaredProperty("timestamp")
        ?.GetValue(pair.Value) as long?;
    switch (pair.Key)
    {
        case "Microsoft.AspNetCore.Hosting.BeginRequest":
            Console.WriteLine($"Request {context.TraceIdentifier} Begin:{context.Request.GetUri()}");
            startTimes.TryAdd(context.TraceIdentifier, timestamp.Value);//記錄請求開始時間
            break;
        case "Microsoft.AspNetCore.Hosting.EndRequest":
            startTimes.TryGetValue(context.TraceIdentifier, out long startTime);
            var elapsedMs = (timestamp - startTime) / TimeSpan.TicksPerMillisecond;//計算耗時
            Console.WriteLine(
                $"Request {context.TraceIdentifier} End: Status Code is {context.Response.StatusCode},Elapsed {elapsedMs}ms");
            startTimes.TryRemove(context.TraceIdentifier, out _);
            break;
    }
}

輸出如下,大功告成:

Request 0HM37UNERKGF0:00000001 Begin:https://localhost:44330
Request 0HM37UNERKGF0:00000001 End: Status Code is 200,Elapsed 38ms

上面有通過反射去獲取診斷數據屬性的代碼(var timestamp = pair.Value.GetType().GetTypeInfo().GetDeclaredProperty("timestamp") ?.GetValue(pair.Value) as long?;),非常不優雅。但我們可以安裝Microsoft.Extensions.DiagnosticAdapter包來簡化診斷數據的消費。安裝后,添加HttpContextDiagnosticObserver,通過添加DiagnosticName指定監聽的診斷名稱,即可進行診斷數據消費。

public sealed class HttpContextDiagnosticObserver
{
    private ConcurrentDictionary<string, long> startTimes = new ConcurrentDictionary<string, long>();
    
    [DiagnosticName("Microsoft.AspNetCore.Hosting.BeginRequest")]
    public void BeginRequest(HttpContext httpContext,long timestamp)
    {
        Console.WriteLine($"Request {httpContext.TraceIdentifier} Begin:{httpContext.Request.GetUri()}");
        startTimes.TryAdd(httpContext.TraceIdentifier, timestamp);//記錄請求開始時間
    }
    
    [DiagnosticName("Microsoft.AspNetCore.Hosting.EndRequest")]
    public void EndRequest(HttpContext httpContext,long timestamp)
    {
        startTimes.TryGetValue(httpContext.TraceIdentifier, out long startTime);
        var elapsedMs = (timestamp - startTime) / TimeSpan.TicksPerMillisecond;//計算耗時
        Console.WriteLine(
            $"Request {httpContext.TraceIdentifier} End: Status Code is {httpContext.Response.StatusCode},Elapsed {elapsedMs}ms");
        startTimes.TryRemove(httpContext.TraceIdentifier, out _);
    }
}

然后使用SubscribeWithAdapter進行訂閱即可。

public void Configure(IApplicationBuilder app, IWebHostEnvironment env, DiagnosticListener diagnosticListener)
{
    // diagnosticListener.Subscribe(new DiagnosticObserver());
    diagnosticListener.SubscribeWithAdapter(new HttpContextDiagnosticObserver());
}

到這里可能也有小伙伴說,我用ActionFilter也可以實現,沒錯,但這兩種方式是完全不同的,DiagnosticSource是完全異步的。

4.3. 應用場景思考

根據DiagnosticSource的特性,可以運用於以下場景 :

1. AOP:因為Diagnostics命名事件一般是成對出現的,因此可以做些攔截操作。比如在Abp集成Cap時,若想默認啟用Uow,就可以消費DotNetCore.CAP.WriteSubscriberInvokeBefore命名事件,創建Uow,再在命名事件DotNetCore.CAP.WriteSubscriberInvokeAfter中提交事務,並Dispose。
2. APM:SkyAPM-dotnet實現就是通過消費診斷日志,進行鏈路跟蹤。
3. EventBus:充分利用其發布訂閱模式,可將其用於進程內事件的發布與消費。

5. Activity(活動)

5.1. Activity 概述

那Activity又是何方神聖,用於解決什么問題呢?關於Activity官方只有一句簡要介紹:Represents an operation with context to be used for logging。(表示包含上下文的操作,用於日志記錄。)

Activity用來存儲和訪問診斷上下文,並由日志系統進行消費。當應用程序開始處理操作時,例如HTTP請求或隊列中的任務,它會在處理請求時創建Activity以在系統中跟蹤該Activity。Activity中存儲的上下文可以是HTTP請求路徑,方法,用戶代理或關聯ID:所有重要信息都應與每個跟蹤一起記錄。當應用程序調用外部依賴關系以完成操作時,它可能需要傳遞一些上下文(例如,關聯ID)以及依賴關系調用,以便能夠關聯來自多個服務的日志。

先來看下Activity主要以下核心屬性:

  1. Tags(標簽)
    IEnumerable<KeyValuePair<string, string>> Tags { get; } - 表示與活動一起記錄的信息。標簽的好例子是實例/機器名稱,傳入請求HTTP方法,路徑,用戶/用戶代理等。標簽不傳遞給子活動。
    典型的標簽用法包括添加一些自定義標簽,並通過它們進行枚舉以填充日志事件的有效負載。可通過Activity AddTag(string key, string value)添加Tag,但不支持通過Key檢索標簽。

  2. Baggage(行李)
    IEnumerable<KeyValuePair<string, string>> Baggage { get; } - 表示要與活動一起記錄並傳遞給其子項的信息。行李的例子包括相關ID,采樣和特征標記。
    Baggage被序列化並與外部依賴項請求一起傳遞。
    典型的Baggage用法包括添加一些Baggage屬性,並通過它們進行枚舉以填充日志事件的有效負載。
    可通過Activity AddBaggage(string key, string value)添加Baggage。並通過string GetBaggageItem(string key)獲取指定Key的Baggage。

  3. OperationName(操作名稱)
    string OperationName { get; } - 活動名稱,必須在構造函數中指定。

  4. StartTimeUtc
    DateTime StartTimeUtc { get; private set; } - UTC格式的啟動時間,如果不指定,則在啟動時默認指定為DateTime.UtcNow。可通過Activity SetStartTime(DateTime startTimeUtc)指定。

  5. Duration
    TimeSpan Duration { get; private set; } - 如果活動已停止,則代表活動持續時間,否則為0。

  6. Id
    string Id { get; private set; } - 表示特定的活動標識符。過濾特定ID可確保您僅獲得與操作中特定請求相關的日志記錄。該Id在活動開始時生成。Id傳遞給外部依賴項,並被視為新的外部活動的[ParentId]。

  7. ParentId
    string ParentId { get; private set; } - 如果活動是根據請求反序列化的,則該活動可能具有進程中的[Parent]或外部Parent。 ParentId和Id代表日志中的父子關系,並允許您關聯傳出和傳入請求。

  8. RootId
    string RootId { get; private set; } - 代表根Id

  9. Current
    static Activity Current { get; } - 返回在異步調用之間流動的當前Activity。

  10. Parent
    Activity Parent { get; private set; } - 如果活動是在同一過程中從另一個活動創建的,則可以使用Partent獲得該活動。但是,如果“活動”是根活動或父項來自流程外部,則此字段可能為null。

  11. Start()
    Activity Start() - 啟動活動:設置活動的Activity.Current和Parent,生成唯一的ID並設置StartTimeUtc(如果尚未設置)。

  12. Stop()
    void Stop() - 停止活動:設置活動的Activity.Current,並使用Activity SetEndTime(DateTime endTimeUtc)或DateTime.UtcNow中提供的時間戳計算Duration。

另外DiagnosticSource中也定義了兩個相關方法:

  1. StartActivity
    Activity StartActivity(Activity activity, object args) - 啟動給定的Activity,並將DiagnosticSource事件消息寫入OperationName.Start格式的命名事件中。
  2. StopActivity
    void StopActivity(Activity activity, object args) - 停止給定的Activity,並將DiagnosticSource事件消息寫入{OperationName}.Stop格式的命名事件中。

5.2. Activity在ASP.NET Core中的應用

要想弄懂Activity,我們還是得向源碼學習,看一下HostingApplicationDiagnostics的實現。首先來看下BeginRequst中的StartActivity方法。

private Activity StartActivity(HttpContext httpContext, out bool hasDiagnosticListener)
{
  Activity activity = new Activity("Microsoft.AspNetCore.Hosting.HttpRequestIn");
  hasDiagnosticListener = false;
  IHeaderDictionary headers = httpContext.Request.Headers;
  StringValues stringValues1;
  if (!headers.TryGetValue(HeaderNames.TraceParent, out stringValues1))
    headers.TryGetValue(HeaderNames.RequestId, out stringValues1);
  if (!StringValues.IsNullOrEmpty(stringValues1))
  {
    activity.SetParentId((string) stringValues1);
    StringValues stringValues2;
    if (headers.TryGetValue(HeaderNames.TraceState, out stringValues2))
      activity.TraceStateString = (string) stringValues2;
    string[] commaSeparatedValues = headers.GetCommaSeparatedValues(HeaderNames.CorrelationContext);
    if (commaSeparatedValues.Length != 0)
    {
      foreach (string str in commaSeparatedValues)
      {
        NameValueHeaderValue parsedValue;
        if (NameValueHeaderValue.TryParse((StringSegment) str, out parsedValue))
          activity.AddBaggage(parsedValue.Name.ToString(), parsedValue.Value.ToString());
      }
    }
  }
  this._diagnosticListener.OnActivityImport(activity, (object) httpContext);
  if (this._diagnosticListener.IsEnabled("Microsoft.AspNetCore.Hosting.HttpRequestIn.Start"))
  {
    hasDiagnosticListener = true;
    this.StartActivity(activity, httpContext);
  }
  else
    activity.Start();
  return activity;
}

從中可以看出,在ASP.NET Core 開始處理請求之前:

  1. 首先,創建了名為Microsoft.AspNetCore.Hosting.HttpRequestIn的Activity,該Activity首先嘗試從HTTP請求頭中獲取TraceParent/euqstId作為當前Activity的ParentId,這個很顯然,是用來鏈路跟蹤的。
  2. 其次,嘗試從CorrelationContext中獲取關聯上下文信息,然后將其添加到創建的Activity的Baggage中,進行關聯上下文的繼續傳遞。
  3. 然后,啟動Activity,然后向Name為Microsoft.AspNetCore.Hosting.HttpRequestIn.Start中寫入診斷日志。

這里大家可能有個疑問,這個關聯上下文信息CorrelationContext又是何時添加到Http請求頭中的呢?在System.Net.Http中的DiagnosticsHandler中添加的。
因此我們應該明白了,整個關聯上下文的傳遞機制。

緊接着再來看一看RequestEnd中的StopActivity方法。

private void StopActivity(Activity activity, HttpContext httpContext)
{
  if (activity.Duration == TimeSpan.Zero)
    activity.SetEndTime(DateTime.UtcNow);
  this._diagnosticListener.Write("Microsoft.AspNetCore.Hosting.HttpRequestIn.Stop", (object) httpContext);
  activity.Stop();
}

從中可以看出主要是先SetEndTime,再寫入Microsoft.AspNetCore.Hosting.HttpRequestIn.Stop命名事件;最后調用Stop方法停止當前Activity。

簡單總結一下,借助Activity中附加的Baggage信息可以實現請求鏈路上上下文數據的共享。

5.3. 應用場景思考

從上面的命名事件中可以看出,其封送的數據類型是特定的,因此可以借助Activity的Tags或Baggage添加自定義的數據進行共享。

按照上面我們的耗時統計,只能統計到整個http請求的耗時,但對於我們定位問題來說還是有困難,比如,某個api即有調用redis,又操作了消息隊列,同時又訪問了數據庫,那到底是那一段超時了呢?顯然不好直接定位,借助activity,我們就可以很好的實現細粒度的鏈路跟蹤。通過activity攜帶的信息,可以將一系列的操作關聯起來,記錄日志,再借助AMP進行可視化快速定位跟蹤。

6. 參考資料

  1. 在 .NET Core 中使用 Diagnostics (Diagnostic Source) 記錄跟蹤信息
  2. Logging using DiagnosticSource in ASP.NET Core
  3. .Net Core中的診斷日志DiagnosticSource講解
  4. Observer Design Pattern
  5. DiagnosticSource User Guide
  6. Activity User Guide
  7. DiagnosticSourcery 101 - Mark Rendle
  8. Improvements in .NET Core 3.0 for troubleshooting and monitoring distributed apps


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM