【问题标题】:Serilog massive performance hit when enabling Debug log level启用调试日志级别时,Serilog 性能受到巨大影响
【发布时间】:2019-08-13 05:48:18
【问题描述】:

我在 .NET Core Service Fabric 应用程序上使用 Serilog。
我们注意到了性能问题,经过调查发现 Serilog 是罪魁祸首。

我们记录了大约 2,000 条调试消息,这需要 10 多秒。
即使仅配置了控制台接收器并将其设置为仅在信息日志级别进行过滤(因此不显示任何调试消息),也是如此。
将 MinimumLevel 设置为 Information 会使相同的代码运行不到 1 秒(即使配置了接收器)。

我们的项目使用:

  • netcoreapp2.0
  • Serilog NuGet 包 2.8.0(最新)

这是 Serilog 所期望的性能吗?

编辑:我注意到另一个(很多)较小的项目有相同的行为。这使我能够隔离问题:我有一个正在检索 ProcessId 的自定义浓缩器。拨打Process.GetCurrentProcess() 非常昂贵。对每个日志调用都这样做是导致性能下降的原因。我将进程 ID 存储在实例字段中,性能飙升。

【问题讨论】:

  • 您可以使用Log.IsEnabled 使您的日志语句有条件。我很确定 select 没有损坏 wrt serilog - 我和许多其他人有很多调试日志记录,没有这样的影响。说了这么多,如果您通过控制台接收器发送大量消息并且它们没有被过滤掉,那么写入(如果没有包含在 Serilog.Sinks.Async 中)将影响您的主线处理的性能(但您似乎排除)

标签: .net-core serilog


【解决方案1】:

过滤掉调试级别的事件与设置最低级别不同; Serilog 可用于结构化日志数据的序列化,因此Debug 事件的构建可能会占用时间。

这可能表明您的调试日志记录存在问题 - Serilog 本身很快,但如果您的调试事件正在序列化任意大的东西,例如请求/响应有效负载或 DTO,您的应用最终将执行大量反射、对对象的属性访问器调用(这可能会阻塞、执行 I/O 和其他疯狂的事情)、分配和垃圾收集。

如果调试事件使用无效的消息模板(即通过使用$"..." 字符串插值或非常量字符串进行记录),那么您的应用也将浪费大量精力将它们解析为格式字符串。

即并不是 Serilog 在这里很慢,而是您的应用无意中让它做了很多浪费的工作。

在控制台接收器上使用Debug 和稍后的Information 过滤器将导致所有这些工作完成,然后被丢弃。将最低级别设置为Information 将首先阻止这项工作。

从长远来看,审核您的调试级别日志记录以使用非常量消息模板、@destructureObjects: true 应该有助于让事情恢复到正常水平。

【讨论】:

    猜你喜欢
    • 1970-01-01
    • 1970-01-01
    • 1970-01-01
    • 2017-01-03
    • 2016-05-10
    • 2019-07-08
    • 2022-09-29
    • 2016-12-12
    • 1970-01-01
    相关资源
    最近更新 更多