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
AccurateUtc is 2.8ns, perfectly acceptable for my needs.