Millisecond timestamp resolution (with suggested fix)

[Robert Važan]

I need my logs to show timestamps with resolution down to 1 millisecond. I've configured my machine to run with 1ms system timer resolution, but to my surprise NLog still uses only 15ms resolution. Here's my test code:

            for (int i = 0; i < 100; ++i)
            {
                Logger.Log(LogLevel.Info, DateTime.Now.ToString("ss.fff"));
                Thread.Sleep(1);
            }

And here's what it produces. The output shows that DateTime.Now has millisecond resolution while NLog timestamp is incremented in 15ms jumps.

...
2013-03-22 14:44:27.5303|INFO|MyApp|27.540
2013-03-22 14:44:27.5303|INFO|MyApp|27.541
2013-03-22 14:44:27.5303|INFO|MyApp|27.542
2013-03-22 14:44:27.5303|INFO|MyApp|27.543
2013-03-22 14:44:27.5303|INFO|MyApp|27.544
2013-03-22 14:44:27.5453|INFO|MyApp|27.545
2013-03-22 14:44:27.5453|INFO|MyApp|27.546
2013-03-22 14:44:27.5453|INFO|MyApp|27.547
2013-03-22 14:44:27.5453|INFO|MyApp|27.548
2013-03-22 14:44:27.5453|INFO|MyApp|27.549
2013-03-22 14:44:27.5453|INFO|MyApp|27.550
2013-03-22 14:44:27.5453|INFO|MyApp|27.551
...

The problem appears to be in NLog.Internal.CurrentTimeGetter.Now property. DotPeek shows this code:

        int tickCount = Environment.TickCount;
        if (tickCount == CurrentTimeGetter.lastTicks)
          return CurrentTimeGetter.lastDateTime;
        DateTime now = DateTime.Now;
        CurrentTimeGetter.lastTicks = tickCount;
        CurrentTimeGetter.lastDateTime = now;
        return now;

It looks like Environment.TickCount has only 15ms resolution despite system timer running in 1ms increments. I understand that querying Environment.TickCount is an optimization for DateTime.Now, which is an expensive operation. Nevertheless, I am not producing much log output and I don't mind removing this optimization. Unfortunately there doesn't seem to be any way to do it other than by modifying and recompiling NLog source code. I would really appreciate multiple time providers. That way there could be cached and uncached versions of DateTime.Now and DateTime.UtcNow. It would also make sense to allow user-defined time providers. Some time-sensitive applications have their own high-accuracy time source.

BTW, I find it surprising that NLog first uses DateTime.Now and subsequently uses DateTime.ToUniversalTime(). Doing it the other way round is more reliable and an order of magnitude faster if UTC time is desired in logs. Anyway with UtcNow time provider there would be no need for TimeLayoutRenderer.UniversalTime property and similar properties in other time renderers.

Kind Regards,
Robert

[Kim Christensen]

Hi Robert,

This would be a very nice improvement, could you please create a feature request on Github Issues, so it can be implemented in NLog in the future?

[Robert Važan]

Is anyone working on this? If not, I might be able to add this feature in the coming days.

[Kim Christensen]

No one is working on this at the moment. I would be great if you could implement that feature

[Robert Važan]

There's now a pending pull request at GitHub with implementation of pluggable time providers. Here's my summary of the changes:

There are now 4 builtin time providers:

- DateTime.Now with Environment.TickCount optimization (class CachedNowTimeSource)
- DateTime.UtcNow with Environment.TickCount optimization (class CachedUtcNowTimeSource)
- raw DateTime.Now (class NowTimeSource)
- raw DateTime.UtcNow (class UtcNowTimeSource)

The raw time source variants are useful to obtain 1ms time precision in applications utilizing timeBeginPeriod API.

Backward-compatible CachedNowTimeSource is used by default. Applications can switch time providers by assigning TimeSource.Current property:

    TimeSource.Current = new UtcNowTimeSource();

Applications can define their own time sources by deriving from TimeSource class and implementing TimeSource.Time property.

Time sources return time with properly set DateTime.Kind property. All NLog code was modified to use DateTime.ToLocalTime API wherever the code assumes that time is local. In my opinion the code that relies on local time is fragile and deserves rewriting to use UTC time everywhere, but that's out of the scope of my patch.

I have made very conservative changes. I've implemented only the API without any XML configuration. Configuration can be easily added on top if it turns out that sufficiently many people find this feature useful.

If you have any questions regarding the patch, please post them here.

