NLog 异步目标时间戳答案

【问题标题】：NLog Async target timestampsNLog 异步目标时间戳
【发布时间】：2015-02-12 08:38:06
【问题描述】：

我对使用异步目标时 NLog 中的时间戳感到好奇。

我知道根据What's the meaning of the time stamp in nlog when async is on?，时间戳是在日志条目排队时生成的，正如您所期望的那样。

但是，我注意到我的一个日志文件中有一些东西，所以我决定快速测试一下。

static void Main(string[] args)
{
    for (int i = 0; i < 10000; i++)
    {
        _logger.Info("Timestamp: {0}, LogNumber: {1}",DateTime.Now.ToString("HH:mm:ss.fff"), i);
    }
    _logger.Factory.Flush();
}

我的 NLog.config 看起来像：

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
      xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <targets async="true">
    
    <target xsi:type="File" name="f" fileName="${basedir}/logs/${shortdate}.log"
            layout="${longdate} ${uppercase:${level}} ${message}" />
  </targets>

  <rules>   
    <logger name="*" minlevel="Trace" writeTo="f" />
  </rules>
</nlog>

现在，如果我查看输出，我们会看到 754 和 9962 之间的所有条目都具有相同的 NLog 时间戳，但是，DateTime.Now 显示了毫秒数：

2015-02-12 08:19:23.3814 INFO Timestamp: 08:19:23.376, LogNumber: 0
...
2015-02-12 08:19:23.3853 INFO Timestamp: 08:19:23.384, LogNumber: 754
...
2015-02-12 08:19:23.4033 INFO Timestamp: 08:19:23.399, LogNumber: 9963
...

我可以理解，通过开销，0.384 的 DateTime.Now 标记可以记录为 0.385，但是，对我来说 .399 输出为 0.385 是没有意义的。

NLog 时间戳的进展方式，几乎看起来时间戳是在日志记录周期中生成的，而不是在日志调用期间生成的。这将与上述文章相反。

那么，这是否与 NLog 使用的时间源有关，或者更确切地说，与生成时间戳的时间有关？

【问题讨论】：

标签： c# nlog

【解决方案1】：

你看到的行为是由 NLog 的时间源系统定义的。

NLog 4.x 提供了 4 种不同的时间源，你可以自己插入。 NLog 的默认时间源针对性能进行了优化，并对返回的值进行了一些缓存。缓存机制使用Environment.TickCount 间隔来返回新日志条目的时间戳。 TickCount 属性的分辨率仅限于系统计时器的分辨率，它不是一个固定值，但通常在 10-16 毫秒范围内变化。

所以，你看到的效果是由 NLog 的默认时间源定义的。而且，顺便说一句，它并不特定于异步目标 - 从您的示例中删除异步属性，您将看到完全相同的行为。

如果您需要更精确地解析日志事件中的时间戳，可以将 NLog 配置为使用其他时间源：

<nlog>
  <time type="AccurateUTC" />
</nlog>

但是，这并不能保证您的所有事件都会有不同的时间戳，您可能会同时获得 2-3 个事件。但是it will use straight value of DateTime.UtcNow填写日志事件的日期/时间字段，没有任何缓存。而且也没有任何日期时区转换...

你可以找到更多关于time sources in NLog wiki的信息

【讨论】：