后端可观测性【免费下载链接】serilogSimple .NET logging with fully-structured events项目地址https://gitcode.com/gh_mirrors/se/serilog点击查看免费下载导读本篇文章以仓库内 MessageTemplateParsingBenchmark 基准报告 为核心围绕 Serilog 的消息模板解析Message Template Parsing这一核心链路的性能展开。你将了解到这份 BenchmarkDotNet 报告到底测量了什么、MessageTemplateParser是如何实现高性能解析的、两个基准用例的耗时差异从何而来以及如何在本地复现这套基准并对照不同运行时的结果。Serilog 采用 Message Templates。消息模板解析就是这条链路上最基础的一环把用户写下的Hello, {Name}这样的字符串拆解为一串文本 token 与属性 token后续的属性绑定、渲染、JSON 序列化都建立在它之上。因此解析器的单次调用成本直接决定了每次写日志的固定开销性能基准报告正是对这一成本的量化。一、这份基准报告在测什么报告文件本身是 BenchmarkDotNet 在.NET Core64 位 RyuJIT上、以Throughput吞吐模式输出的 Markdown 结果完整复述如下Host Process Environment Information: BenchmarkDotNet.Corev0.9.9.0 OSWindows Processor?, ProcessorCount8 Frequency2533306 ticks, Resolution394.7411 ns, TimerTSC CLRCORE, Arch64-bit ? [RyuJIT] GCConcurrent Workstation dotnet cli version: 1.0.0-preview2-003121 TypeMessageTemplateParsingBenchmark ModeThroughputMethodMedianStdDevScaledScaled-SDEmptyTemplate188.2760 ns2.4773 ns1.000.00DefaultConsoleOutputTemplate2,753.6243 ns22.7107 ns14.540.22两个被测方法来自 MessageTemplateParsingBenchmark.csnamespace Serilog.PerformanceTests; [MemoryDiagnoser] public class MessageTemplateParsingBenchmark { MessageTemplateParser _parser new(); [Benchmark(Baseline true)] public void EmptyTemplate() { _parser.Parse(); } [Benchmark] public void DefaultConsoleOutputTemplate() { _parser.Parse({Timestamp:yyyy-MM-dd HH:mm:ss} [{Level}] {Message}{NewLine}{Exception}); } }即一次调用new MessageTemplateParser().Parse(...)分别以空字符串基线和Serilog 默认控制台输出模板为输入统计中位数耗时。测试类标注了[MemoryDiagnoser]意味着同时记录内存分配在较新的 BenchmarkDotNet 版本报告中有对应列。需要说明的是当前仓库中的 MessageTemplateParsingBenchmark.cs 还包含第三个方法LiteralTextOnly()一段不含任何属性的纯文本而这份 netcoreapp1.0 历史报告只包含前两个方法可以推断该报告早于LiteralTextOnly用例的加入——这也提示我们基准报告是对特定源码版本的快照对照时应注意被测方法的差异。二、被测对象MessageTemplateParser 源码拆解基准直接调用的是 MessageTemplateParser.cs它是IMessageTemplateParser的公开实现。要理解耗时差异需要看清它的内部流程。2.1 Parse 入口与 Tokenize 主循环public MessageTemplate Parse(string messageTemplate) { Guard.AgainstNull(messageTemplate); return new(messageTemplate, Tokenize(messageTemplate)); }Parse先把模板交给Tokenize惰性求值生成 token 序列再构造MessageTemplate。构造时 MessageTemplate.cs 会做三件事保存原始Text把 token 序列ToArray()固化为TokenArray遍历 token 数组用GetElementsOfTypeToArrayPropertyToken收集所有属性 token判断它们是全位置参数如{0}、{1}还是命名参数混合使用还会向SelfLog写出告警。Tokenize是一个while(true)主循环交替调用ParseTextToken和ParsePropertyToken直到消费完整个模板var nextIndex 0; while (true) { var beforeText nextIndex; var tt ParseTextToken(nextIndex, messageTemplate, out nextIndex); if (nextIndex beforeText) yield return tt; if (nextIndex messageTemplate.Length) yield break; var beforeProp nextIndex; var pt ParsePropertyToken(nextIndex, messageTemplate, out nextIndex); if (beforeProp nextIndex) yield return pt; if (nextIndex messageTemplate.Length) yield break; }2.2 文本 token 的快速路径与转义处理ParseTextToken的性能设计值得注意它先尝试IndexOfAny(CurlyBraceChars)直接找到下一个{或}。如果后面不再有花括号整个剩余片段就是纯文本一次Substring搞定不分配任何 StringBuilder源码注释明确说明了这一意图大多数情况下不会遇到转义序列因此可以只用一次Substring分配。只有当真的命中{{/}}转义序列时才走慢路径——用StringBuilder逐字符累积把转义后的单个花括号拼进文本 token。也就是说最常见的“无转义”场景是近乎零分配的快速路径而转义是罕见情况。2.3 属性 token 的解析与校验ParsePropertyToken拿到{...}的原始片段后依次执行IndexOf(})定位闭合括号找不到就把剩余文本当作TextToken容错TrySplitTagContent用:format 分隔符和,alignment 分隔符把{属性名:格式,对齐}拆成三部分属性名校验若首字符是数字则必须全部是数字否则按文本处理位置参数如{0}否则走标识符规则首字符必须是字母或_后续允许字母、数字、_与..之后要求重新开始一段标识符支持{test.name}这样的嵌套属性名全数字的{0}在 PropertyToken.cs 构造时解析为_position从而标记为IsPositional解构提示符destructuring hint表示Destructure完整展开对象$表示Stringify转字符串其余为Default——见 Destructuring.cs 中的枚举定义format 校验逐个字符检查只要不包含}即合法因此{Time:hh:mm}、{Number:##.0;-##.0;zero}这种含冒号、分号、加号的格式都能通过alignment 校验宽度必须能解析为整数且不能是int.MinValue开头的正号对齐按文本处理-表示左对齐否则右对齐最终构造 Alignment.cs 的Alignment结构。2.4 容错非法模板按文本输出解析器采用“尽力而为”策略见Parse的 XML 注释语法不合法时绝不抛异常而是把对应片段降级为TextToken。例如{}、{$}、{Hello,10}、{Hello,-aa}、{Hello,}都会被当作普通文本。这一容错设计保证了日志 API 在模板写错时依然可用代价是解析路径上多了若干校验分支。三、两个被测用例的逐个拆解3.1 EmptyTemplate基线188.3 ns输入是空字符串。Tokenize的第一行就是长度检查if (messageTemplate.Length 0) { yield return EmptyTextToken; yield break; }直接复用静态的EmptyTextTokennew TextToken()零字符串分配随后MessageTemplate构造执行string.Concat、ToArray、遍历 token 数组收集属性结果为空。整条路径只创建MessageTemplate与一个 token 数组对象这解释了为什么它能以188 ns量级完成并被选作 Scaled 基准值 1.00。3.2 DefaultConsoleOutputTemplate基准用例2,753.6 ns输入是 Serilog 控制台输出的默认模板{Timestamp:yyyy-MM-dd HH:mm:ss} [{Level}] {Message}{NewLine}{Exception}拆开来看它包含5 个属性 token与若干文本片段{Timestamp:yyyy-MM-dd HH:mm:ss}属性名Timestamp 带 10 个字符的 format[{Level}]中的{Level}、{Message}、{NewLine}、{Exception}4 个无 format 属性文本片段空格、[、]右括号加空格。与空模板相比每个属性 token 都要走IndexOf(})、Substring、TrySplitTagContent、属性名逐字符校验、format 逐字符校验、构造PropertyToken等一连串步骤MessageTemplate构造还要对 10 来个 token 做数组分配与类型过滤。token 越多、格式串越长解析的固定开销越大——这正是 14.54 倍差距的直接来源。四、结果数据解读4.1 指标说明BenchmarkDotNet 报告中的关键列含义Median中位数耗时比均值更能抵抗 JIT 预热抖动是吞吐基准的默认报告值本报告为 v0.9.9.0 老版本格式仅输出中位数StdDev标准差反映结果稳定性两个用例都只有 223 ns 的波动说明解析路径非常确定Scaled / Scaled-SD相对基线方法EmptyTemplate的耗时比值及其标准差。DefaultConsoleOutputTemplate的Scaled14.54表示完整模板解析成本约为空模板的14.5 倍。4.2 跨运行时与版本的对照仓库results/目录还保存了同一基准在其他运行时上的历史报告正好可以横向对比运行环境报告路径EmptyTemplateDefaultConsoleOutputTemplateScaled.NET Corenetcoreapp1.0Windowsresults/netcoreapp1.0/...188.28 nsMedian2,753.62 nsMedian14.54.NET Framework 4.5.2Windowsresults/net4.5.2/...183.32 nsMedian2,636.22 nsMedian14.40.NET Corenetcoreapp2.0macOSresults/netcoreapp2.0/...371.0 nsMean2,912.1 nsMean7.86三个值得注意的观察点基于报告数据本身不作过度外推绝对耗时在 3 µs 以内即使是最复杂的默认控制台模板单次解析也只有 2.62.9 µs 量级是典型的“每次写日志的固定成本”规模Scaled 比值在运行时之间并不一致14.54 vs 14.40 vs 7.86基线EmptyTemplate的绝对成本会随运行时、CLR 版本、硬件差异变化比值随之被放大或缩小——例如 netcoreapp2.0 报告在 macOS/i7-7567U 上空模板本身耗时 371 ns几乎是 1.0 报告的两倍因而相对差距缩小到 7.86netcoreapp2.0 报告BenchmarkDotNet v0.10.6补全了分配数据EmptyTemplate每次解析分配264 BDefaultConsoleOutputTemplate分配2,296 B。分配的差异同样来自 token 数组、Substring结果与PropertyToken对象的数量差。这些报告都是 BenchmarkDotNet 特定版本、特定硬件的输出快照不能直接拿来跨机器横向断言它们的价值在于揭示空模板 vs 完整模板这种数量级差异以及解析器固定开销的稳定性。五、在真实日志流水线中的位置基准里是裸调用MessageTemplateParser而真实日志路径中解析器被套了一层缓存。在 MessageTemplateProcessor.cs 中class MessageTemplateProcessor : ILogEventPropertyFactory, ILogEventPropertyValueFactory { readonly MessageTemplateCache _parser new(new MessageTemplateParser()); ... public void Process(string messageTemplate, ... out MessageTemplate parsedTemplate, out EventProperty[] properties) { parsedTemplate _parser.Parse(messageTemplate); properties _propertyBinder.ConstructProperties(parsedTemplate, messageTemplateParameters); } }Logger.Write的每次调用都会走到_messageTemplateProcessor.Process(...)见 Logger.cs而内层 MessageTemplateCache.cs 用按引用比较字符串的 Hashtable缓存了解析结果MaxCacheItems 1000超出后整体Clear()防止缓存无界增长源码注释强调这是为了防止错误用法导致的 OOMMaxCachedTemplateLength 1024超过 1024 字符的模板跳过缓存直接交给内部解析器。这意味着实际生产路径中同一个模板字符串只会被MessageTemplateParser完整解析一次后续命中缓存直接返回MessageTemplate实例。基准报告测量的是缓存未命中时的最坏成本cold path而 hot path 的成本要低得多——这正是 Serilog 把解析性能优化的重点放在单次解析要快和缓存要命中两个维度上的原因。相关缓存命中/泄漏场景另有专门的 MessageTemplateCacheBenchmark 基准与之配套。六、如何复现这套基准当前仓库的性能测试项目 Serilog.PerformanceTests.csproj 面向net10.0;net9.0;net8.0并引用了 BenchmarkDotNet。运行入口是 Harness.cs 中定义的 xunit 事实测试[Fact] public void MessageTemplateParsing() { BenchmarkRunner.RunMessageTemplateParsingBenchmark(); }按其文件头注释的示例方式可以用dotnet test过滤运行dotnet test -c Release --filter FullyQualifiedNameSerilog.PerformanceTests.Harness.MessageTemplateParsing注意当前项目目标框架为net8.0/net9.0/net10.0如与历史报告netcoreapp1.0、netcoreapp2.0对标应选择相近框架并用-f指定。仓库根目录还提供了 RunPerfTests.ps1它会先执行./Build.ps1构建再对每个test/*.PerformanceTests项目运行dotnet test -c Release批量产出全部基准报告——results/目录下的 Markdown 报告即此类流程的产物。由于 BenchmarkDotNet 会执行多次预热与测量迭代完整运行通常需要较长时间建议用--filter只跑需要的基准。七、正确性保障解析器单元测试性能之外解析器的正确性边界由 MessageTemplateParserTests.cs 覆盖其中大量用例与基准中两个模板的行为直接相关空模板解析为单个空TextTokenAnEmptyMessageIsASingleTextToken{Timestamp:yyyy-MM-dd HH:mm:ss}这类带格式的属性FormatsCanContainColons验证{Time:hh:mm}的 format 为hh:mmFormatsCanContainMultipleSections验证{Number:##.0;-##.0;zero}这类多段格式位置参数ASingleIntegerPropertyNameIsParsedAsPositionalProperty验证{0}的IsPositional true容错路径AMalformedPropertyTagIsParsedAsText、NonNumberAlignmentIsParsedAsText、AlignmentOfIntMinValueIsParsedAsText等用例锁定非法片段按文本输出的行为转义DoubledLeftBracketsAreParsedAsASingleBracket系列用例保证{{/}}的正确折叠边界防回归IndexOutOfRangeExceptionBugHasNotRegressed专门验证{,,}这类极端输入不会触发越界异常。这些测试与基准报告互为印证高吞吐的解析实现与严苛的容错语义是同一份代码的两面任何性能优化都不得破坏这些既定行为。八、结论与性能要点回到这份 netcoreapp1.0 基准报告可以提炼出以下事实与工程要点解析开销与模板复杂度强相关空模板约 188 ns含 5 个属性 token 与格式串的默认控制台模板约 2.75 µsScaled 14.54差距主要来自 token 数量、子串分配与逐字符校验单次解析的固定成本在微秒量级且稳定性好StdDev 极小属于可预测的常量开销文本快速路径IndexOfAny 单次Substring与转义慢路径StringBuilder的分流是解析器在常见场景下控制分配的关键设计见 MessageTemplateParser.cs缓存使解析成本在真实路径上被摊薄MessageTemplateCache以 1000 条目/1024 字符为边界缓存已解析模板见 MessageTemplateCache.cs生产热点是缓存命中路径而非裸解析基准是版本与硬件敏感的跨运行时对比时Scaled 比值会随基线成本漂移1.0 时代 14.54 vs 2.0 时代 7.86引用数据时应注明报告出处与生成环境如 net4.5.2 报告 与 netcoreapp2.0 报告。对使用者而言最直接的启示是日志消息模板尽量保持简短、稳定——模板越长、属性越多冷启动解析越贵而模板字符串高度重复时Serilog 的模板缓存会让这部分成本趋近于零。若需要进一步压低固定开销可关注配套的 MessageTemplateCacheBenchmark 与 MessageTemplateRenderingBenchmark渲染侧报告它们分别覆盖了缓存命中行为与解析后渲染阶段的成本。赞分享后端可观测性【免费下载链接】serilogSimple .NET logging with fully-structured events项目地址https://gitcode.com/gh_mirrors/se/serilog点击查看免费下载相关推荐Polly 遥测Telemetry性能开销实测TelemetryBenchmark 基准报告解读与源码剖析Polly 遥测Telemetry性能开销实测TelemetryBenchmark 基准报告解读与源码剖析 本篇文章以仓库中由 BenchmarkDotN后端微服务Serilog LogContext 富集性能基准测试深度解读从报告数据到源码实现Serilog LogContext 富集性能基准测试深度解读从报告数据到源码实现 Serilog 的 LogContext 日志上下文允许开发者在代码执后端可观测性QMQ源码剖析深入理解消息存储与消费的底层实现QMQ源码剖析深入理解消息存储与消费的底层实现 QMQ作为去哪儿网内部广泛使用的消息中间件自2012年诞生以来在订单场景、报价搜索等高吞吐量业务中发挥着重要创作声明：本文部分内容由AI辅助生成（AIGC），仅供参考