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?

Answer 1

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.