During a recent debugging session involving some juicy threading issues, the logs were showing some scary stuff. Given that we’re talking about threading issues, order of operations and timing is everything. And the operations were all out of order! When the log entries were ordered by record ID you have one sequence of events yet when ordered by timestamp you have another sequence. In terms of the desired behaviour, one is spot on (when sorted by ID), the other is very wrong.

Looking in to the NLog configuration, async target wrappers are used. At first I thought this could be the issue, things are logged from different threads, stuff getting out of order etc, but no.

Then there was a question of ‘when does NLog populate the timestamp?’. Does it populate it upfront or when the event is committed somewhere? As it turns out, it populates the timestamp in the LogEventInfo constructor, so all is well there.

You’ll notice that in the LogEventInfo constructor, the timestamp isn’t set as simply as reading DateTime.UtcNow, it’s retrieved via a provider. How NLog retrieves the current time is configurable and by default it will use a timestamp that’s accurate to 16ms. 16 entire milliseconds! Bingo. Given that our log entries were being grouped in brackets of roughly 10ms, we had our issue.

How do you increase the accuracy? Can you increase the accuracy? Of course! As explained in the Time-Souce wiki page, you need to override the default TimeSource. As with anything, increased accuracy comes with a slight performance overhead. From the performance comparison table, the difference between FastUtc and AccurateUtc is 2.8ns, perfectly acceptable for my needs.

GitHub user vcaraulean created a benchmark test to compare the performance of each TimeSource provider. I used this to create a complete solution which you can run in your own environment to see what works best for you. Below are the results I got from running in my local VM. Remember to create a release mode build, otherwise the results will be highly skewed.

BenchmarkDotNet=v0.10.0
OS=Microsoft Windows NT 6.2.9200.0
Processor=Intel(R) Core(TM) i7-4770HQ CPU 2.20GHz, ProcessorCount=2
Frequency=10000000 Hz, Resolution=100.0000 ns, Timer=UNKNOWN
Host Runtime=Clr 4.0.30319.42000, Arch=64-bit RELEASE [RyuJIT]
GC=Concurrent Workstation
JitModules=clrjit-v4.6.1590.0
Job Runtime(s):
	Clr 4.0.30319.42000, Arch=64-bit RELEASE [RyuJIT]

Method	Mean	StdErr	StdDev	Median
FastLocal	2.9914 ns	0.0344 ns	0.1333 ns	3.0056 ns
FastUtc	3.2813 ns	0.0218 ns	0.0843 ns	3.2954 ns
AccurateLocal	278.5057 ns	0.8608 ns	3.3337 ns	278.4796 ns
AccurateUtc	5.2378 ns	0.0392 ns	0.1517 ns	5.1960 ns