企业官网建设流程全解析

• 后端
• 可观测性

本报告基于 Serilog 仓库中 MessageTemplateCacheBenchmark_Leaking 基准测试结果，深入剖析消息模板缓存在「缓存溢出」（Leaking，即缓存条目持续超过上限而被反复清空）这一极端场景下，三种缓存实现（Dictionary、Hashtable、ConcurrentDictionary）在吞吐量上的真实差异。读完本文，你将理解 Serilog 消息模板缓存的内部机制、缓存上限与溢出保护的实现原理，掌握如何解读 BenchmarkDotNet 基准报告中的参数维度与缩放比例，并学会在真实日志场景中规避缓存泄漏带来的数量级性能退化。

一、背景：为什么 Serilog 需要一个消息模板缓存

Serilog 采用「fully-structured events」的日志模型，每次调用logger.Information("Processed {@Position} for {Task} in {Elapsed:000} ms", ...)这类结构化日志时，日志框架都需要：

1. 将消息模板字符串（如"Processed {@Position} for {Task}"）解析为 token 序列（文本 token、属性 token 等），得到 MessageTemplate 对象；
2. 依据模板中的属性 token 绑定实际参数，构造EventProperty[]；
3. 将结果封装为LogEvent交给 sink 输出。

其中第 1 步「模板解析」涉及正则式词法分析，是相对昂贵的热点操作。如果在每次写日志时都重新解析同一条模板字符串，开销会线性累积。为此，Serilog 在 MessageTemplateProcessor 中用一个MessageTemplateCache包装了真正的解析器：

readonly MessageTemplateCache _parser = new(new MessageTemplateParser());

缓存以「模板字符串 → 解析结果 MessageTemplate」的映射形式工作：命中的模板直接复用解析结果，未命中的才交给底层MessageTemplateParser解析，并写入缓存。该处理器由 LoggerConfiguration 构造，并被 Logger 在每次Write时通过_messageTemplateProcessor.Process(...)调用（见 Logger.cs），因此缓存的性能直接决定整个日志管线的吞吐上限。

二、基准测试设计：Leaking 场景的构造

本报告对应的基准源码位于 test/Serilog.PerformanceTests/MessageTemplateCacheBenchmark/MessageTemplateCacheBenchmark_Leaking.cs，其关键设计如下：

const string DefaultOutputTemplate = "{Timestamp:yyyy-MM-dd HH:mm:ss} [{Level}] {Message}{NewLine}{Exception}"; const int MaxCacheItems = 1000; [Params(10000)] public int Items { get; set; } [Params(1, 10, 100, 1000)] public int OverflowCount { get; set; } [Params(1, -1)] public int MaxDegreeOfParallelism { get; set; }

• Items = 10000：共生成 10000 条互不相同的模板字符串（DefaultOutputTemplate追加随机Guid），模拟「滥用缓存」——每条消息都携带一个全新的模板，而不是复用固定的模板常量；
• OverflowCount ∈ {1, 10, 100, 1000}：决定总模板集合大小为total = MaxCacheItems + OverflowCount（即 1001 ~ 2000），工作集刚好越过缓存上限 1000，造成持续溢出；
• MaxDegreeOfParallelism ∈ {1, -1}：-1表示使用Parallel.For的默认调度（多线程并行），1表示强制单线程执行，用于区分并发竞争带来的额外开销。

Run方法通过Parallel.For让各线程反复执行cache.Parse(_templateList[idx % total])。由于三种被测缓存实现都实现了IMessageTemplateParser接口，基准可对同一工作负载分别进行 Dictionary、Hashtable（Serilog 生产实现）与 ConcurrentDictionary 三种实现的对比。

此外，被测缓存全部包装了 NoOpMessageTemplateParser（解析直接返回常量模板），从而隔离「解析成本」，将基准焦点完全集中在缓存查找、锁竞争与溢出清除本身。

三、被测实现与缓存溢出保护机制

三份被测代码在「溢出保护」上逻辑完全一致：当缓存条目数达到上限MaxCacheItems = 1000时，下一次写入前会先执行_templates.Clear()全量清空，再写入新条目。以生产实现 MessageTemplateCache.cs 为例：

