Log with timestamps that have millisecond accuracy & resolution in Windows C++

Question

I'm aware that for timing accuracy, functions like timeGetTime, timeBeginPeriod, QueryPerformanceCounter etc are great, giving both good resolution & accuracy, but only based on time-since-boot, with no direct link to clock time.

However, I don't want to time events as such. I want to be able to produce an exact timestamp (local time) so that I can display it in a log file, eg 31-12-2010 12:38:35.345, for each entry made. (I need the millisecond accuracy)

The standard Windows time functions, like GetLocalTime, whilst they give millisecond values, don't have millisecond resolution, depending on the OS running. I'm using XP, so I can't expect much better than about a 15ms resolution.

What I need is a way to get the best of both worlds, without creating a large overhead to get the required output. Overly large methods/calculations would mean that the logger would start to eat up too much time during its operation.

What would be the best/simplest way to do this?

score 5 · Answer 1 · answered Dec 31 '10 at 13:03

5

You can try GetSystemAsFileTime which expresses time in units of 100-nanoseconds. You are up to Windows to determine what actual resolution it populates it with.

Alternative method is just to query the local time and use QueryPerformanceCounter to lock in an offset to time ratio at application startup and apply that to subsequent counter readings.

answered Dec 31 '10 at 13:03

Steve-o

12,678
2
41
60

However, my difficulty lies in dealing with the millisecond value from timeGetTime, and the SYSTEMTIME structure of GetLocalTime. I can get both at startup, calulate a difference in timeGetTime at log time, but how to apply that offset to the GetLocalTime structure in a clean & swift process is eluding me. Extending this to use QueryPerformanceCounter adds another variable (QueryPerformanceFrequency) to the mix, thereby slowing it even further. I need a 'quick' algorithm, not one that will hog up a system. – Dave Dec 31 '10 at 13:44
@Psychic worrying about basic math performance on gigahertz processors is a bit silly when your are outputting to a disk which is many factors slower. – Steve-o Dec 31 '10 at 13:45
Output is primarily to screen. File would be optional, as would database output. There would also be many entries per second, hence the need for millisecond accuracy, so having an optimized method is of great need in this instance. We might have gigahertz computers, but a logging system doesn't get it all. I have quite a number of other modules taking up much more resources which can't be slowed down by an inefficient logger. – Dave Dec 31 '10 at 14:19
Please note that the FILETIME returned are usually only accurate to 1 ms and not to 100ns intervals. But given that you want milliseconds accuracy this is not a problem. On older Windows versions (2000) you might need to call NtSetTimerResolution to get the accuracy you need. – Ritsaert Hornstra Dec 31 '10 at 15:36
Also note that GetSystemAsFileTime is the fastest way to obtain an UTC timestamp on a Windows system (it only takes a few clockcycli)! – Ritsaert Hornstra Dec 31 '10 at 15:37

Lior Kogan · Accepted Answer · 2010-12-31T15:04:29.057

First, some functions:

// ==========================================================================
#define NOMINMAX
#define _AFXDLL
#include "afxwin.h"               // TRACE
#include "windows.h"              // ULARGE_INTEGER
#include "mmSystem.h"             // timeGetTime
#pragma comment(lib, "Winmm.lib") // timeGetTime

// ==========================================================================
// convert FILETIME to ULONGLONG
// (casting won't work on 64-bit platforms, due to alignment of FILETIME members)
inline void ToULL(const FILETIME& ft, ULONGLONG& uft)
{
    ULARGE_INTEGER uli;
    uli.LowPart = ft.dwLowDateTime ;
    uli.HighPart= ft.dwHighDateTime;
    uft= uli.QuadPart;
}

// --------------------------------------------------------------------------
// convert ULONGLONG to FILETIME
// (casting won't work on 64-bit platforms, due to alignment of FILETIME members)
inline void ToFILETIME(const ULONGLONG& uft, FILETIME& ft)
{
    ULARGE_INTEGER uli;
    uli.QuadPart= uft;
    ft.dwLowDateTime = uli.LowPart ;
    ft.dwHighDateTime= uli.HighPart;
}

// --------------------------------------------------------------------------
// ULONGLONG version for GetSystemTimeAsFileTime
inline void GetSystemTimeAsULL(ULONGLONG& uft)
{
    FILETIME ft;
    ::GetSystemTimeAsFileTime(&ft);
    ToULL(ft, uft);
}

// --------------------------------------------------------------------------
// convert ULONGLONG to time-components
bool ULLToSystemTime(const ULONGLONG nTime        ,  // [i]
                     WORD&           nYear        ,  // [o] 1601 - 30827
                     WORD&           nMonth       ,  // [o] 1 -    12
                     WORD&           nDay         ,  // [o] 1 -    31
                     WORD&           nHour        ,  // [o] 0 -    23
                     WORD&           nMinute      ,  // [o] 0 -    59
                     WORD&           nSecond      ,  // [o] 0 -    59
                     WORD&           nMilliseconds ) // [o] 0 -   999
{
    SYSTEMTIME sysTime;
    FILETIME   ft     ;
    ToFILETIME(nTime, ft);

    // the wDayOfWeek member of the SYSTEMTIME structure is ignored
    if (0 == ::FileTimeToSystemTime(&ft, &sysTime))
        return false;

    nYear        = sysTime.wYear        ;
    nMonth       = sysTime.wMonth       ;
    nDay         = sysTime.wDay         ;
    nHour        = sysTime.wHour        ;
    nMinute      = sysTime.wMinute      ;
    nSecond      = sysTime.wSecond      ;
    nMilliseconds= sysTime.wMilliseconds;
    return true;
}

