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:

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:

Method

Median

StdDev

FastLocal

5.7752 ns

0.3450 ns

FastUtc

5.8330 ns

0.4939 ns

AccurateLocal

784.4354 ns

61.6136 ns

AccurateUtc

7.0547 ns

0.3934 ns

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.