Kind Regards,
Robert

[Kim Christensen]

Hi, thanks for the patch.
i haven't looked at the patch in detail yet, but it seems like very good quality.
Would it be possible to allow song the time provider from the configuration file to?

[Robert Važan]

Hi Kim,

I hope I will be able to carve out some time to do the XML configuration this evening. I will let you know when it's done.

Kind Regards,
Robert

[Robert Važan]

Ok, I've added XML configuration for the time source. It's used like this:

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

The following types are defined: FastLocal, FastUTC, AccurateLocal, AccurateUTC. FastLocal is default.

I've also renamed the corresponding classes: FastLocalTimeSource, FastUtcTimeSource, AccurateLocalTimeSource, AccurateUtcTimeSource.

It is possible to programmatically add more configurable time sources by attaching TimeSourceAttribute to them.

There appears to be a whole ensemble of custom tools for maintaining API documentation and XSD files. Understanding how these tools work is beyond me. Nevertheless I've noticed that these tools often hardcode some knowledge about NLog internals (targets, layouts, etc.). I guess the toolchain will need to be updated in order to properly support time sources in XSD and API documentation.

[Kim Christensen]

Looks very good. I'll try to test it soon.
Yeah the documentation generation is beyond me to, have not look into to it that much, after i took over the project from Jarek. But there is a first time for everything :-)

--
You received this message because you are subscribed to the Google Groups "NLog-Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to nlog-users+...@googlegroups.com.
To post to this group, send email to nlog-...@googlegroups.com.
Visit this group at http://groups.google.com/group/nlog-users?hl=en.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Stefano Del Furia]

HI,

i have tried to use your last feature with this configuration:

  <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" 

        xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">

    <time type='FastUTC' />

    

    <targets async="false">

      <target name="patternfile" xsi:type="File" fileName="${basedir}/_logs/LogEmiter.Nlog.txt" keepFileOpen="true"

        layout="${longdate:universalTime=true} - ${message}" />

    </targets>

    <rules>

      <logger name="*" minlevel="Debug" writeTo="patternfile" />

    </rules>

  </nlog>

with this sample code

            for (int i = 0; i < 100; ++i)

            {

                log.Warn(string.Format("It's gonna happen!!:{0}", DateTime.Now.ToString("hh.mm.ss.ffffff")));

                Thread.Sleep(10);

            }

but i get this log:

2013-10-01 14:42:04.8256 - It's gonna happen!!:04.42.04.825695

2013-10-01 14:42:04.9646 - It's gonna happen!!:04.42.04.964650

2013-10-01 14:42:04.9776 - It's gonna happen!!:04.42.04.977652

2013-10-01 14:42:04.9776 - It's gonna happen!!:04.42.04.989653     -------

2013-10-01 14:42:04.9916 - It's gonna happen!!:04.42.05.002659     -------

2013-10-01 14:42:05.0146 - It's gonna happen!!:04.42.05.014658

2013-10-01 14:42:05.0266 - It's gonna happen!!:04.42.05.026662

2013-10-01 14:42:05.0386 - It's gonna happen!!:04.42.05.038664

2013-10-01 14:42:05.0386 - It's gonna happen!!:04.42.05.051664     -------

2013-10-01 14:42:05.0536 - It's gonna happen!!:04.42.05.064665     -------

Where every 3 line the time showed by the logger is different from the time included with the messages,

What am i wrong ???

Thanks

[Robert Važan]

This is expected behavior. FastUTC will cache measured time for about 15 milliseconds. That's why it's called fast - it won't call DateTime.UtcNow every time. You should use AccurateUTC time source to get exact time.

[Stefano Del Furia]

HI,

thanks for the reply.

Now i have do the change but i get the same result.

Probably, because i use the 2.0.1.2 version while the fix is on version 2.1 ????

And this version is not available as nuget download so i think i must download the source code and build it from myself.

Is this correct??

Thanks

[Robert Važan]

You are correct. I submitted the patch in June 2013. Version 2.0.1.2 is from April 2013. You will have to build from sources.

[Robert Važan]

I've written two tutorials on using time sources in NLog:

Configure current time source:
http://blog.angeloflogic.com/2013/10/how-to-configure-nlog-time-source.html

Write custom time source:
http://blog.angeloflogic.com/2013/10/how-to-write-custom-nlog-time-source.html

[Kim Christensen]

Good work. I'm in the final stage of releasing the next version, when this is done I'll publish a post on the NLog homepage with links to your posts.