Timestamp accuracy and resolution in NLog

In one of internal projects we got a situation where our log management system was displaying entries from NLog in wrong “logical” order, despite being explicitly ordered by timestamp.

Here are few insights I got after investigating the case.

Let’s create a basic example to show the problem.

for (var i = 0; i < 100; i++ )
{
    _log.Info($"Iteration {i}: {DateTime.Now.ToString("HH:mm:ss.fffffff")}");
}

If we run this code with default NLog configuration, we will get output like this:

2016-07-11 16:14:23.8486343 Iteration 0: 16:14:23.8486343
2016-07-11 16:14:23.8486343 Iteration 1: 16:14:23.8496384
2016-07-11 16:14:23.8486343 Iteration 2: 16:14:23.8506392
2016-07-11 16:14:23.8486343 Iteration 3: 16:14:23.8526399
2016-07-11 16:14:23.8486343 Iteration 4: 16:14:23.8536741
2016-07-11 16:14:23.8486343 Iteration 5: 16:14:23.8546388
2016-07-11 16:14:23.8566766 Iteration 6: 16:14:23.8566766
2016-07-11 16:14:23.8566766 Iteration 7: 16:14:23.8576574
2016-07-11 16:14:23.8566766 Iteration 8: 16:14:23.8596377
2016-07-11 16:14:23.8566766 Iteration 9: 16:14:23.8596377
2016-07-11 16:14:23.8566766 Iteration 10: 16:14:23.8606376
2016-07-11 16:14:23.8566766 Iteration 11: 16:14:23.8606376
2016-07-11 16:14:23.8566766 Iteration 12: 16:14:23.8616403

As you see, multiple log entries are recorder with same timestamp (but check the timestamps in the message - they are much more varied). This looks fine if you’re looking in a console or in a single log file. But it will get quite annoying if you’re querying your log storage system and ordering results by time - sort order will be not what you would expect.

If we dig deeper in this problem, we will discover that NLog, has a mechanism called TimeSource. This provider is used to get the current time for each instance of LogEventInfo class created for every log entry in your application. There are a total of 4 different time source implementations, and, of course, you can create your own, if you please.

The default implementation of NLog’s time source is optimized for performance and caches the values that are being returned. Caching logic uses Environment.TickCount intervals to return time stamps for new log entries. And the 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.

As a result, with default configuration, you get a timestamp resolution of ~15 milliseconds for your log entries.

Luckily, NLog provides other implementations of TimeSource. They are documented to an extend here. The default is the FastLocal and is has the caching behaviour I described above. FastUTC is using a similar caching approach but returning UTC timestamps. AccurateLocal and AccurateUTC, theoretically, should be better bets if you want a more precise timestamps in your log entries.

If we change our NLog configuration to use a more accurate time source:

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

… then we will get a quite different picture in the output:

2016-07-11 21:20:32.5920090 Iteration 0: 23:20:32.5889709
2016-07-11 21:20:32.5939717 Iteration 1: 23:20:32.5929728
2016-07-11 21:20:32.5949707 Iteration 2: 23:20:32.5949707
2016-07-11 21:20:32.5959701 Iteration 3: 23:20:32.5959701
2016-07-11 21:20:32.6310051 Iteration 4: 23:20:32.6310051
2016-07-11 21:20:32.6330058 Iteration 5: 23:20:32.6330058
2016-07-11 21:20:32.6340033 Iteration 6: 23:20:32.6340033
2016-07-11 21:20:32.6370016 Iteration 7: 23:20:32.6370016
2016-07-11 21:20:32.6400059 Iteration 8: 23:20:32.6400059
2016-07-11 21:20:32.6766186 Iteration 9: 23:20:32.6766186
2016-07-11 21:20:32.6795909 Iteration 10: 23:20:32.6795909
2016-07-11 21:20:32.6826277 Iteration 11: 23:20:32.6826277
2016-07-11 21:20:32.6835886 Iteration 12: 23:20:32.6835886

Now we got a much better results: our logging timestamps are matching quite nicely timestamps from our message generated by DateTime.Now!

Both of the accurate time sources are using respectively current values of DateTime: DateTime.Now and DateTime.UtcNow. And this is giving us a better result, with timestamp resolution closer to 1 ms.

I actually wondered, how much is the difference in performance will be between fast and accurate TimeSource implementations? BenchmarkDotNet to the rescue! I quickly put together a benchmark that measured the difference between using different time sources. Results are quite interesting:

Quite telling: fast implementations are the fastest but, as we’ve seen before, timestamps are cached and not that precise. AccurateUTC is a very close runner. If you’re asking, why is this not the default time source, the response probably will be the dreaded backward compatibility, as time sources were added around NLog 2.x.

Summing up

If you care about timestamps in your logs, change the default TimeSource to AccurateUTC. There’s a very small performance overhead, but you will get a much better accuracy and all your timestamps will be in UTC. Actually, the second gain (UTC timestamps), is extremely valuable when you have to deal with logging in complex or geographically distributed applications. So, please, consider it.