Ronin Building Blocks - Precision Time
Have you ever been working on debugging or diagnosing an issue and you need to get the time it takes to execute an external service call? I personally don't want to use a stop watch, although it is a viable solution, when I already have the start time (DateTime.UtcNow) that I wrote to my logs, I just want to subtract the start time from DateTime.UtcNow when I am done. Trying this approach presents some really strange and unreliable timings because the approximate resolution of the DateTime.UtcNow property 10 milliseconds.
This was so frustrating to see a bunch of calls that had no I/O take zero millseconds so I decide to try a test. I created an array of 1 million DateTime elements and looped through populating the elements with the current date time then checked to see how many operations occurred before it advanced to the next time (approximately 10 milliseconds later). This resulted in around 87000 entries being written before the time advanced. Yes so if you were to use the DateTime.UtcNow method instead of the stop watch your analysis would show it took no notable time to perform those 87000 operations.
To add to this looking at logs from my system I couldn't determine the order of operations if there was not more than 10 milliseconds between the entries. All of this begs for something better. Please remember that in distributed systems solutions the time makes no sense across machines, even if the machine is time synced. The computer times will always have some variance between them and a wall clock solution should only be used for single machine diagnostics or to act as a approximate alignment to events that occur.
The solution I am going to outline here is to create a precision time class to run on Windows 2012 R2 and beyond. For this reason instead of using .NET Core I will build a classic C# library. The API that is the center of the library is the GetSystemTimePreciseAsFileTime providing an approximate resolution that is less than 1 microsecond. Performing the same test that I did on the DateTime.UtcNow this was able to reduce my entries written before the time changes from 87000 to 4. This is a great improvement assuming that even writing a log will take a minimum of 4 calls.
When doing a PInvoke into unmanaged code a runtime security check is performed resulting in the call stack being walked. To improve the performance of this call I have decided to supress this check but that is something that should be done at your own discretion. Validate the security implications and decide if they are acceptable, in my scenario they are. I wrap the native method PInvoke signatures in an internal class to control access to them.
namespace Ronin.Clocks.Precision.Internal
{
#region Using Clauses
using System.Security;
using System.Runtime.InteropServices;
#endregion
/// <summary>
/// Native methods that are not exposed externally
/// </summary>
[SuppressUnmanagedCodeSecurity]
internal static class NativeMethods
{
#region Methods
/// <summary>
/// Definition for the Windows API to return the precise time.
/// </summary>
/// <param name="fileTime">The current system time as a file time</param>
[DllImport("kernel32.dll", ExactSpelling = true, EntryPoint = "GetSystemTimePreciseAsFileTime", SetLastError = true)]
internal static extern void GetSystemTime(ref long fileTime);
#endregion
}
}
Now to expose it I want to offer some simple properties and methods that should be self explanatory to anyone consuming the library. I decided to expose a UtcNow property that mirrors the DateTime.UtcNow but with better resolution and a UtcNowOffset that returns a DateTimeOffset instead.
namespace Ronin.Clocks.Precision
{
#region Using Clauses
using System;
using Internal;
#endregion
/// <summary>
/// A set of methods that expose the Windows System Time functions to retrieve a more precise time
/// </summary>
public static class PrecisionTime
{
#region Properties
/// <summary>
/// Returns the current system time as a file time construct
/// </summary>
public static long CurrentSystemTime
{
get
{
long time = 0;
NativeMethods.GetSystemTime(ref time);
return time;
}
}
/// <summary>
/// Returns a precise DateTime representing the current system time
/// </summary>
public static DateTime UtcNow => DateTime.FromFileTimeUtc(CurrentSystemTime);
/// <summary>
/// Returns a precise DateTimeOffset representing the current system time
/// </summary>
public static DateTimeOffset UtcNowOffset => DateTimeOffset.FromFileTime(CurrentSystemTime);
#endregion
#region Methods
/// <summary>
/// Retrieves a precise DateTime representing the current system time
/// </summary>
/// <returns>The current system time</returns>
public static DateTime GetDateTime()
{
return DateTime.FromFileTimeUtc(CurrentSystemTime);
}
/// <summary>
/// Retrieves a precise DateTimeOffset representing the current system time
/// </summary>
/// <returns>The current system time</returns>
public static DateTimeOffset GetDateTimeOffset()
{
return DateTimeOffset.FromFileTime(CurrentSystemTime);
}
#endregion
}
}
You can choose to hide the methods but I like giving as many options as possible. So now let's see how to use it.
var startTime = PrecisionTime.UtcNow;
// Do my work
var duration = PrecisionTime.UtcNow - startTime;
That wraps up the precision time block!
Comments
- Anonymous
November 09, 2016
Hello!Why this timer? What wrong with Stopwatch?- Anonymous
November 17, 2016
First, to be clear, there is nothing wrong with a Stopwatch. I have come across many scenarios where I need a precise time to write into logs etc. at the beginning and end of an action. If I already need these two times it seems odd to me to leverage another instrumentation technique to time the code block. To add to that I find the times written to the logs to be less precise than I would like.
- Anonymous