// --------------------------------------------------------------------------
void TraceTime(const ULONGLONG nTime) // [i]
{
    WORD nYear,nMonth,nDay,nHour,nMinute,nSecond,nMilliseconds;
    ULLToSystemTime(nTime, nYear,nMonth,nDay,nHour,nMinute,nSecond,nMilliseconds);
    TRACE("Time: %02u-%02u-%04u %02u:%02u:%02u.%03u\n", nDay,nMonth,nYear,nHour,nMinute,nSecond,nMilliseconds);
}

Now, how to use:

ULONGLONG u0,u1;
::GetSystemTimeAsULL(u0);

// wait for tick (each 14.4mS)
do
{
    ::GetSystemTimeAsULL(u1);
}
while (u0==u1);

DWORD d1= ::timeGetTime();

// d1 and u1 are now synchronized

// ... do some work

// get current time:
ULONGLONG u2= u1+(::timeGetTime() - d1)*10000; // mSec --> HectoNanoSec

TraceTime(u2);

Note that you should resync d1 and u1 once in 2-3 minutes to keep the accuracy. Actually, you can measure the drift between the clocks to find the optimal resync interval.

Interesting the point about the 64-bit casting as I wasn't aware on that. Means my current solution is 32-bit locked as I'm using (__int64*)&ft — Dave, Jan 04 '11 at 09:36
Whilst this isn't what I've ended up with, it is certainly closest to the logic I've used (albeit in a 32-bit locked version). This answer is probably better though! — Dave, Jan 04 '11 at 09:41

score 0 · Answer 3 · answered Dec 31 '10 at 13:11

I once wrote the code for this, but eventually abandoned it and made peace with OS time resolution. The code called both GetLocalTime and QueryPerformanceCounter in a tight loop for like 50 times. When I detect that result of GetLocalTime was changed by one resolution tick then I assume that result from corresponding QueryPerformanceCounter is close enough to the beginning of that tick. That way I get a precise time offset. From that point onward I call QueryPerformanceCounter and do math with time offset to get me a precise local time.

In the end I reasoned that all this is not worth so much trouble, and that I don't really need all that precision.

score 0 · Answer 4 · answered Dec 31 '10 at 13:41

What I'd do is to get the system time and the queryperfcounter at startup. You know have a reasonably accurate starting point.

Then call QueryPerformanceCounter() in your log system, subtract the start-QPC-value, divide by QPF to get seconds (store in a double), combine this value with the system time at startup and print.

score 0 · Answer 5 · answered Dec 31 '10 at 14:36

typedef struct _TIME_FIELDS {

USHORT Year; USHORT Month; USHORT Day; USHORT Hour; USHORT Minute; USHORT Second; USHORT Milliseconds; USHORT Weekday;

} TIME_FIELDS;

typedef signed __int64      INT64;
typedef unsigned __int64    UINT64;


INT64 get_current_time ()
{
    ULONG secs;
    LARGE_INTEGER tm;

    KeQuerySystemTime (&tm);

    RtlTimeToSecondsSince1970(&tm, &secs);

    /* NOTE: tm is in 100s of nano seconds */
    return (secs * 1000 + (tm.QuadPart/10000)%1000);
}

LARGE_INTEGER get_system_time ()
{
    LARGE_INTEGER tm;
    INT64 time = get_current_time ();

    RtlSecondsSince1970ToTime (time, &tm);

    /* NOTE: tm is in 100s of nano seconds */
    tm.QuadPart += (QTIME_MSECS(time)%1000)*10000;
    return tm;

}

int log_current_time ()
{
    static char* month_names[] =
    {
    "Jan",
    "Feb",
    "Mar",
    "Apr",
    "May",
    "Jun",
    "Jul",
    "Aug",
    "Sep",
    "Oct",
    "Nov",
    "Dec"
    };

    LARGE_INTEGER tm, lcl_time;
    TIME_FIELDS fields;

    tm = get_system_time ();

   ExSystemTimeToLocalTime (&tm, &lcl_time);

   RtlTimeToTimeFields(&tm, &fields);

    printf ("%s %02d %04d:%02d:%02d:%02d:%02d", month_names[fields.Month - 1],
        fields.Day, fields.Year, fields.Hour, fields.Minute, fields.Second,
        fileds.Milliseconds);
}

Please note that this code uses two undocumented things, TIME_FILEDS structure and RtlTimeToTimeFields function. I am using a similar implementation in my code and it works fine on all the current WIN NT flavors. However, using this is not guaranteed to be portable among the next WIN NT release

Log with timestamps that have millisecond accuracy & resolution in Windows C++

5 Answers5