Resolves QPID-4084, changing the format of high-res logged time from seconds-since-start to date/time, consistent with the POSIX version of the broker.

git-svn-id: https://svn.apache.org/repos/asf/qpid/trunk/qpid@1373147 13f79535-47bb-0310-9956-ffa450edef68

1 files changed, 60 insertions, 14 deletions

diff --git a/cpp/src/qpid/sys/windows/Time.cpp b/cpp/src/qpid/sys/windows/Time.cpp
index 25c50819cd..700a25391f 100644
--- a/cpp/src/qpid/sys/windows/Time.cpp
+++ b/cpp/src/qpid/sys/windows/Time.cpp
@@ -20,10 +20,12 @@
  */
 
 #include "qpid/sys/Time.h"
+#include <cmath>
 #include <ostream>
 #include <boost/date_time/posix_time/posix_time.hpp>
 #include <boost/thread/thread_time.hpp>
 #include <windows.h>
+#include <time.h>
 
 using namespace boost::posix_time;
 
@@ -33,8 +35,16 @@ namespace {
 // more or less. Keep track of the start value and the conversion factor to
 // seconds.
 bool timeInitialized = false;
-LARGE_INTEGER start;
-double freq = 1.0;
+LARGE_INTEGER start_hpc;
+double hpc_freq = 1.0;
+
+double start_time;
+
+/// Static constant to remove time skew between FILETIME and POSIX
+/// time.  POSIX and Win32 use different epochs (Jan. 1, 1970 v.s.
+/// Jan. 1, 1601).  The following constant defines the difference
+/// in 100ns ticks.
+const DWORDLONG FILETIME_to_timval_skew = 0x19db1ded53e8000;
 
 }
 
@@ -114,23 +124,59 @@ void outputFormattedNow(std::ostream& o) {
 }
 
 void outputHiresNow(std::ostream& o) {
+    ::time_t tv_sec;
+    ::tm timeinfo;
+    char time_string[100];
+
     if (!timeInitialized) {
-        start.QuadPart = 0;
+        // To start, get the current time from FILETIME which includes
+        // sub-second resolution. However, since FILETIME is updated a bit
+        // "bumpy" every 15 msec or so, future time displays will be the
+        // starting FILETIME plus a delta based on the high-resolution
+        // performance counter.
+        FILETIME file_time;
+        ULARGE_INTEGER start_usec;
+        ::GetSystemTimeAsFileTime(&file_time);   // This is in 100ns units
+        start_usec.LowPart = file_time.dwLowDateTime;
+        start_usec.HighPart = file_time.dwHighDateTime;
+        start_usec.QuadPart -= FILETIME_to_timval_skew;
+        start_usec.QuadPart /= 10;   // Convert 100ns to usec
+        tv_sec = (time_t)(start_usec.QuadPart / (1000 * 1000));
+        long tv_usec = (long)(start_usec.QuadPart % (1000 * 1000));
+        start_time = static_cast<double>(tv_sec);
+        start_time += tv_usec / 1000000.0;
+
+        start_hpc.QuadPart = 0;
         LARGE_INTEGER iFreq;
         iFreq.QuadPart = 1;
-        QueryPerformanceCounter(&start);
+        QueryPerformanceCounter(&start_hpc);
         QueryPerformanceFrequency(&iFreq);
-        freq = static_cast<double>(iFreq.QuadPart);
+        hpc_freq = static_cast<double>(iFreq.QuadPart);
         timeInitialized = true;
     }
-    LARGE_INTEGER iNow;
-    iNow.QuadPart = 0;
-    QueryPerformanceCounter(&iNow);
-    iNow.QuadPart -= start.QuadPart;
-    if (iNow.QuadPart < 0)
-        iNow.QuadPart = 0;
-    double now = static_cast<double>(iNow.QuadPart);
-    now /= freq;                 // now is seconds after this
-    o << std::fixed << std::setprecision(8) << std::setw(16) << std::setfill('0') << now << "s ";
+    LARGE_INTEGER hpc_now;
+    hpc_now.QuadPart = 0;
+    QueryPerformanceCounter(&hpc_now);
+    hpc_now.QuadPart -= start_hpc.QuadPart;
+    if (hpc_now.QuadPart < 0)
+        hpc_now.QuadPart = 0;
+    double now = static_cast<double>(hpc_now.QuadPart);
+    now /= hpc_freq;                 // now is seconds after this
+    double fnow = start_time + now;
+    double usec, sec;
+    usec = modf(fnow, &sec);
+    tv_sec = static_cast<time_t>(sec);
+#ifdef _MSC_VER
+    ::localtime_s(&timeinfo, &tv_sec);
+#else
+    timeinfo = *(::localtime(&tv_sec));
+#endif
+    ::strftime(time_string, 100,
+               "%Y-%m-%d %H:%M:%S",
+               &timeinfo);
+    // No way to set "max field width" to cleanly output the double usec so
+    // convert it back to integral number of usecs and print that.
+    unsigned long i_usec = usec * 1000 * 1000;
+    o << time_string << "." << std::setw(6) << std::setfill('0') << i_usec << " ";
 }
 }}