【.NET Core框架】诊断日志（DiagnosticSource）

介绍

DiagnosticSource它本身是一个基于发布订阅模式的工作模式，由于它本身的实现方式是异步的，所以不仅仅可以把它用到日志上，还可以用它实现异步操作，或者用它简化实现发布订阅的功能。DiagnosticSource本身是一个抽象类，我们最常用到的是它的子类DiagnosticListener，通过DiagnosticSource的Write方法实现发布一条有具体名称的消息，然后通过IObserver去订阅消息。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方法，这个方法用于判断是够存在对应名称的消费者，这样可以有效的避免发送消息浪费。

订阅消息

上面我们提到了订阅消息是通过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);
}

有了具体的订阅者实现类，我们就可以为发布者注册订阅者了

//AllListeners获取所有发布者,它的类型是IObservable<DiagnosticListener>,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}");
        }));
    }
}));

具体实现可总结为两步，首先为发布者注册订阅者，然后获取订阅者获取发布的消息。这种写法还是比较复杂的，首先需要实现订阅者类，然后通过一系列复杂的操作，才能完成消息订阅，然后还要自己获取发布的消息，解析具体的消息值，总之操作流程非常繁琐。微软似乎也意识到了这个问题，于是乎给我提供了一个关于实现订阅者的便利方法，编辑项目文件引入DiagnosticAdapter包

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

通过这个包解决了我们两个痛点，首先是关于订阅者的注册难问题，其次解决了关于发布消息解析难的痛点。我们可以直接订阅一个适配类来充当订阅者的载体，其次我们可以定义方法模拟订阅去订阅消息，而这个方法的参数就是我们发布的消息内容。

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 =>
{
        //适配订阅
        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的方式。

多个消息类型演示

发布消息：

            //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 = "隔壁" });
            }

            //MyTest2
            diagnosticSource = new DiagnosticListener("MyTest2");
            pubName = "MyTest2.Log";
            //判断是否存在MyTest.Log的订阅者
            if (diagnosticSource.IsEnabled(pubName))
            {
                //发送名为MyTest.Log的消息，包含Name，Address两个属性
                diagnosticSource.Write(pubName, new { Name = "old王2", Address = "隔壁2" });
            }


    DiagnosticListener.AllListeners.Subscribe(new AnonymousObserver<DiagnosticListener>(listener =>
    {
            listener.SubscribeWithAdapter(new MyDiagnosticListener());
    }));

    public class MyDiagnosticListener
    {
        //发布的消息主题名称
        [DiagnosticName("MyTest.Log")]
        //发布的消息参数名称和发布的属性名称要一致
        public void MyLog(string name, string address)
        {
            System.Console.WriteLine($"监听名称:MyTest.Log");
            System.Console.WriteLine($"获取的信息为:{name}的地址是{address}");
        }
        //发布的消息主题名称
        [DiagnosticName("MyTest2.Log")]
        //发布的消息参数名称和发布的属性名称要一致
        public void MyLog2(string name, string address)
        {
            System.Console.WriteLine($"监听名称:MyTest2.Log");
            System.Console.WriteLine($"获取的信息为:{name}的地址是{address}");
        }
    }

DotNetCore源码中诊断日志的埋点

在.Net Core的源码中，微软默认在涉及到网络请求或处理请求等许多重要的节点都使用了DiagnosticListener来发布拦截的消息，接下来就罗列一些我知道的比较常见的埋点

在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);

我们可以看下在处理请求的过程中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和开始时间戳信息
订阅aspnetcore消息：

    public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
    {
        var listener = app.ApplicationServices.GetRequiredService<DiagnosticListener>();
        listener.SubscribeWithAdapter(new AspNetCoreDiagnosticListener());
    }

    public class AspNetCoreDiagnosticListener
    {
        [DiagnosticName("Microsoft.AspNetCore.Hosting.HttpRequestIn.Start")]
        public void Start(HttpContext httpContext, long startTimestamp)
        {
            System.Console.WriteLine($"Start,url:{ httpContext.Request.Path.Value}");
        }
        [DiagnosticName("Microsoft.AspNetCore.Hosting.BeginRequest")]
        public void BeginRequest(HttpContext httpContext, long startTimestamp)
        {           
            System.Console.WriteLine($"BeginRequest,url:{ httpContext.Request.Path.Value}");
        }
        [DiagnosticName("Microsoft.AspNetCore.Hosting.EndRequest")]
        public void EndRequest(HttpContext httpContext, long startTimestamp)
        {
            System.Console.WriteLine($"EndRequest,url:{ httpContext.Request.Path.Value}");
        }
        [DiagnosticName("Microsoft.AspNetCore.Hosting.UnhandledException")]
        public void Exception(HttpContext httpContext, Exception exception)
        {
            System.Console.WriteLine($"EndRequest,url:{ httpContext.Request.Path.Value}");
        }
    }

