NLog 异步目标时间戳

Question

我很好奇使用异步目标时 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
...

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

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

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

Answer 1

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

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

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

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

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

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

您可以找到有关 time sources in NLog wiki

的更多信息

NLog 异步目标时间戳

NLog Async target timestamps

c#

nlog