diff --git a/.gitignore b/.gitignore index b4a43b56..b99e119c 100644 --- a/.gitignore +++ b/.gitignore @@ -3,6 +3,13 @@ # Build results /build/ +PresentMon/build/ + +# Claude Code +.claude/ + +# Accidental nul file from Windows commands +PresentMon/nul # vcpkg dependencies /vcpkg_installed/ diff --git a/PresentData/GpuTrace.cpp b/PresentData/GpuTrace.cpp index 717de24f..bcfc0f17 100644 --- a/PresentData/GpuTrace.cpp +++ b/PresentData/GpuTrace.cpp @@ -75,6 +75,16 @@ GpuTrace::GpuTrace(PMTraceConsumer* pmConsumer) { } +GpuTrace::~GpuTrace() +{ + for (auto& pair : mContexts) { + auto context = pair.second; + if (context.mIsHwQueue) { + delete context.mNode; + } + } +} + void GpuTrace::RegisterDevice(uint64_t hDevice, uint64_t pDxgAdapter) { // Sometimes there are duplicate start events diff --git a/PresentData/GpuTrace.hpp b/PresentData/GpuTrace.hpp index 0cd38256..1e7fae5e 100644 --- a/PresentData/GpuTrace.hpp +++ b/PresentData/GpuTrace.hpp @@ -75,6 +75,7 @@ class GpuTrace { public: explicit GpuTrace(PMTraceConsumer* pmConsumer); + ~GpuTrace(); void RegisterDevice(uint64_t hDevice, uint64_t pDxgAdapter); void UnregisterDevice(uint64_t hDevice); diff --git a/PresentData/PresentMonTraceConsumer.cpp b/PresentData/PresentMonTraceConsumer.cpp index 355bbdfa..43cf2731 100644 --- a/PresentData/PresentMonTraceConsumer.cpp +++ b/PresentData/PresentMonTraceConsumer.cpp @@ -2365,8 +2365,8 @@ void PMTraceConsumer::CompletePresent(std::shared_ptr const& p) static_cast(appFrameId - it->second.FrameId) >= 10) { // Remove the app frame data if the app frame id is too old it = mAppTimingDataByAppFrameId.erase(it); // Erase and move to the next element - } else if (appFrameId == 0 && it->second.ProcessId == processId && - it->second.AssignedToPresent == false && it->second.AppPresentStartTime != 0 && + } else if (appFrameId == 0 && it->second.ProcessId == processId && + it->second.AssignedToPresent == false && it->second.AppPresentStartTime != 0 && presentStartTime >= it->second.AppPresentStartTime && presentStartTime - it->second.AppPresentStartTime >= mDeferralTimeLimit) { // Remove app frame data if the app present start time is too old @@ -2376,6 +2376,47 @@ void PMTraceConsumer::CompletePresent(std::shared_ptr const& p) ++it; // Move to the next element } } + + // Prune out old PC Latency timing data to prevent memory leaks. + // This is critical because PCL data accumulates for every frame and the + // PCLStatsShutdown event (the only other cleanup mechanism) is app-controlled. + if (mTrackPcLatency) { + auto pclFrameId = present->PclFrameId; + for (auto it = mPclTimingDataByPclFrameId.begin(); it != mPclTimingDataByPclFrameId.end();) { + if (it->first.second == processId) { + // For entries from this process: + // 1. Remove if assigned and frame ID is too old (10+ frames behind) + // 2. Remove if timestamp is too old (stale data - assigned or not) + bool shouldRemove = false; + + // Get the best available timestamp for this entry + uint64_t timingValue = mUsingOutOfBoundPresentStart + ? it->second.PclOutOfBandPresentStartTime + : it->second.PclPresentStartTime; + if (timingValue == 0) { + timingValue = it->second.PclSimStartTime; + } + + if (pclFrameId != 0 && it->second.AssignedToPresent && + static_cast(pclFrameId - it->second.FrameId) >= 10) { + // Remove assigned PCL data if frame id is too old + shouldRemove = true; + } else if (timingValue != 0 && presentStartTime >= timingValue && + presentStartTime - timingValue >= mDeferralTimeLimit) { + // Remove PCL data (assigned or not) if timestamp is too old + shouldRemove = true; + } + + if (shouldRemove) { + it = mPclTimingDataByPclFrameId.erase(it); + } else { + ++it; + } + } else { + ++it; + } + } + } } void PMTraceConsumer::UpdateReadyCount(bool useLock) @@ -2708,6 +2749,16 @@ void PMTraceConsumer::HandleProcessEvent(EVENT_RECORD* pEventRecord) event.ProcessId = desc[0].GetData(); event.IsStartEvent = false; + // Clean up PC Latency tracking data for this process to prevent memory leaks. + // This is necessary because PCLStatsShutdown events are application-controlled + // and may not be sent if the app crashes or terminates abnormally. + if (mTrackPcLatency) { + std::erase_if(mPclTimingDataByPclFrameId, [&event](const auto& p) { + return p.first.second == event.ProcessId; + }); + mLatestPingTimestampByProcessId.erase(event.ProcessId); + } + break; } default: @@ -2734,6 +2785,14 @@ void PMTraceConsumer::HandleProcessEvent(EVENT_RECORD* pEventRecord) mMetadata.GetEventData(pEventRecord, desc, _countof(desc)); event.ProcessId = desc[0].GetData(); event.IsStartEvent = false; + + // Clean up PC Latency tracking data for this process to prevent memory leaks. + if (mTrackPcLatency) { + std::erase_if(mPclTimingDataByPclFrameId, [&event](const auto& p) { + return p.first.second == event.ProcessId; + }); + mLatestPingTimestampByProcessId.erase(event.ProcessId); + } } else { return; } diff --git a/PresentData/PresentMonTraceSession.cpp b/PresentData/PresentMonTraceSession.cpp index bf55805e..d9caadbf 100644 --- a/PresentData/PresentMonTraceSession.cpp +++ b/PresentData/PresentMonTraceSession.cpp @@ -477,6 +477,9 @@ ULONG PMTraceSession::Start( sessionProps.Wnode.Flags = WNODE_FLAG_TRACED_GUID; sessionProps.LogFileMode = EVENT_TRACE_REAL_TIME_MODE; // We have a realtime consumer, not writing to a log file sessionProps.LoggerNameOffset = offsetof(TraceProperties, mSessionName); // Location of session name; will be written by StartTrace() + sessionProps.BufferSize = 64; // Buffer size in KB + sessionProps.MinimumBuffers = 256; // Minimum number of buffers allocated for the session's buffer pool + sessionProps.MaximumBuffers = 1024; // Maximum number of buffers (0 = no limit) auto status = StartTraceW(&mSessionHandle, sessionName, &sessionProps); if (status != ERROR_SUCCESS) { @@ -656,6 +659,41 @@ void PMTraceSession::TimestampToLocalSystemTime(uint64_t timestamp, SYSTEMTIME* *ns = (timestamp % 10000000) * 100; } +bool PMTraceSession::QueryEtwStatus(EtwStatus* status) const +{ + if (mSessionHandle == 0) { + return false; + } + + TraceProperties sessionProps = {}; + sessionProps.Wnode.BufferSize = (ULONG) sizeof(TraceProperties); + sessionProps.LoggerNameOffset = offsetof(TraceProperties, mSessionName); + + auto queryStatus = ControlTraceW(mSessionHandle, nullptr, &sessionProps, EVENT_TRACE_CONTROL_QUERY); + if (queryStatus != ERROR_SUCCESS) { + return false; + } + + // Update cached status + mCachedEtwStatus.mEtwBuffersInUse = sessionProps.NumberOfBuffers - sessionProps.FreeBuffers; + mCachedEtwStatus.mEtwTotalBuffers = sessionProps.NumberOfBuffers; + mCachedEtwStatus.mEtwEventsLost = sessionProps.EventsLost; + mCachedEtwStatus.mEtwBuffersLost = sessionProps.LogBuffersLost + sessionProps.RealTimeBuffersLost; + + if (sessionProps.NumberOfBuffers > 0) { + mCachedEtwStatus.mEtwBufferFillPct = 100.0 * mCachedEtwStatus.mEtwBuffersInUse / sessionProps.NumberOfBuffers; + } else { + mCachedEtwStatus.mEtwBufferFillPct = 0.0; + } + + // Copy to output if provided + if (status != nullptr) { + *status = mCachedEtwStatus; + } + + return true; +} + ULONG EnableProvidersListing( TRACEHANDLE sessionHandle, const GUID* pSessionGuid, diff --git a/PresentData/PresentMonTraceSession.hpp b/PresentData/PresentMonTraceSession.hpp index d292e2be..7d170fdf 100644 --- a/PresentData/PresentMonTraceSession.hpp +++ b/PresentData/PresentMonTraceSession.hpp @@ -6,6 +6,14 @@ struct PMTraceConsumer; +struct EtwStatus { + double mEtwBufferFillPct; + ULONG mEtwBuffersInUse; + ULONG mEtwTotalBuffers; + ULONG mEtwEventsLost; + ULONG mEtwBuffersLost; +}; + struct PMTraceSession { enum TimestampType { TIMESTAMP_TYPE_QPC = 1, @@ -38,6 +46,9 @@ struct PMTraceSession { bool mIsRealtimeSession = false; + // Cached ETW status for CSV output (updated periodically via QueryEtwStatus) + mutable EtwStatus mCachedEtwStatus = {}; + ULONG Start(wchar_t const* etlPath, // If nullptr, start a live/realtime tracing session wchar_t const* sessionName); // Required session name void Stop(); @@ -48,6 +59,8 @@ struct PMTraceSession { double TimestampToMilliSeconds(uint64_t timestamp) const; void TimestampToLocalSystemTime(uint64_t timestamp, SYSTEMTIME* st, uint64_t* ns) const; uint64_t MilliSecondsDeltaToTimestamp(double millisecondsDelta) const; + + bool QueryEtwStatus(EtwStatus* status) const; }; ULONG StopNamedTraceSession(wchar_t const* sessionName); diff --git a/PresentMon/CommandLine.cpp b/PresentMon/CommandLine.cpp index c0236ed7..8bb10dbc 100644 --- a/PresentMon/CommandLine.cpp +++ b/PresentMon/CommandLine.cpp @@ -411,6 +411,7 @@ bool ParseCommandLine(int argc, wchar_t** argv) args->mWriteFrameId = false; args->mWriteDisplayTime = false; args->mDisableOfflineBackpressure = false; + args->mTrackEtwStatus = false; bool sessionNameSet = false; bool csvOutputStdout = false; @@ -479,6 +480,7 @@ bool ParseCommandLine(int argc, wchar_t** argv) else if (ParseArg(argv[i], L"write_frame_id")) { args->mWriteFrameId = true; continue; } else if (ParseArg(argv[i], L"write_display_time")) { args->mWriteDisplayTime = true; continue; } else if (ParseArg(argv[i], L"disable_offline_backpressure")) { args->mDisableOfflineBackpressure = true; continue; } + else if (ParseArg(argv[i], L"track_etw_status")) { args->mTrackEtwStatus = true; continue; } // Provided argument wasn't recognized else if (!(ParseArg(argv[i], L"?") || ParseArg(argv[i], L"h") || ParseArg(argv[i], L"help"))) { diff --git a/PresentMon/ConsoleApplication.sln b/PresentMon/ConsoleApplication.sln index af79fb82..1d779663 100644 --- a/PresentMon/ConsoleApplication.sln +++ b/PresentMon/ConsoleApplication.sln @@ -1,7 +1,7 @@  Microsoft Visual Studio Solution File, Format Version 12.00 -# Visual Studio Version 17 -VisualStudioVersion = 17.6.33723.286 +# Visual Studio Version 18 +VisualStudioVersion = 18.1.11312.151 d18.0 MinimumVisualStudioVersion = 10.0.40219.1 Project("{8BC9CEB8-8B4A-11D0-8D11-00A0C91BC942}") = "PresentData", "..\PresentData\PresentData.vcxproj", "{892028E5-32F6-45FC-8AB2-90FCBCAC4BF6}" EndProject @@ -10,6 +10,8 @@ Project("{8BC9CEB8-8B4A-11D0-8D11-00A0C91BC942}") = "PresentMon", "PresentMon.vc {892028E5-32F6-45FC-8AB2-90FCBCAC4BF6} = {892028E5-32F6-45FC-8AB2-90FCBCAC4BF6} EndProjectSection EndProject +Project("{8BC9CEB8-8B4A-11D0-8D11-00A0C91BC942}") = "CommonUtilities", "..\IntelPresentMon\CommonUtilities\CommonUtilities.vcxproj", "{08A704D8-CA1C-45E9-8EDE-542A1A43B53E}" +EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|ARM = Debug|ARM @@ -54,6 +56,22 @@ Global {4EB9794B-1F12-48CE-ADC1-917E9810F29E}.Release|x64.Build.0 = Release|x64 {4EB9794B-1F12-48CE-ADC1-917E9810F29E}.Release|x86.ActiveCfg = Release|Win32 {4EB9794B-1F12-48CE-ADC1-917E9810F29E}.Release|x86.Build.0 = Release|Win32 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Debug|ARM.ActiveCfg = Debug|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Debug|ARM.Build.0 = Debug|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Debug|ARM64.ActiveCfg = Debug|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Debug|ARM64.Build.0 = Debug|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Debug|x64.ActiveCfg = Debug|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Debug|x64.Build.0 = Debug|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Debug|x86.ActiveCfg = Debug|Win32 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Debug|x86.Build.0 = Debug|Win32 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Release|ARM.ActiveCfg = Release|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Release|ARM.Build.0 = Release|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Release|ARM64.ActiveCfg = Release|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Release|ARM64.Build.0 = Release|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Release|x64.ActiveCfg = Release|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Release|x64.Build.0 = Release|x64 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Release|x86.ActiveCfg = Release|Win32 + {08A704D8-CA1C-45E9-8EDE-542A1A43B53E}.Release|x86.Build.0 = Release|Win32 EndGlobalSection GlobalSection(SolutionProperties) = preSolution HideSolutionNode = FALSE diff --git a/PresentMon/CsvOutput.cpp b/PresentMon/CsvOutput.cpp index 1f7efe70..a3ca7c18 100644 --- a/PresentMon/CsvOutput.cpp +++ b/PresentMon/CsvOutput.cpp @@ -179,6 +179,13 @@ void WriteCsvHeader(FILE* fp) if (args.mWriteFrameId) { fwprintf(fp, L",FrameId"); } + if (args.mTrackEtwStatus) { + fwprintf(fp, L",EtwBufferFillPct" + L",EtwBuffersInUse" + L",EtwTotalBuffers" + L",EtwEventsLost" + L",EtwBuffersLost"); + } fwprintf(fp, L"\n"); if (args.mCSVOutput == CSVOutput::Stdout) { @@ -259,6 +266,14 @@ void WriteCsvRow( if (args.mWriteFrameId) { fwprintf(fp, L",%u", p.FrameId); } + if (args.mTrackEtwStatus) { + fwprintf(fp, L",%.1lf,%lu,%lu,%lu,%lu", + pmSession.mCachedEtwStatus.mEtwBufferFillPct, + pmSession.mCachedEtwStatus.mEtwBuffersInUse, + pmSession.mCachedEtwStatus.mEtwTotalBuffers, + pmSession.mCachedEtwStatus.mEtwEventsLost, + pmSession.mCachedEtwStatus.mEtwBuffersLost); + } fwprintf(fp, L"\n"); if (args.mCSVOutput == CSVOutput::Stdout) { @@ -393,6 +408,13 @@ void WriteCsvHeader(FILE* fp) fwprintf(fp, L",PCLFrameId"); } } + if (args.mTrackEtwStatus) { + fwprintf(fp, L",EtwBufferFillPct" + L",EtwBuffersInUse" + L",EtwTotalBuffers" + L",EtwEventsLost" + L",EtwBuffersLost"); + } fwprintf(fp, L"\n"); if (args.mCSVOutput == CSVOutput::Stdout) { @@ -606,6 +628,14 @@ void WriteCsvRow( fwprintf(fp, L",%u", p.PclFrameId); } } + if (args.mTrackEtwStatus) { + fwprintf(fp, L",%.1lf,%lu,%lu,%lu,%lu", + pmSession.mCachedEtwStatus.mEtwBufferFillPct, + pmSession.mCachedEtwStatus.mEtwBuffersInUse, + pmSession.mCachedEtwStatus.mEtwTotalBuffers, + pmSession.mCachedEtwStatus.mEtwEventsLost, + pmSession.mCachedEtwStatus.mEtwBuffersLost); + } fwprintf(fp, L"\n"); if (args.mCSVOutput == CSVOutput::Stdout) { diff --git a/PresentMon/MainThread.cpp b/PresentMon/MainThread.cpp index ca4bb719..d2741553 100644 --- a/PresentMon/MainThread.cpp +++ b/PresentMon/MainThread.cpp @@ -11,11 +11,15 @@ enum { // Timer ID's must be non-zero DELAY_TIMER_ID = 1, TIMED_TIMER_ID = 2, + ETW_STATUS_TIMER_ID = 3, }; +static constexpr UINT ETW_STATUS_INTERVAL_MS = 1000; // Query ETW status every 1 second + static HWND gWnd = NULL; static bool gIsRecording = false; static uint32_t gHotkeyIgnoreCount = 0; +static PMTraceSession* gPMTraceSession = nullptr; static bool LoadNVDDManifest() { @@ -77,6 +81,23 @@ static bool IsRecording() return gIsRecording; } +static void OutputEtwStatus() +{ + if (gPMTraceSession == nullptr) { + return; + } + + EtwStatus status = {}; + if (gPMTraceSession->QueryEtwStatus(&status)) { + wprintf(L"[ETW Status] BufferFillPct=%.1f%% BuffersInUse=%lu TotalBuffers=%lu EventsLost=%lu BuffersLost=%lu\n", + status.mEtwBufferFillPct, + status.mEtwBuffersInUse, + status.mEtwTotalBuffers, + status.mEtwEventsLost, + status.mEtwBuffersLost); + } +} + static void StartRecording() { auto const& args = GetCommandLineArgs(); @@ -164,6 +185,10 @@ static LRESULT CALLBACK HandleWindowMessage(HWND hWnd, UINT uMsg, WPARAM wParam, ExitMainThread(); } return 0; + + case ETW_STATUS_TIMER_ID: + OutputEtwStatus(); + return 0; } break; @@ -301,6 +326,7 @@ int wmain(int argc, wchar_t** argv) // Start the ETW trace session. PMTraceSession pmSession; pmSession.mPMConsumer = &pmConsumer; + gPMTraceSession = &pmSession; auto status = pmSession.Start(args.mEtlFileName, args.mSessionName); // If a session with this same name is already running, we either exit or @@ -377,6 +403,13 @@ int wmain(int argc, wchar_t** argv) PostMessageW(gWnd, WM_HOTKEY, HOTKEY_ID, args.mHotkeyModifiers & ~MOD_NOREPEAT); } + // Start ETW status monitoring timer if requested (only for realtime sessions) + if (args.mTrackEtwStatus && args.mEtlFileName == nullptr) { + // Query initial status immediately so CSV output has valid values from the start + pmSession.QueryEtwStatus(nullptr); + SetTimer(gWnd, ETW_STATUS_TIMER_ID, ETW_STATUS_INTERVAL_MS, (TIMERPROC) nullptr); + } + // Enter the MainThread message loop. This thread will block waiting for // any window messages, dispatching the appropriate function to // HandleWindowMessage(), and then blocking again until the WM_QUIT message @@ -395,10 +428,15 @@ int wmain(int argc, wchar_t** argv) } // Stop the trace session. + if (args.mTrackEtwStatus && args.mEtlFileName == nullptr) { + KillTimer(gWnd, ETW_STATUS_TIMER_ID); + } + if (args.mScrollLockIndicator) { EnableScrollLock(originalScrollLockEnabled); } + gPMTraceSession = nullptr; pmSession.Stop(); // Wait for the consumer and output threads to end (which are using the diff --git a/PresentMon/PresentMon.hpp b/PresentMon/PresentMon.hpp index 389855c2..611ccf32 100644 --- a/PresentMon/PresentMon.hpp +++ b/PresentMon/PresentMon.hpp @@ -102,6 +102,7 @@ struct CommandLineArgs { bool mWriteFrameId; bool mWriteDisplayTime; bool mDisableOfflineBackpressure; + bool mTrackEtwStatus; }; // Metrics computed per-frame. Duration and Latency metrics are in milliseconds.