后端可观测性【免费下载链接】serilogSimple .NET logging with fully-structured events项目地址https://gitcode.com/gh_mirrors/se/serilog点击查看免费下载本报告基于 Serilog 仓库results/net4.5.2/NestedLoggerLatencyBenchmark-report-github.md中的 BenchmarkDotNet 实测结果深入剖析通过ForContextT()创建的嵌套 Logger 写日志比根 Logger 慢多少这一核心问题先还原完整性能数据与运行环境再从 NestedLoggerLatencyBenchmark.cs 的基准实现出发沿 Logger.ForContext →FixedPropertyEnricher.Enrich()→PostLevelCheckEmit()的调用链解释 3.6 倍开销从何而来最后给出吞吐量Throughput模式下的数据解读方法、跨平台跨框架的结果对比与实战调优建议。读者读完可获得嵌套 Logger 延迟开销的量化认知、基准复现的完整命令、以及基于源码的最小化上下文设计原则。一、基准报告全景环境、方法与原始数据1.1 报告文件与测试目标本报告对应的基准类为 NestedLoggerLatencyBenchmark.cs其源码注释开门见山Tests the overhead of writing through a nested logger.即测试通过嵌套 Logger 写入日志事件的额外开销。该基准被注册在 Harness.cs 的NestedLoggerLatency测试方法中可通过dotnet test筛选器独立运行。1.2 运行环境信息原报告原文报告头部ini块完整记录了主机环境对理解数据可比性至关重要Host Process Environment Information: BenchmarkDotNet.Corev0.9.9.0 OSMicrosoft Windows NT 6.2.9200.0 ProcessorIntel(R) Core(TM) i7-3720QM CPU 2.60GHz, ProcessorCount8 Frequency2533306 ticks, Resolution394.7411 ns, TimerTSC CLRMS.NET 4.0.30319.42000, Arch64-bit RELEASE [RyuJIT] GCConcurrent Workstation JitModulesclrjit-v4.6.1080.0 TypeNestedLoggerLatencyBenchmark ModeThroughput关键环境参数解读参数值含义BenchmarkDotNet.Corev0.9.9.0早期 BenchmarkDotNet 版本对应中位数 StdDev Scaled的数据格式OSWindows NT 6.2.9200.0Windows 8Build 9200Processori7-3720QM 2.60GHzIvy Bridge 移动端四核八线程 CPU约 2012 年产品TimerTSC基于时间戳计数器Rdtsc的高精度计时CLRMS.NET 4.0.30319.NET Framework 4.5.264-bit RELEASE启用 RyuJITGCConcurrent Workstation工作站并发 GC说明测试进程是典型客户端应用配置ModeThroughput吞吐量模式尽可能短的时间内执行尽可能多的操作报告每次操作耗时需要说明当前仓库的 Serilog.PerformanceTests.csproj 目标框架已演进为net10.0;net9.0;net8.0并引用 BenchmarkDotNet 0.15.2net4.5.2目录下的这份报告属于仓库历史基准输出反映的是 .NET Framework 4.5.2 早期 BenchmarkDotNet 时代的数据应作为相对比例而非绝对耗时来使用。1.3 原始性能数据原报告全文核心Method | Median | StdDev | Scaled | Scaled-SD | ------------- |----------- |---------- |------- |---------- | RootLogger | 14.5315 ns | 0.6035 ns | 1.00 | 0.00 | NestedLogger | 52.6109 ns | 1.0453 ns | 3.60 | 0.15 |四列统计量的语义Median中位数Throughput 模式下所有样本按耗时排序后的中位值代表典型单次操作耗时。RootLogger 约 14.53 nsNestedLogger 约 52.61 ns。StdDev标准差样本波动幅度。NestedLogger 的 1.0453 ns 在 52.6 ns 的量级上约 2%说明测量稳定。Scaled相对基准倍率NestedLogger / RootLogger的耗时比值基线方法[Benchmark(Baseline true)]恒为 1.00。NestedLogger 为 3.60即嵌套 Logger 写路径耗时约为根 Logger 的3.6 倍。Scaled-SD倍率的标准差0.15 表明 3.60 这个倍率的置信范围约为 ±0.15。结论原报告核心在 .NET Framework 4.5.2 上通过ForContextT()派生的嵌套 Logger 写入一个预构建LogEvent的中位耗时为 52.6 ns是根 Logger14.5 ns的 3.6 倍。二、基准实现逐行解读为什么对比是干净的2.1 完整基准代码NestedLoggerLatencyBenchmark.cs 全文仅 32 行结构清晰public class NestedLoggerLatencyBenchmark { ILogger _log null!, _nested null!; readonly LogEvent _event Some.InformationEvent(); [GlobalSetup] public void Setup() { _log new LoggerConfiguration() .WriteTo.Sink(new NullSink()) .CreateLogger(); _nested _log.ForContextNestedLoggerLatencyBenchmark(); } [Benchmark(Baseline true)] public void RootLogger() { _log.Write(_event); } [Benchmark] public void NestedLogger() { _nested.Write(_event); } }2.2 基准设计的关键点复用预构建LogEvent_event在字段初始化时通过Some.InformationEvent()创建一次两个基准方法都直接调用Write(LogEvent)重载见 Logger.cs。这排除了消息模板解析与属性绑定对测量的干扰只测量日志管道本身的转发开销——是延迟Latency基准而非分配Allocations基准。NullSink 隔离输出成本NullSink.Emit()为空实现见 NullSink.cs测量结果不包含任何真实输出设备的 I/O 成本纯粹是 Serilog 内部管道的 CPU 开销。同一 Logger 实例派生嵌套 Logger_nested _log.ForContextNestedLoggerLatencyBenchmark()走的是 Logger.ForContext(Type source) 重载它内部转发到ForContext(Constants.SourceContextPropertyName, source.FullName)即以类型全名Serilog.PerformanceTests.NestedLoggerLatencyBenchmark为值创建SourceContext属性。事件零属性Some.InformationEvent()见 Some.cs用默认模板Hello, world!绑定出零个属性的事件因此两个基准方法测得的就是最小化路径上的纯开销差。2.3 基线方法标记RootLogger标注[Benchmark(Baseline true)]这就是报告中Scaled 1.00的来源NestedLogger未标注基线其Scaled 3.60由 BenchmarkDotNet 自动计算为相对基线的倍数。三、源码级原理3.6 倍开销从哪来3.1 嵌套 Logger 的结构派生即包装ForContext的本质是复制一份 Logger但把_sink指回父 Logger、并附加一个 enricher。看 Logger.ForContext(ILogEventEnricher) 的实现public ILogger ForContext(ILogEventEnricher enricher) { if (enricher null!) return this; return new Logger( _messageTemplateProcessor, _minimumLevel, _levelSwitch, this, // ← 新 Logger 的 _sink 指向父 Logger 自身 enricher, // ← 新 Logger 携带的上下文 enricher null, _overrideMap); }而ForContext(string, object?, bool)会把值包装成FixedPropertyEnrichervar propertyValue _messageTemplateProcessor.CreatePropertyValue(value, destructureObjects); var enricher new FixedPropertyEnricher(new(propertyName, propertyValue));因此_nested的写路径是嵌套 Logger → 追加SourceContext属性 → 作为事件转发给根 Logger → 根 Logger 再追加自己的 enricher若存在→ 根 Logger 的 sink。3.2 写路径调用链的两次PostLevelCheckEmit两个基准方法最终都进入Write(LogEvent logEvent)Logger.cspublic void Write(LogEvent logEvent) { if (logEvent null!) return; if (!IsEnabled(logEvent.Level)) return; PostLevelCheckEmit(logEvent); SelfMetrics.PipelineEventEmitted.Add(1); }随后核心在PostLevelCheckEmitLogger.csvoid PostLevelCheckEmit(LogEvent logEvent) { try { _enricher.Enrich(logEvent, _messageTemplateProcessor); } catch (Exception ex) { SelfLog.WriteLine(Exception {0} caught while enriching {1} with {2}., ex, logEvent, _enricher); } _sink.Emit(logEvent); }沿调用链逐层核算开销根 Logger 路径RootLoggerWrite(_event)→ 1 次IsEnabled级别检查 → 1 次PostLevelCheckEmit_enricher为空的EmptyEnricher几乎零成本→NullSink.Emit。约 14.5 ns。嵌套 Logger 路径NestedLoggerWrite(_event)→ 1 次IsEnabled→PostLevelCheckEmit此时_enricher是携带SourceContext的FixedPropertyEnricher其Enrich()见 FixedPropertyEnricher.cs调用logEvent.AddPropertyIfAbsent(...)追加SourceContext属性然后_sink.Emit(_event)又把事件转交给根 Logger而根 Logger 作为ILogEventSink收到事件时走的是 ILogEventSink.Emitvoid ILogEventSink.Emit(LogEvent logEvent) { Guard.AgainstNull(logEvent); // Bypasses the level check so that child loggers // using this one as a sink can increase verbosity. PostLevelCheckEmit(logEvent); }也就是说嵌套路径包含两次PostLevelCheckEmit一次发生在嵌套 Logger一次发生在被当作 sink 的根 Logger外加一次属性追加。这正是3.6 倍开销的主要构成层级转发本身在纳秒级管道中就是不可忽略的倍增项。3.3 为什么 SourceContext 属性追加也在成本内ForContextTSource()会向事件追加SourceContext属性。在基准场景中事件原本零属性AddPropertyIfAbsent需要执行属性名合法性校验、值已由CreatePropertyValue在ForContext时预转换、向事件的属性集合插入。虽然单次追加是纳秒级操作但在 52 ns 的总开销中占比不可忽视。这也解释了为什么官方基准中RootLogger vs NestedLogger不是 2 倍而是 3.6 倍——属性追加 双PostLevelCheckEmit 嵌套转发叠加而成。3.4 级别检查的特别之处值得注意嵌套路径中根 Logger 被作为 sink 调用时绕过了级别检查源码注释明确Bypasses the level check so that child loggers using this one as a sink can increase verbosity。这意味着嵌套 Logger 可以根据自己的_minimumLevel决定是否接收事件事件一旦进入管道无论根 Logger 的级别如何都会被转发到底层 sink——级别过滤的职责被下放到每一层自己身上。相关的最小级别继承矩阵可以在 ChildLoggerTests.cs 中找到详尽的用例覆盖。四、把数据放到坐标里跨框架、跨运行模式对比同一基准在仓库的多个 results 目录下均有历史输出可观察耗时与倍率的演变运行环境RootLogger 中位数NestedLogger 中位数Scaled.NET Framework 4.5.2本报告results/net4.5.214.53 ns52.61 ns3.60.NET Core 1.0results/netcoreapp1.014.01 ns59.45 ns4.23.NET Core 2.0results/netcoreapp2.0Mac OS X / i7-7567U11.78 ns41.70 ns3.54观察要点倍率稳定在 3.54.2 之间无论 .NET Framework 还是 .NET Core、无论 Windows 还是 macOS嵌套 Logger 的相对开销都落在约 3.54.2 倍区间说明嵌套层级转发是稳定的结构性成本而非某次运行时特有的回归。绝对耗时受硬件与框架影响显著i7-3720QM2012 年移动 CPU上的 52.6 ns 与 i7-7567UKaby Lake上的 41.7 ns 不可直接横向比较对比时应优先看Scaled倍率。RyuJIT 与 CLR 差异net4.5.2 报告标注Arch64-bit RELEASE [RyuJIT]netcoreapp1.0/2.0 同样为 64bit RyuJITJIT 后端一致性使得倍率有可比性。需要注意的局限三份报告的主机硬件、操作系统、BenchmarkDotNet 版本各不相同任何跨报告对比都应同时标注环境差异仅将Scaled作为同一基准设计下的相对参考。五、如何在本仓库复现该基准5.1 完整跑全部性能测试仓库根目录提供一键脚本 RunPerfTests.ps1其流程为先执行./Build.ps1构建再对test/*.PerformanceTests下的每个项目执行dotnet test -c Release# 在仓库根目录执行 ./RunPerfTests.ps15.2 单独运行 NestedLoggerLatency性能测试项目以 xUnit 包装 BenchmarkDotNet见 Harness.cs 的类注释可通过--filter只跑嵌套 Logger 延迟基准dotnet test -c Release --filter FullyQualifiedNameSerilog.PerformanceTests.Harness.NestedLoggerLatency测试方法内部即执行BenchmarkRunner.RunNestedLoggerLatencyBenchmark()。当前 Serilog.PerformanceTests.csproj 的目标框架为net10.0;net9.0;net8.0实际运行需要本机安装对应 .NET SDK想要复现 net4.5.2 报告需在具备 .NET Framework 4.5.2 的环境下使用历史版本的 BenchmarkDotNet 与测试工程这已超出当前仓库默认构建范围。5.3 复现时的注意事项请使用Release 配置运行dotnet test -c ReleaseDebug 配置下 JIT 优化不同测出的绝对数值与相对倍率都会失真。基准对机器负载敏感关闭不必要的后台进程优先在空闲、稳定的机器上执行以获得较小的 StdDev。修改基准前先阅读 Some.cs 与 NullSink.cs它们是所有性能基准公用的事件工厂与空输出设施。六、解读与工程实践如何把 3.6 倍开销用到实处6.1 数据回答的问题本报告回答了三个工程问题嵌套 Logger 是否免费不免费。每次事件写入的额外开销约 38 ns52.61 − 14.53在每次操作纳秒级的日志管道中是显著的相对倍增3.6 倍。开销来自哪嵌套转发导致的第二次PostLevelCheckEmit 每次事件的SourceContext属性追加而非 sink 输出本身NullSink 已隔离 I/O。绝对数值有多大约 52 ns/次。在绝大多数业务系统中这意味着每秒数千万次以上日志写入量级才会构成瓶颈——热路径优化的收益远大于绝对时间。6.2 工程建议按热点控制层级深度ForContext每嵌套一层就增加一次PostLevelCheckEmit与一次属性追加。避免在极高频如每次请求/循环迭代内代码路径上做无谓的多层ForContext包装优先在边界处如中间件、请求入口一次性建立上下文 Logger 并复用。预构建事件可复用基准本身证明了预构建LogEventWrite(LogEvent)的用法把成本压到最低业务中若同一事件模板高频出现可考虑缓存解析后的模板与属性降低模板解析路径开销相关机制见 MessageTemplateCache.cs。级别过滤先行Write的第一步是IsEnabled快速检查Logger.cs在成本最低的位置就把被过滤的事件挡在管道外。高频路径上先用Log.IsEnabled(LogEventLevel.Verbose)之类判断再构造昂贵参数是省下完整管道成本的关键。配合其他基准综合评估本基准衡量延迟AllocationsBenchmark.cs 衡量分配NestedLoggerCreationBenchmark.cs 衡量ForContext创建成本。三者组合才能完整回答嵌套 Logger 值不值。6.3 数据的边界与诚实解读本报告数据仅代表 .NET Framework 4.5.2 i7-3720QM 主机 早期 BenchmarkDotNet 的实测快照不构成对任意现代硬件的性能承诺。3.6 倍是纯管道转发的相对开销真实应用中加入序列化、输出 I/O 后嵌套层级的相对占比会被稀释。引用本数据时应同时引用 NestedLoggerLatencyBenchmark.cs 的基准设计避免脱离测量前提使用绝对数值。七、小结results/net4.5.2/NestedLoggerLatencyBenchmark-report-github.md这份基准报告以最小化实验回答了 Serilog 一个基础性能问题通过ForContextTSource()派生的嵌套 Logger 写事件的中位耗时52.61 ns是根 Logger14.53 ns的 3.6 倍。结合 Logger.cs 源码可见倍率来源于嵌套转发带来的二次PostLevelCheckEmit与每次事件的SourceContext属性追加。跨 .NET Framework / .NET Core 的历史报告显示倍率稳定在 3.54.2 区间证明这是结构性的层级转发成本。对工程实践而言该数据的价值不在于52 ns 绝对值而在于提示上下文应建立在边界、事件应复用、级别过滤应前置——这正是把 Serilog 用到极致的三条铁律。赞分享后端可观测性【免费下载链接】serilogSimple .NET logging with fully-structured events项目地址https://gitcode.com/gh_mirrors/se/serilog点击查看免费下载相关推荐Dragonboat fsync 落盘延迟基准全解析磁盘实测数据与 Raft 日志写入路径剖析Dragonboat fsync 落盘延迟基准全解析磁盘实测数据与 Raft 日志写入路径剖析 导读 本文围绕 Dragonboat 仓库 tools/fsy集群算法后端Polly 遥测Telemetry性能开销实测TelemetryBenchmark 基准报告解读与源码剖析Polly 遥测Telemetry性能开销实测TelemetryBenchmark 基准报告解读与源码剖析 本篇文章以仓库中由 BenchmarkDotN后端微服务IronClaw 零开销延迟追踪宏ironclaw_observability 的设计契约与实现剖析IronClaw 零开销延迟追踪宏ironclaw_observability 的设计契约与实现剖析 ironclaw_observability 是 Iro人工智能AI 应用交互助手AI Agent创作声明：本文部分内容由AI辅助生成（AIGC），仅供参考