Improve --datetime accuracy

This commit has two changes to improve --datetime:

1) When processing an ETL, use full precision for the trace start time
   (previously was only using milliseconds).  This will result in the
   same present time for WPA and PresentMon when using --datetime and
   --etl_file.

2) When collecting in realtime with --datetime, this changes the ETW
   timestamp from QPC to SYSTEMTIME.  This ensures PresentMon's reported
   present start time will be the correct datetime, however it will not
   exactly match WPA.  WPA converts QPC into datetimes, but PresentMon
   cannot match that during realtime collection without using the same
   trace start time, which I can't find a way to query.

See issue #194

Author: JeffersonMontgomery-Intel

PresentData/TraceSession.cpp

@@ -352,8 +352,8 @@ void CALLBACK EventRecordCallback(EVENT_RECORD* pEventRecord)
     #pragma warning(disable: 4984) // c++17 extension
 
     if constexpr (SAVE_FIRST_TIMESTAMP) {
-        if (session->mStartQpc.QuadPart == 0) {
-            session->mStartQpc = hdr.TimeStamp;
+        if (session->mStartTimestamp.QuadPart == 0) {
+            session->mStartTimestamp = hdr.TimeStamp;
         }
     }
 
@@ -481,18 +481,19 @@ ULONG TraceSession::Start(
     PMTraceConsumer* pmConsumer,
     MRTraceConsumer* mrConsumer,
     wchar_t const* etlPath,
-    wchar_t const* sessionName)
+    wchar_t const* sessionName,
+    TimestampType timestampType)
 {
     assert(mSessionHandle == 0);
     assert(mTraceHandle == INVALID_PROCESSTRACE_HANDLE);
-    mStartQpc.QuadPart = 0;
+    mStartTimestamp.QuadPart = 0;
     mPMConsumer = pmConsumer;
     mMRConsumer = mrConsumer;
     mContinueProcessingBuffers = TRUE;
 
     // -------------------------------------------------------------------------
     // Configure trace properties
-    EVENT_TRACE_LOGFILE traceProps = {};
+    EVENT_TRACE_LOGFILEW traceProps = {};
     traceProps.LogFileName = (wchar_t*) etlPath;
     traceProps.ProcessTraceMode = PROCESS_TRACE_MODE_EVENT_RECORD | PROCESS_TRACE_MODE_RAW_TIMESTAMP;
     traceProps.Context = this;
@@ -528,7 +529,7 @@ ULONG TraceSession::Start(
 
         TraceProperties sessionProps = {};
         sessionProps.Wnode.BufferSize = (ULONG) sizeof(TraceProperties);
-        sessionProps.Wnode.ClientContext = 1;                     // Clock resolution to use when logging the timestamp for each event; 1 == query performance counter
+        sessionProps.Wnode.ClientContext = timestampType;         // Clock resolution to use when logging the timestamp for each event
         sessionProps.LogFileMode = EVENT_TRACE_REAL_TIME_MODE;    // We have a realtime consumer, not writing to a log file
         sessionProps.LogFileNameOffset = 0;                       // 0 means no output log file
         sessionProps.LoggerNameOffset = offsetof(TraceProperties, mSessionName);  // Location of session name; will be written by StartTrace()
@@ -556,7 +557,7 @@ ULONG TraceSession::Start(
         sessionProps.LoggerThreadId           // tracing session identifier
         */
 
-        auto status = StartTrace(&mSessionHandle, sessionName, &sessionProps);
+        auto status = StartTraceW(&mSessionHandle, sessionName, &sessionProps);
         if (status != ERROR_SUCCESS) {
             mSessionHandle = 0;
             return status;
@@ -571,7 +572,7 @@ ULONG TraceSession::Start(
 
     // -------------------------------------------------------------------------
     // Open the trace
-    mTraceHandle = OpenTrace(&traceProps);
+    mTraceHandle = OpenTraceW(&traceProps);
     if (mTraceHandle == INVALID_PROCESSTRACE_HANDLE) {
         auto lastError = GetLastError();
         Stop();
@@ -584,14 +585,15 @@ ULONG TraceSession::Start(
     // captures are based off the timestamp here.
 
     switch (traceProps.LogfileHeader.ReservedFlags) {
-    case 2: // System time
-        mQpcFrequency.QuadPart = 10000000ull;
+    case TIMESTAMP_TYPE_SYSTEM_TIME:
+        mTimestampFrequency.QuadPart = 10000000ull;
         break;
-    case 3: // CPU cycle counter
-        mQpcFrequency.QuadPart = 1000000ull * traceProps.LogfileHeader.CpuSpeedInMHz;
+    case TIMESTAMP_TYPE_CPU_CYCLE_COUNTER:
+        mTimestampFrequency.QuadPart = 1000000ull * traceProps.LogfileHeader.CpuSpeedInMHz;
         break;
-    default: // 1 == QPC
-        mQpcFrequency = traceProps.LogfileHeader.PerfFreq;
+    case TIMESTAMP_TYPE_QPC:
+    default:
+        mTimestampFrequency = traceProps.LogfileHeader.PerfFreq;
         break;
     }
 
@@ -602,17 +604,20 @@ ULONG TraceSession::Start(
         QueryPerformanceCounter(&qpc1);
         GetSystemTimeAsFileTime(&ft);
         QueryPerformanceCounter(&qpc2);
-        FileTimeToLocalFileTime(&ft, &mStartTime);
-        mStartQpc.QuadPart = qpc1.QuadPart + (qpc2.QuadPart - qpc1.QuadPart) / 2;
+        FileTimeToLocalFileTime(&ft, (FILETIME*) &mStartFileTime);
+        mStartTimestamp.QuadPart = (qpc1.QuadPart + qpc2.QuadPart) / 2;
     } else {
-        SYSTEMTIME ust = {};
-        SYSTEMTIME lst = {};
+        // Convert start FILETIME to local start FILETIME
+        SYSTEMTIME ust{};
+        SYSTEMTIME lst{};
         FileTimeToSystemTime((FILETIME const*) &traceProps.LogfileHeader.StartTime, &ust);
         SystemTimeToTzSpecificLocalTime(&traceProps.LogfileHeader.TimeZone, &ust, &lst);
-        SystemTimeToFileTime(&lst, &mStartTime);
+        SystemTimeToFileTime(&lst, (FILETIME*) &mStartFileTime);
+        // The above conversion stops at milliseconds, so copy the rest over too
+        mStartFileTime += traceProps.LogfileHeader.StartTime.QuadPart % 10000;
     }
 
-    InitializeTimestampInfo(&mStartQpc, mQpcFrequency);
+    InitializeTimestampInfo(&mStartTimestamp, mTimestampFrequency);
 
     return ERROR_SUCCESS;
 }

PresentData/TraceSession.hpp

@@ -5,20 +5,27 @@ struct PMTraceConsumer;
 struct MRTraceConsumer;
 
 struct TraceSession {
-    LARGE_INTEGER mStartQpc = {};
-    LARGE_INTEGER mQpcFrequency = {};
-    FILETIME mStartTime = {};
+    LARGE_INTEGER mStartTimestamp = {};
+    LARGE_INTEGER mTimestampFrequency = {};
+    uint64_t mStartFileTime = 0;
     PMTraceConsumer* mPMConsumer = nullptr;
     MRTraceConsumer* mMRConsumer = nullptr;
     TRACEHANDLE mSessionHandle = 0;                         // invalid session handles are 0
     TRACEHANDLE mTraceHandle = INVALID_PROCESSTRACE_HANDLE; // invalid trace handles are INVALID_PROCESSTRACE_HANDLE
     ULONG mContinueProcessingBuffers = TRUE;
 
+    enum TimestampType {
+        TIMESTAMP_TYPE_QPC = 1,
+        TIMESTAMP_TYPE_SYSTEM_TIME = 2,
+        TIMESTAMP_TYPE_CPU_CYCLE_COUNTER = 3,
+    };
+
     ULONG Start(
-        PMTraceConsumer* pmConsumer, // Required PMTraceConsumer instance
-        MRTraceConsumer* mrConsumer, // If nullptr, no WinMR tracing
-        wchar_t const* etlPath,         // If nullptr, live/realtime tracing session
-        wchar_t const* sessionName);    // Required session name
+        PMTraceConsumer* pmConsumer,  // Required PMTraceConsumer instance
+        MRTraceConsumer* mrConsumer,  // If nullptr, no WinMR tracing
+        wchar_t const* etlPath,       // If nullptr, live/realtime tracing session
+        wchar_t const* sessionName,   // Required session name
+        TimestampType timestampType); // Which timestamp type to use
 
     void Stop();
 

PresentMon/Console.cpp

@@ -266,7 +266,7 @@ void UpdateConsole(uint32_t processId, ProcessInfo const& processInfo)
 
         auto const& present0 = *chain.mPresentHistory[(chain.mNextPresentIndex - chain.mPresentHistoryCount) % SwapChainData::PRESENT_HISTORY_MAX_COUNT];
         auto const& presentN = *chain.mPresentHistory[(chain.mNextPresentIndex - 1) % SwapChainData::PRESENT_HISTORY_MAX_COUNT];
-        auto cpuAvg = QpcDeltaToSeconds(presentN.PresentStartTime - present0.PresentStartTime) / (chain.mPresentHistoryCount - 1);
+        auto cpuAvg = TimestampDeltaToSeconds(presentN.PresentStartTime - present0.PresentStartTime) / (chain.mPresentHistoryCount - 1);
         auto gpuAvg = 0.0;
         auto dspAvg = 0.0;
         auto latAvg = 0.0;
@@ -292,14 +292,14 @@ void UpdateConsole(uint32_t processId, ProcessInfo const& processInfo)
                 }
             }
 
-            gpuAvg = QpcDeltaToSeconds(gpuSum) / (chain.mPresentHistoryCount - 1);
+            gpuAvg = TimestampDeltaToSeconds(gpuSum) / (chain.mPresentHistoryCount - 1);
 
             if (displayCount >= 2) {
-                dspAvg = QpcDeltaToSeconds(displayN->ScreenTime - display0ScreenTime) / (displayCount - 1);
+                dspAvg = TimestampDeltaToSeconds(displayN->ScreenTime - display0ScreenTime) / (displayCount - 1);
             }
 
             if (displayCount >= 1) {
-                latAvg = QpcDeltaToSeconds(latSum) / displayCount;
+                latAvg = TimestampDeltaToSeconds(latSum) / displayCount;
             }
         }
 

PresentMon/CsvOutput.cpp

@@ -112,34 +112,34 @@ void UpdateCsv(ProcessInfo* processInfo, SwapChainData const& chain, PresentEven
     auto lastPresented = chain.mPresentHistory[(chain.mNextPresentIndex - 1) % SwapChainData::PRESENT_HISTORY_MAX_COUNT].get();
 
     // Compute frame statistics.
-    double msBetweenPresents      = 1000.0 * PositiveQpcDeltaToSeconds(lastPresented->PresentStartTime, p.PresentStartTime);
-    double msInPresentApi         = 1000.0 * PositiveQpcDeltaToSeconds(p.PresentStartTime, p.PresentStopTime);
+    double msBetweenPresents      = 1000.0 * PositiveTimestampDeltaToSeconds(lastPresented->PresentStartTime, p.PresentStartTime);
+    double msInPresentApi         = 1000.0 * PositiveTimestampDeltaToSeconds(p.PresentStartTime, p.PresentStopTime);
     double msUntilRenderComplete  = 0.0;
     double msUntilDisplayed       = 0.0;
     double msBetweenDisplayChange = 0.0;
 
     if (args.mTrackDisplay) {
-        msUntilRenderComplete = 1000.0 * QpcDeltaToSeconds(p.PresentStartTime, p.ReadyTime);
+        msUntilRenderComplete = 1000.0 * TimestampDeltaToSeconds(p.PresentStartTime, p.ReadyTime);
 
         if (presented) {
-            msUntilDisplayed = 1000.0 * PositiveQpcDeltaToSeconds(p.PresentStartTime, p.ScreenTime);
+            msUntilDisplayed = 1000.0 * PositiveTimestampDeltaToSeconds(p.PresentStartTime, p.ScreenTime);
 
             if (chain.mLastDisplayedPresentIndex != UINT32_MAX) {
                 auto lastDisplayed = chain.mPresentHistory[chain.mLastDisplayedPresentIndex % SwapChainData::PRESENT_HISTORY_MAX_COUNT].get();
-                msBetweenDisplayChange = 1000.0 * PositiveQpcDeltaToSeconds(lastDisplayed->ScreenTime, p.ScreenTime);
+                msBetweenDisplayChange = 1000.0 * PositiveTimestampDeltaToSeconds(lastDisplayed->ScreenTime, p.ScreenTime);
             }
         }
     }
 
     double msUntilRenderStart = 0.0;
     if (args.mTrackGPU) {
-        msUntilRenderStart = 1000.0 * QpcDeltaToSeconds(p.PresentStartTime, p.GPUStartTime);
+        msUntilRenderStart = 1000.0 * TimestampDeltaToSeconds(p.PresentStartTime, p.GPUStartTime);
     }
 
     double msSinceInput = 0.0;
     if (args.mTrackInput) {
         if (p.InputTime != 0) {
-            msSinceInput = 1000.0 * QpcDeltaToSeconds(p.PresentStartTime - p.InputTime);
+            msSinceInput = 1000.0 * TimestampDeltaToSeconds(p.PresentStartTime - p.InputTime);
         }
     }
 
@@ -155,7 +155,7 @@ void UpdateCsv(ProcessInfo* processInfo, SwapChainData const& chain, PresentEven
     if (args.mOutputDateTime) {
         SYSTEMTIME st = {};
         uint64_t ns = 0;
-        QpcToLocalSystemTime(p.PresentStartTime, &st, &ns);
+        TimestampToLocalSystemTime(p.PresentStartTime, &st, &ns);
         fwprintf(fp, L"%u-%u-%u %u:%02u:%02u.%09llu",
             st.wYear,
             st.wMonth,
@@ -165,7 +165,7 @@ void UpdateCsv(ProcessInfo* processInfo, SwapChainData const& chain, PresentEven
             st.wSecond,
             ns);
     } else {
-        fwprintf(fp, L"%.*lf", DBL_DIG - 1, QpcToSeconds(p.PresentStartTime));
+        fwprintf(fp, L"%.*lf", DBL_DIG - 1, TimestampToSeconds(p.PresentStartTime));
     }
     fwprintf(fp, L",%.*lf,%.*lf",
         DBL_DIG - 1, msInPresentApi,
@@ -186,18 +186,18 @@ void UpdateCsv(ProcessInfo* processInfo, SwapChainData const& chain, PresentEven
     if (args.mTrackGPU) {
         fwprintf(fp, L",%.*lf,%.*lf",
             DBL_DIG - 1, msUntilRenderStart,
-            DBL_DIG - 1, 1000.0 * QpcDeltaToSeconds(p.GPUDuration));
+            DBL_DIG - 1, 1000.0 * TimestampDeltaToSeconds(p.GPUDuration));
     }
     if (args.mTrackGPUVideo) {
         fwprintf(fp, L",%.*lf",
-            DBL_DIG - 1, 1000.0 * QpcDeltaToSeconds(p.GPUVideoDuration));
+            DBL_DIG - 1, 1000.0 * TimestampDeltaToSeconds(p.GPUVideoDuration));
     }
     if (args.mTrackInput) {
         fwprintf(fp, L",%.*lf", DBL_DIG - 1, msSinceInput);
     }
     if (args.mOutputQpcTime) {
         if (args.mOutputQpcTimeInSeconds) {
-            fwprintf(fp, L",%.*lf", DBL_DIG - 1, QpcDeltaToSeconds(p.PresentStartTime));
+            fwprintf(fp, L",%.*lf", DBL_DIG - 1, TimestampDeltaToSeconds(p.PresentStartTime));
         } else {
             fwprintf(fp, L",%llu", p.PresentStartTime);
         }

PresentMon/LateStageReprojectionData.cpp

@@ -14,7 +14,7 @@ enum {
 void LateStageReprojectionData::PruneDeque(std::deque<LateStageReprojectionEvent> &lsrHistory, uint32_t msTimeDiff, uint32_t maxHistLen) {
     while (!lsrHistory.empty() && (
         lsrHistory.size() > maxHistLen ||
-        1000.0 * QpcDeltaToSeconds(lsrHistory.back().QpcTime - lsrHistory.front().QpcTime) > msTimeDiff)) {
+        1000.0 * TimestampDeltaToSeconds(lsrHistory.back().QpcTime - lsrHistory.front().QpcTime) > msTimeDiff)) {
         lsrHistory.pop_front();
     }
 }
@@ -63,7 +63,7 @@ double LateStageReprojectionData::ComputeHistoryTime(const std::deque<LateStageR
 
     auto start = lsrHistory.front().QpcTime;
     auto end = lsrHistory.back().QpcTime;
-    return QpcDeltaToSeconds(end - start);
+    return TimestampDeltaToSeconds(end - start);
 }
 
 size_t LateStageReprojectionData::ComputeHistorySize() const
@@ -89,7 +89,7 @@ double LateStageReprojectionData::ComputeFps(const std::deque<LateStageReproject
     auto end = lsrHistory.back().QpcTime;
     auto count = lsrHistory.size() - 1;
 
-    return count / QpcDeltaToSeconds(end - start);
+    return count / TimestampDeltaToSeconds(end - start);
 }
 
 double LateStageReprojectionData::ComputeSourceFps() const
@@ -168,8 +168,8 @@ LateStageReprojectionRuntimeStats LateStageReprojectionData::ComputeRuntimeStats
     stats.mAppProcessId = mLSRHistory[count - 1].GetAppProcessId();
     stats.mLsrProcessId = mLSRHistory[count - 1].ProcessId;
 
-    stats.mAppSourceCpuRenderTimeInMs = 1000.0 * QpcDeltaToSeconds(totalAppSourceCpuRenderTime);
-    stats.mAppSourceReleaseToLsrAcquireInMs = 1000.0 * QpcDeltaToSeconds(totalAppSourceReleaseToLsrAcquireTime);
+    stats.mAppSourceCpuRenderTimeInMs = 1000.0 * TimestampDeltaToSeconds(totalAppSourceCpuRenderTime);
+    stats.mAppSourceReleaseToLsrAcquireInMs = 1000.0 * TimestampDeltaToSeconds(totalAppSourceReleaseToLsrAcquireTime);
 
     stats.mAppSourceReleaseToLsrAcquireInMs /= count;
     stats.mAppSourceCpuRenderTimeInMs /= count;
@@ -249,8 +249,8 @@ void UpdateLsrCsv(LateStageReprojectionData& lsr, ProcessInfo* proc, LateStageRe
 
     auto& curr = lsr.mLSRHistory[len - 1];
     auto& prev = lsr.mLSRHistory[len - 2];
-    const double deltaMilliseconds = 1000.0 * QpcDeltaToSeconds(curr.QpcTime - prev.QpcTime);
-    const double timeInSeconds = QpcToSeconds(p.QpcTime);
+    const double deltaMilliseconds = 1000.0 * TimestampDeltaToSeconds(curr.QpcTime - prev.QpcTime);
+    const double timeInSeconds = TimestampToSeconds(p.QpcTime);
 
     fprintf(fp, "%ws,%d,%d", proc->mModuleName.c_str(), curr.GetAppProcessId(), curr.ProcessId);
     if (args.mTrackDebug) {
@@ -262,18 +262,18 @@ void UpdateLsrCsv(LateStageReprojectionData& lsr, ProcessInfo* proc, LateStageRe
         double appPresentToLsrMilliseconds = 0.0;
         if (curr.IsValidAppFrame()) {
             const uint64_t currAppPresentTime = curr.GetAppPresentTime();
-            appPresentToLsrMilliseconds = 1000.0 * QpcDeltaToSeconds(curr.QpcTime - currAppPresentTime);
+            appPresentToLsrMilliseconds = 1000.0 * TimestampDeltaToSeconds(curr.QpcTime - currAppPresentTime);
 
             if (prev.IsValidAppFrame() && (curr.GetAppProcessId() == prev.GetAppProcessId())) {
                 const uint64_t prevAppPresentTime = prev.GetAppPresentTime();
-                appPresentDeltaMilliseconds = 1000.0 * QpcDeltaToSeconds(currAppPresentTime - prevAppPresentTime);
+                appPresentDeltaMilliseconds = 1000.0 * TimestampDeltaToSeconds(currAppPresentTime - prevAppPresentTime);
             }
         }
         fprintf(fp, ",%.6lf,%.6lf", appPresentDeltaMilliseconds, appPresentToLsrMilliseconds);
     }
     fprintf(fp, ",%.6lf,%d,%d", deltaMilliseconds, !curr.NewSourceLatched, curr.MissedVsyncCount);
     if (args.mTrackDebug) {
-        fprintf(fp, ",%.6lf,%.6lf", 1000 * QpcDeltaToSeconds(curr.Source.GetReleaseFromRenderingToAcquireForPresentationTime()), 1000.0 * QpcDeltaToSeconds(curr.GetAppCpuRenderFrameTime()));
+        fprintf(fp, ",%.6lf,%.6lf", 1000 * TimestampDeltaToSeconds(curr.Source.GetReleaseFromRenderingToAcquireForPresentationTime()), 1000.0 * TimestampDeltaToSeconds(curr.GetAppCpuRenderFrameTime()));
     }
     fprintf(fp, ",%.6lf", curr.AppPredictionLatencyMs);
     if (args.mTrackDebug) {

PresentMon/OutputThread.cpp

@@ -345,12 +345,12 @@ static void PruneHistory(
 {
     assert(processEvents.size() + presentEvents.size() + lsrEvents.size() > 0);
 
-    auto latestQpc = std::max(std::max(
+    auto latestTimestamp = std::max(std::max(
         processEvents.empty() ? 0ull : processEvents.back().QpcTime,
         presentEvents.empty() ? 0ull : presentEvents.back()->PresentStartTime),
         lsrEvents.empty()     ? 0ull : lsrEvents.back()->QpcTime);
 
-    auto minQpc = latestQpc - SecondsDeltaToQpc(2.0);
+    auto minTimestamp = latestTimestamp - SecondsDeltaToTimestamp(2.0);
 
     for (auto& pair : gProcesses) {
         auto processInfo = &pair.second;
@@ -361,7 +361,7 @@ static void PruneHistory(
             for (; count > 0; --count) {
                 auto index = swapChain->mNextPresentIndex - count;
                 auto const& presentEvent = swapChain->mPresentHistory[index % SwapChainData::PRESENT_HISTORY_MAX_COUNT];
-                if (presentEvent->PresentStartTime >= minQpc) {
+                if (presentEvent->PresentStartTime >= minTimestamp) {
                     break;
                 }
                 if (index == swapChain->mLastDisplayedPresentIndex) {

PresentMon/PresentMon.hpp

@@ -155,9 +155,9 @@ void DequeueAnalyzedInfo(
     std::vector<std::shared_ptr<PresentEvent>>* presentEvents,
     std::vector<std::shared_ptr<PresentEvent>>* lostPresentEvents,
     std::vector<std::shared_ptr<LateStageReprojectionEvent>>* lsrs);
-double QpcDeltaToSeconds(uint64_t qpcDelta);
-double QpcDeltaToSeconds(uint64_t qpcFrom, uint64_t qpcTo);
-double PositiveQpcDeltaToSeconds(uint64_t qpcFrom, uint64_t qpcTo);
-uint64_t SecondsDeltaToQpc(double secondsDelta);
-double QpcToSeconds(uint64_t qpc);
-void QpcToLocalSystemTime(uint64_t qpc, SYSTEMTIME* st, uint64_t* ns);
+double TimestampDeltaToSeconds(uint64_t timestampDelta);
+double TimestampDeltaToSeconds(uint64_t timestampFrom, uint64_t timestampTo);
+double PositiveTimestampDeltaToSeconds(uint64_t timestampFrom, uint64_t timestampTo);
+uint64_t SecondsDeltaToTimestamp(double secondsDelta);
+double TimestampToSeconds(uint64_t timestamp);
+void TimestampToLocalSystemTime(uint64_t timestamp, SYSTEMTIME* st, uint64_t* ns);