lock (_templatesLock) { // Exceeding MaxCacheItems is *not* the sunny day scenario; all we're doing here is preventing out-of-memory // conditions when the library is used incorrectly. Correct use (templates, rather than // direct message strings) should barely, if ever, overflow this cache. if (_templates.Count == MaxCacheItems) _templates.Clear(); _templates[messageTemplate] = result; }

源码注释已经明确指出：溢出不是正常使用场景，这里的清空策略只是为了在「库被错误使用」（例如每条日志直接内联消息字符串而非模板常量）时防止内存无限增长。它在防御 OOM 的同时，也放弃了缓存应有的「命中率收益」。

三个实现的差异在于存储结构与并发策略：

需要说明的是，生产实现之所以选择 Hashtable 而非Dictionary<,>，是出于线程安全考虑：Hashtable 官方支持「单写多读」（multiple readers with a single writer）的并发语义，允许读操作不加锁；而Dictionary<,>只保证「不被修改时的多读并发」，一旦有写入，并发读就可能抛异常或读到不一致状态。相关设计取舍在 MessageTemplateCache.cs 的注释中有完整引用说明。

所有缓存还共享另一条优化规则：MaxCachedTemplateLength = 1024，模板字符串长度超过 1024 字符时直接跳过缓存、即时解析，避免缓存长字符串浪费内存。

另外，三份实现都使用 ByReferenceStringComparer（RuntimeHelpers.GetHashCode+ReferenceEquals的引用相等语义）作为键比较器。这与实际日志使用模式相吻合——应用代码中同一模板字符串通常来自同一字符串字面量（interned 或内联常量），引用相等判断极快，且能避免逐字符比较的开销。

四、基准环境与运行方式

报告头部记录了本次运行环境（BenchmarkDotNet 生成的环境信息）：

BenchmarkDotNet=v0.10.6, OS=Mac OS X 10.12 Processor=Intel Core i7-7567U CPU 3.50GHz (Kaby Lake), ProcessorCount=4 Frequency=1000000000 Hz, Resolution=1.0000 ns, Timer=UNKNOWN dotnet cli version=2.1.4 [Host] : .NET Core 4.6.0.0, 64bit RyuJIT DefaultJob : .NET Core 4.6.0.0, 64bit RyuJIT

• 这是netcoreapp2.0 / BenchmarkDotNet v0.10.6 / .NET Core 4.6.0.0（对应 .NET Core 2.x 运行时）时代产物，属于 2017~2018 年左右的测量数据，用于对比不同实现的相对关系而非绝对性能；
• 机器为 4 核 Kaby Lake 笔记本处理器，Timer=UNKNOWN表示当时计时器信息未被识别；
• 仓库results/目录还保留了同场景在 net4.5.2 等目标框架下的报告，可供交叉对比。

复现方法：在仓库根目录执行 RunPerfTests.ps1 会先跑 Build.ps1，再对每个*.PerformanceTests项目执行dotnet test -c Release；也可以直接运行 Harness.cs 中的MessageTemplateCache测试入口（它会依次运行 Cached 与 Leaking 两套基准），或按 Harness.cs 文档注释所示使用dotnet test -c Release --filter "FullyQualifiedName=..."精确筛选。基准项目 Serilog.PerformanceTests.csproj 通过ProjectReference引用src/Serilog/Serilog.csproj，并使用 BenchmarkDotNet 作为基准框架。

五、基准结果数据（完整表格）

以下数据来自 MessageTemplateCacheBenchmark_Leaking-report-github.md，列含义：Items模板总数（固定 10000）、OverflowCount越过缓存上限的模板数量、MaxDegreeOfParallelism并行度（-1 为多线程并行，1 为单线程）、Mean平均耗时、Scaled相对 Baseline（Dictionary）的倍数。

六、结果解读：三个关键观察

6.1 ConcurrentDictionary 在溢出场景下性能崩溃

最醒目的结论是：一旦缓存持续溢出，ConcurrentDictionary 实现的耗时达到 Dictionary 的约 25~100 倍，中位数稳定在 80~200 ms 量级，而 Dictionary / Hashtable 仅约 2~4 ms。

原因分析（结合 ConcurrentDictionaryTemplateCache.cs 源码）：

• 溢出触发的_templates.Clear()会清空整个条目带（stripes），之后所有线程立即再次遭遇大量TryGetValue未命中；
• ConcurrentDictionary 的无锁TryGetValue在「几乎全部未命中」时无法带来任何收益，反而每次都要经历完整的哈希定位与条带锁定路径，解析结果写入也伴随细粒度锁与内存屏障；
• 工作集（total = 1000 + OverflowCount）与 Items=10000 之间使用idx % total取模访问，意味着大量线程会反复请求同样的 1001~2000 个模板，缓存每次清空后这些模板被反复重新解析、重新写入，形成「清空—重建」的死循环，ConcurrentDictionary 的高并发元数据开销被放大到极致。

6.2 Dictionary 与 Hashtable 在并行溢出场景下难分伯仲

在MaxDegreeOfParallelism = -1（多线程）时，Dictionary 与 Hashtable 的耗时几乎持平（Scaled 0.90~1.00），Hashtable 甚至多数配置下略快。这印证了生产实现选择 Hashtable 的初衷：Hashtable 支持「单写多读」，读路径完全无锁，多线程下大量未命中读不会触发锁竞争；而测试参照的 Dictionary 实现把所有读也放进lock内（见 DictionaryMessageTemplateCache.cs），多线程下锁竞争抵消了它泛型实现的速度优势。

6.3 单线程下 Hashtable 反而落后约 30%

当MaxDegreeOfParallelism = 1时，Hashtable 稳定地比 Dictionary 慢约 30%（Scaled 1.30~1.31），与溢出程度无关。这是因为：

• 单线程下锁完全无竞争，Dictionary 泛型实现 +ByReferenceStringComparer（RuntimeHelpers.GetHashCode的运行时引用哈希）避免了 Hashtable 非泛型接口带来的装箱与虚调用开销；
• Hashtable 的「无锁读」优势在单线程下无处发挥，纯粹变成负担。

这说明溢出场景下没有免费的午餐：Hashtable 用单线程 30% 的开销换取了多线程下的无锁读安全性，与 Serilog 日志框架「可能被任意多线程调用」的实际定位是匹配的。

七、与缓存命中场景（Cached）的对照实验

为了完整理解缓存行为，仓库还提供了姊妹基准 MessageTemplateCacheBenchmark_Cached 及其报告 MessageTemplateCacheBenchmark_Cached-report-github.md。该基准在Setup阶段预热三个缓存（模板全部命中后才开始计时），模拟正常使用方式。两组结果呈现完全相反的趋势：

• Cached（高命中）场景：Hashtable 与 ConcurrentDictionary 相对 Dictionary 的 Scaled 约为 0.15~0.24，即快 4~7 倍——无锁读 + 引用比较在纯命中路径上优势显著；
• Leaking（持续溢出）场景：ConcurrentDictionary 相对 Dictionary 的 Scaled 高达 25~100 倍，成为最差实现。

两组对照清晰地说明：缓存的性能高度依赖「命中率」，而命中率由使用方式决定。当应用把模板写成常量时，缓存命中率接近 100%，无锁结构收益巨大；当应用每行日志都拼接出全新消息字符串时，缓存名存实亡，测试参照的 Concurrent 实现还会因反复清空而放大成本。

八、对实际使用的实践启示

结合基准结论与源码注释（"Correct use (templates, rather than direct message strings) should barely, if ever, overflow this cache"），可以得出以下可操作的工程建议：

1. 始终使用模板常量：logger.Information("User {UserId} logged in", id)优于logger.Information($"User {id} logged in")。前者是固定模板字符串，缓存命中且稳定复用；后者每次生成新字符串，模板缓存被当作「每条唯一模板」处理，直接走向 Leaking 场景；
2. 警惕动态模板拼接：如果确实需要动态格式，注意缓存上限为 1000 条、单条上限 1024 字符（MessageTemplateCache.cs），超出后缓存清空或直接跳过解析缓存；
3. 解读基准报告时关注相对量而非绝对值：本报告的绝对毫秒数来自 2017 年的 4 核笔记本环境，但「溢出场景下 ConcurrentDictionary 比 Dictionary 慢 25~100 倍」这一相对结论由设计使然（反复 Clear + 无锁命中率趋零），在更长的时间跨度与更多核心上仍具参考价值；仓库results/net4.5.2/下同一基准的报告（MessageTemplateCacheBenchmark_Leaking-report-github.md）也呈现了相同趋势（Concurrent 慢 24~88 倍），可佐证该结论的平台无关性；
4. 监控真实命中率：如果应用日志吞吐在并发下出现异常回退，优先排查是否每条日志都在生成新模板字符串，再结合缓存源码定位清空频率。

九、总结

MessageTemplateCacheBenchmark_Leaking 报告 是一份对「缓存被错误使用」场景的定量警示：当模板字符串持续溢出缓存上限时，Serilog 生产使用的 Hashtable 缓存与测试参照的 Dictionary 实现仍能保持 2~4 ms 的量级表现，而 ConcurrentDictionary 实现会退化到其 25~100 倍。结合 MessageTemplateCache.cs、MessageTemplateProcessor.cs 与两套基准源码，可以确认：模板缓存的设计目标不是应付泄漏，而是在正确使用（模板常量）时通过引用比较与无锁读实现近乎零成本的复用。维护结构化日志高性能的关键，始终在于把消息模板当作可复用的常量资源，而非每次写入时的即时拼接产物。

• 后端
• 可观测性