HttpClinet

    DiagnosticListener.AllListeners.Subscribe(new MyObserver<DiagnosticListener>(listener =>
    {
        listener.SubscribeWithAdapter(new HttpClienDiagnosticListener());
    }));

    public class HttpClienDiagnosticListener
    {

        [DiagnosticName("System.Net.Http.Request")]
        public void HttpRequest(System.Net.Http.HttpRequestMessage request)
        {
            Console.WriteLine($"request,url:{request.RequestUri.AbsoluteUri}");
        }

        [DiagnosticName("System.Net.Http.Response")]
        public void HttpResponse(System.Net.Http.HttpResponseMessage response)
        {
            Console.WriteLine($"response,code:{response.StatusCode.ToString()},content:{response.Content.ReadAsStringAsync().Result}");
        }

        [DiagnosticName("System.Net.Http.Exception")]
        public void HttpException(System.Net.Http.HttpRequestMessage request, Exception exception)
        {

        }
    }

其他

在.Net Core相关的源码中还有许多其他关于DiagnosticListener的埋点信息比如请求执行到Action的时候或者出现全局异常的时候都有类似的处理。同样在EFCore中也存在这些埋点信息，有兴趣的可以自行查阅相关源码和SkyAPM-dotnet源码

案例1、统计http请求耗时

public void Configure(
            IApplicationBuilder app
            , IWebHostEnvironment env
            , DiagnosticListener diagnosticListener)
{
            //HTTP耗时记录
            diagnosticListener.SubscribeWithAdapter(new HttpContextDiagnosticObserver<T>(logger));
}

订阅者：

public sealed class HttpContextDiagnosticObserver<T> : IDisposable
    {
        private readonly ConcurrentDictionary<string, long> _startTimeDict = new ConcurrentDictionary<string, long>();
        private readonly ILogger<T> _logger;
        public HttpContextDiagnosticObserver(ILogger<T> logger)
        {
            this._logger = logger;
        }

        [DiagnosticName("Microsoft.AspNetCore.Hosting.BeginRequest")]
        public void BeginRequest(HttpContext httpContext, long timestamp)
        {
            var request = httpContext.Request;
            if (SkipPath(request.Path))
            {
                return;
            }
            string requestID = httpContext.TraceIdentifier;
            this._startTimeDict.TryAdd(requestID, timestamp);//记录请求开始时间
            this._logger.LogDebug($"RequestID=>[{requestID}], Method=>[{request.Method}], Begin=>[{request.GetDisplayUrl()}], User=>[{this.GetUser(httpContext)}]");
        }

        [DiagnosticName("Microsoft.AspNetCore.Hosting.EndRequest")]
        public void EndRequest(HttpContext httpContext, long timestamp)
        {
            var request = httpContext.Request;
            if (SkipPath(request.Path))
            {
                return;
            }
            string requestID = httpContext.TraceIdentifier;
            this._startTimeDict.TryGetValue(requestID, out long startTime);
            var elapsedMs = (timestamp - startTime) / TimeSpan.TicksPerMillisecond;//计算耗时
            this._startTimeDict.TryRemove(httpContext.TraceIdentifier, out _);
            this._logger.LogDebug($"RequestID=>[{requestID}], Method=>[{request.Method}], End=>[{request.GetDisplayUrl()}], StatusCode=>[{httpContext.Response.StatusCode}], Elapsed=>[{elapsedMs} ms], User=>[{this.GetUser(httpContext)}]");
        }

        private static bool SkipPath(string path)
        {
            return path == null
                || path.EndsWith(".css", StringComparison.CurrentCultureIgnoreCase)
                || path.EndsWith(".js", StringComparison.CurrentCultureIgnoreCase)
                || path.EndsWith(".jpg", StringComparison.CurrentCultureIgnoreCase)
                || path.EndsWith(".png", StringComparison.CurrentCultureIgnoreCase)
                || path.EndsWith(".gif", StringComparison.CurrentCultureIgnoreCase)
                || path.EndsWith(".svg", StringComparison.CurrentCultureIgnoreCase)
                || path.EndsWith(".woff", StringComparison.CurrentCultureIgnoreCase)
                || path.EndsWith(".woff2", StringComparison.CurrentCultureIgnoreCase)
                || path.EndsWith(".eot", StringComparison.CurrentCultureIgnoreCase)
                || path.EndsWith(".ttf", StringComparison.CurrentCultureIgnoreCase)
                || path.Contains("/check/", StringComparison.CurrentCultureIgnoreCase)
                || path.Contains("_health_", StringComparison.CurrentCultureIgnoreCase)
                || path.EndsWith(".ico", StringComparison.CurrentCultureIgnoreCase)
                || path.Equals("/")
                ;
        }

        /// <summary>
        /// 登录用户
        /// </summary>
        /// <param name="httpContext"></param>
        /// <returns></returns>
        private string GetUser(HttpContext httpContext)
        {
            string email = null;
            if (httpContext.User.Identity.IsAuthenticated)
            {
                email = httpContext.User.Identities.First(u => u.IsAuthenticated).FindFirst(ClaimTypes.Email).Value;
            }
            else
            {
                email = "no-login";
            }
            return email;
        }

        public void Dispose()
        {
            this._startTimeDict.Clear();
        }

    }

参考：
https://www.cnblogs.com/wucy/p/13532534.html

posted @ 2021-03-09 19:54 .Neterr 阅读(285) 评论(0) 编辑收藏举报

刷新页面返回顶部

.Neter学习笔记