NLog Async target timestamps

Question

I'm curious about timestamping in NLog when using async targets.

I know that according to What's the meaning of the time stamp in nlog when async is on? the timestamp is generated when the log entry is queued, as you would expect.

However, I noticed something in one of my log files, so I decided to whip up a quick test.

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();
}

My NLog.config looks like:

<?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>

Now if I look at the output, we see that all entries between 754, and 9962 have the same NLog timestamp, however, DateTime.Now shows the milliseconds progressing:

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
...

I can understand that with the overheads, a DateTime.Now stamp of .384 could be logged an .385, however, it doesn't make sense to me that .399 comes out as .385.

The way that the NLog timestamp progresses, almost looks like the timestamp is generated during a logging cycle, rather than the log call. Which would be contrary to the above article.

So, is this something to do with the time source NLog uses, or rather, when the timestamp is generated?

Answer 1

Behavior you see is defined by time source system of NLog.

NLog 4.x provides 4 different time sources, and you can plug in your own. The default time source of NLog is optimized for performance and does some caching of the values that are being returned. The caching mechanism uses Environment.TickCount intervals to return time stamps for new log entries. Resolution of TickCount property is limited to resolution of system timer which is not a fixed value but typically varies in the 10-16 ms range.

So, the effect you see is defined by default time source of NLog. And, btw, it's not specific to async targets - remove async property from your example and you will see exactly same behavior.

If you need a more precise resolution for time stamps in your log events, you can configure NLog to use another time source:

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

However, this will not guarantee that all your events will have different time stamps, you might get 2-3 events with same time. But it will use straight value of DateTime.UtcNow to fill in the date/time field of log event, without any caching. And without any date time zone conversions too...

You can find more info about time sources in NLog wiki