我对使用异步目标时 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，但是，0.399 结果为 0.385 对我来说没有意义。
NLog 时间戳的进展方式几乎看起来像是在日志记录周期中生成的时间戳，而不是在日志调用期间生成的。这与上面的文章相反。
那么，这是否与 NLog 使用的时间源有关，或者更确切地说，与生成时间戳的时间有关？
最佳答案
你看到的行为是由NLog的时间源系统定义的。
NLog 4.x 提供了 4 种不同的时间源，您可以插入自己的时间源。 NLog 的默认时间源针对性能进行了优化，并对返回的值进行了一些缓存。缓存机制使用Environment.TickCount返回新日志条目时间戳的时间间隔。 TickCount 属性的分辨率仅限于系统定时器的分辨率，该分辨率不是固定值，但通常在 10-16 ms 范围内变化。
所以，你看到的效果是由NLog默认时间源定义的。而且，顺便说一句，它并不特定于异步目标 - 从示例中删除 async 属性，您将看到完全相同的行为。
如果您需要更精确地解析日志事件中的时间戳，您可以将 NLog 配置为使用其他时间源:
<nlog>
<time type="AccurateUTC" />
</nlog>
但是，这并不能保证您的所有事件都有不同的时间戳，您可能会得到 2-3 个事件具有相同的时间。但是it will use straight value of DateTime.UtcNow填写日志事件的日期/时间字段，不进行任何缓存。并且也没有任何日期时区转换...
您可以找到有关 time sources in NLog wiki 的更多信息
关于c# - NLog 异步目标时间戳，我们在Stack Overflow上找到一个类似的问题： https://stackoverflow.com/questions/28472786/