Eliminate 1000ms ETW latency (true realtime overlay)

IntelPresentMon/AppCef/Web/src/core/preferences.ts

@@ -27,6 +27,8 @@ export interface Preferences {
     metricPollRate: number;
     overlayDrawRate: number;
     telemetrySamplingPeriodMs: number;
+    etwFlushPeriod: number;
+    manualEtwFlush: boolean;
     metricsOffset: number;
     metricsWindow: number;
     overlayPosition: OverlayPosition;
@@ -65,8 +67,10 @@ export function makeDefaultPreferences(): Preferences {
         independentWindow: false,
         metricPollRate: 40,
         overlayDrawRate: 10,
-        telemetrySamplingPeriodMs: 100, 
-        metricsOffset: 1020, 
+        telemetrySamplingPeriodMs: 100,
+        etwFlushPeriod: 8,
+        manualEtwFlush: true,
+        metricsOffset: 32, 
         metricsWindow: 1000, 
         overlayPosition: 0, 
         timeRange: 10, 
@@ -104,7 +108,7 @@ export function makeDefaultPreferences(): Preferences {
 
 export const signature: Signature = {
     code: "p2c-cap-pref",
-    version: "0.17.0",
+    version: "0.18.0",
 };
 
 export interface PreferenceFile {
@@ -138,6 +142,15 @@ const migrations: Migration[] = [
             prefs.overlayDrawRate = drawRate;
         }
     },
+    {
+        version: '0.18.0',
+        migrate: (prefs: Preferences) => {
+            console.info('Migrating preferences to 0.18.0 (manualEtwFlush enable/rate)');
+            const def = makeDefaultPreferences();
+            prefs.manualEtwFlush = def.manualEtwFlush;
+            prefs.etwFlushPeriod = def.etwFlushPeriod;
+        }
+    },
 ];
 
 migrations.sort((a, b) => compareVersions(a.version, b.version));

IntelPresentMon/AppCef/Web/src/views/MetricProcessingView.vue

@@ -128,6 +128,18 @@ export default Vue.extend({
         Preferences.writeAttribute({ attr: 'metricsWindow', val: metricsWindow });
       },
     },
+    etwFlushPeriod: {
+      get(): number { return Preferences.preferences.etwFlushPeriod; },
+      set(etwFlushPeriod: number) {
+        Preferences.writeAttribute({ attr: 'etwFlushPeriod', val: etwFlushPeriod });
+      },
+    },
+    manualEtwFlush: {
+      get(): boolean { return Preferences.preferences.manualEtwFlush; },
+      set(manualEtwFlush: boolean) {
+        Preferences.writeAttribute({ attr: 'manualEtwFlush', val: manualEtwFlush });
+      },
+    },
     adapters(): Adapter[] {
       return Adapters.adapters;
     },

IntelPresentMon/AppCef/source/NanoCefProcessHandler.cpp

@@ -7,15 +7,13 @@
 #include "SchemeHandlerFactory.h"
 #include "DataBindAccessor.h"
 #include <Core/source/infra/Logging.h>
+#include <Core/source/infra/LogSetup.h>
 #include "include/wrapper/cef_closure_task.h"
 #include <include/cef_task.h>
 #include "include/base/cef_callback.h"
 #include "util/AsyncEndpointManager.h"
 #include "util/CefValues.h"
 #include <Core/source/cli/CliOptions.h>
-#include <CommonUtilities/mt/Thread.h>
-#include <CommonUtilities/log/NamedPipeMarshallReceiver.h>
-#include <CommonUtilities/log/EntryMarshallInjector.h>
 #include <include/cef_parser.h>
 
 using namespace pmon::util;
@@ -94,33 +92,7 @@ namespace p2c::client::cef
             std::string pipePrefix = std::format("p2c-logpipe-{}-{}", GetCurrentProcessId(), ++count);
             pChildCommandLine->AppendSwitchWithValue(opt.logPipeName.GetName(), pipePrefix);
             // launch connector thread
-            mt::Thread{ "logconn", count, [pipePrefix] {
-                try {
-                    // wait maximum 1.5sec for pipe to be created
-                    if (!pipe::DuplexPipe::WaitForAvailability(R"(\\.\pipe\)" + pipePrefix, 1500)) {
-                        pmlog_warn(std::format("Failed to connect to logging source server {} after waiting 1.5s", pipePrefix));
-                        return;
-                    }
-                    // retry connection maximum 3 times, every 16ms
-                    const int nAttempts = 3;
-                    for (int i = 0; i < nAttempts; i++) {
-                        try {
-                            auto pChan = log::GetDefaultChannel();
-                            auto pReceiver = std::make_shared<log::NamedPipeMarshallReceiver>(pipePrefix, log::IdentificationTable::GetPtr());
-                            auto pInjector = std::make_shared<log::EntryMarshallInjector>(pChan, std::move(pReceiver));
-                            pChan->AttachComponent(std::move(pInjector));
-                            return;
-                        }
-                        catch (const pipe::PipeError&) {
-                            std::this_thread::sleep_for(16ms);
-                        }
-                    }
-                    pmlog_warn(std::format("Failed to connect to logging source server {} after {} attempts", pipePrefix, nAttempts));
-                }
-                catch (...) {
-                    pmlog_error(ReportException());
-                }
-            } }.detach();
+            ConnectToLoggingSourcePipe(pipePrefix, count);
         }
     }
 

IntelPresentMon/AppCef/source/util/AsyncEndpointManager.cpp

@@ -2,7 +2,6 @@
 // SPDX-License-Identifier: MIT
 #include "AsyncEndpointManager.h"
 #include <Core/source/infra/Logging.h>
-#include <Core/source/infra/util/Util.h>
 #include <algorithm>
 #include "CefValues.h"
 #include <include/cef_task.h>

IntelPresentMon/AppCef/source/util/MakeOverlaySpec.cpp

@@ -32,6 +32,8 @@ namespace p2c::client::util
             .graphDataWindowSize = traversedPref["timeRange"],
             .averagingWindowSize = traversedPref["metricsWindow"],
             .metricsOffset = traversedPref["metricsOffset"],
+            .etwFlushPeriod = traversedPref["etwFlushPeriod"],
+            .manualEtwFlush = traversedPref["manualEtwFlush"],
             .overlayPosition = (kern::OverlaySpec::OverlayPosition)traversedPref["overlayPosition"],
             .overlayWidth = traversedPref["overlayWidth"],
             .upscale = traversedPref["upscale"],

IntelPresentMon/AppCef/source/util/async/GetTopGpuProcess.h

@@ -8,7 +8,7 @@
 #include <ranges>
 #include <Core/source/win/GpuUtilization.h>
 #include <Core/source/win/ProcessMapBuilder.h>
-#include <Core/source/infra/util/Util.h>
+#include <CommonUtilities/str/String.h>
 
 namespace p2c::client::util::async
 {
@@ -40,7 +40,7 @@ namespace p2c::client::util::async
                 std::unordered_set<std::string> blacklistSet(blacklist.begin(), blacklist.end());
                 // remove candidate target processes that match blacklist (lower case compare)
                 std::erase_if(procList, [&](const win::Process& proc) {
-                    auto narrowName = infra::util::ToNarrow(proc.name);
+                    auto narrowName = ::pmon::util::str::ToNarrow(proc.name);
                     for (auto& c : narrowName) {
                         c = std::tolower(c);
                     }

IntelPresentMon/AppCef/source/winmain.cpp

@@ -232,24 +232,33 @@ int APIENTRY WinMain(HINSTANCE hInstance, HINSTANCE hPrevInstance, LPSTR lpCmdLi
 
     try {
         // service-as-child handling
+        std::optional<std::string> logSvcPipe;
         std::optional<boost::process::child> childSvc;
         if (!opt.cefType && opt.svcAsChild) {
             using namespace std::literals;
             namespace bp = boost::process;
 
+            logSvcPipe = opt.logSvcPipe.AsOptional().value_or(
+                std::format("pm2-child-svc-log-{}", GetCurrentProcessId()));
             childSvc.emplace("PresentMonService.exe"s,
                 "--control-pipe"s, *opt.controlPipe,
                 "--nsm-prefix"s, "pm-frame-nsm"s,
                 "--intro-nsm"s, *opt.shmName,
                 "--etw-session-name"s, *opt.etwSessionName,
-                "--log-level"s, std::to_string((int)log::GlobalPolicy::Get().GetLogLevel()));
+                "--log-level"s, std::to_string((int)log::GlobalPolicy::Get().GetLogLevel()),
+                "--log-pipe-name"s, *logSvcPipe);
 
             if (!pmon::util::win::WaitForNamedPipe(*opt.controlPipe, 1500)) {
                 pmlog_error("timeout waiting for child service control pipe to go online");
                 return -1;
             }
         }
 
+        if (!opt.cefType && opt.logSvcPipeEnable) {
+            // connect to service's log pipe (best effort)
+            ConnectToLoggingSourcePipe(logSvcPipe.value_or(*opt.logSvcPipe), 0);
+        }
+
         using namespace client;
         // cef process constellation fork control
         CefMainArgs main_args{ hInstance };

IntelPresentMon/CommonUtilities/CommonUtilities.vcxproj

@@ -22,6 +22,7 @@
     <ClInclude Include="BuildId.h" />
     <ClInclude Include="cli\CliFramework.h" />
     <ClInclude Include="Exception.h" />
+    <ClInclude Include="IntervalWaiter.h" />
     <ClInclude Include="log\ChannelFlusher.h" />
     <ClInclude Include="log\CopyDriver.h" />
     <ClInclude Include="log\DiagnosticDriver.h" />
@@ -75,6 +76,10 @@
     <ClInclude Include="mt\Thread.h" />
     <ClInclude Include="pipe\CoroMutex.h" />
     <ClInclude Include="pipe\Pipe.h" />
+    <ClInclude Include="pipe\SecurityMode.h" />
+    <ClInclude Include="PrecisionWaiter.h" />
+    <ClInclude Include="Qpc.h" />
+    <ClInclude Include="rng\PairToRange.h" />
     <ClInclude Include="str\String.h" />
     <ClInclude Include="third\reflect.hpp" />
     <ClInclude Include="win\Event.h" />
@@ -83,11 +88,13 @@
     <ClInclude Include="win\Overlapped.h" />
     <ClInclude Include="win\Utilities.h" />
     <ClInclude Include="win\WinAPI.h" />
+    <ClInclude Include="pipe\WrapAsio.h" />
   </ItemGroup>
   <ItemGroup>
     <ClCompile Include="BuildId.cpp" />
     <ClCompile Include="cli\CliFramework.cpp" />
     <ClCompile Include="Exception.cpp" />
+    <ClCompile Include="IntervalWaiter.cpp" />
     <ClCompile Include="log\ChannelFlusher.cpp" />
     <ClCompile Include="log\CopyDriver.cpp" />
     <ClCompile Include="log\DiagnosticDriver.cpp" />
@@ -120,6 +127,8 @@
     <ClCompile Include="mt\Thread.cpp" />
     <ClCompile Include="pipe\CoroMutex.cpp" />
     <ClCompile Include="pipe\Pipe.cpp" />
+    <ClCompile Include="PrecisionWaiter.cpp" />
+    <ClCompile Include="Qpc.cpp" />
     <ClCompile Include="str\String.cpp" />
     <ClCompile Include="win\Event.cpp" />
     <ClCompile Include="win\Handle.cpp" />

IntelPresentMon/CommonUtilities/CommonUtilities.vcxproj.filters

@@ -207,6 +207,24 @@
     <ClInclude Include="BuildId.h">
       <Filter>Header Files</Filter>
     </ClInclude>
+    <ClInclude Include="PrecisionWaiter.h">
+      <Filter>Header Files</Filter>
+    </ClInclude>
+    <ClInclude Include="Qpc.h">
+      <Filter>Header Files</Filter>
+    </ClInclude>
+    <ClInclude Include="IntervalWaiter.h">
+      <Filter>Header Files</Filter>
+    </ClInclude>
+    <ClInclude Include="rng\PairToRange.h">
+      <Filter>Header Files</Filter>
+    </ClInclude>
+    <ClInclude Include="pipe\SecurityMode.h">
+      <Filter>Header Files</Filter>
+    </ClInclude>
+    <ClInclude Include="pipe\WrapAsio.h">
+      <Filter>Header Files</Filter>
+    </ClInclude>
   </ItemGroup>
   <ItemGroup>
     <ClCompile Include="cli\CliFramework.cpp">
@@ -329,6 +347,15 @@
     <ClCompile Include="BuildId.cpp">
       <Filter>Source Files</Filter>
     </ClCompile>
+    <ClCompile Include="PrecisionWaiter.cpp">
+      <Filter>Source Files</Filter>
+    </ClCompile>
+    <ClCompile Include="Qpc.cpp">
+      <Filter>Source Files</Filter>
+    </ClCompile>
+    <ClCompile Include="IntervalWaiter.cpp">
+      <Filter>Source Files</Filter>
+    </ClCompile>
   </ItemGroup>
   <ItemGroup>
     <None Include="vcpkg.json" />

IntelPresentMon/CommonUtilities/Exception.cpp

@@ -75,24 +75,32 @@ namespace pmon::util
 		}
 	}
 
-	std::string ReportException(std::exception_ptr pEx) noexcept
+	std::string ReportException(std::string note, std::exception_ptr pEx) noexcept
 	{
 		if (!pEx) {
 			pEx = std::current_exception();
 		}
+		const auto concat = [&](std::string what) {
+			if (!note.empty()) {
+				return note + "\n" + what;
+			}
+			else {
+				return what;
+			}
+		};
 		if (pEx) {
 			try {
 				std::rethrow_exception(pEx);
 			}
 			catch (const std::exception& e) {
-				try { return std::format("[{}] {}", typeid(e).name(), e.what()); }
+				try { return concat(std::format("[{}] {}", typeid(e).name(), e.what())); }
 				catch (...) { return {}; }
 			}
 			catch (...) {
-				return "Unrecognized exception";
+				return concat("Unrecognized exception");
 			}
 		}
-		return "No exception in flight";
+		return concat("No exception in flight");
 	}
 
 	PM_STATUS GeneratePmStatus(std::exception_ptr pEx) noexcept

IntelPresentMon/CommonUtilities/Exception.h

@@ -40,7 +40,7 @@ namespace pmon::util
 		return exception;
 	}
 
-	std::string ReportException(std::exception_ptr pEx = {}) noexcept;
+	std::string ReportException(std::string note = {}, std::exception_ptr pEx = {}) noexcept;
 
 	PM_STATUS GeneratePmStatus(std::exception_ptr pEx = {}) noexcept;
 

IntelPresentMon/CommonUtilities/IntervalWaiter.cpp

@@ -0,0 +1,40 @@
+#include "IntervalWaiter.h"
+#include <thread>
+
+namespace pmon::util
+{
+	IntervalWaiter::IntervalWaiter(double intervalSeconds, double waitBuffer)
+		:
+		intervalSeconds_{ intervalSeconds },
+		waiter_{ waitBuffer }
+	{}
+
+	void IntervalWaiter::SetInterval(double intervalSeconds)
+	{
+		intervalSeconds_ = intervalSeconds;
+	}
+
+	void IntervalWaiter::SetInterval(std::chrono::nanoseconds interval)
+	{
+		intervalSeconds_ = double(interval.count()) / 1'000'000'000.;
+	}
+
+	void IntervalWaiter::Wait()
+	{
+		const auto waitTimeSeconds = [=, this] {
+			const auto t = timer_.Peek();
+			auto targetCandidate = lastTargetTime_ + intervalSeconds_;
+			// if we are on-time
+			if (t <= targetCandidate) {
+				lastTargetTime_ = targetCandidate;
+				return targetCandidate - t;
+			}
+			// if we are late, reset target to NOW and do not wait
+			lastTargetTime_ = t;
+			return 0.;
+		}();
+		if (waitTimeSeconds > 0.) {
+			waiter_.Wait(waitTimeSeconds);
+		}
+	}
+}

IntelPresentMon/CommonUtilities/IntervalWaiter.h

@@ -0,0 +1,28 @@
+// Copyright (C) 2022 Intel Corporation
+// SPDX-License-Identifier: MIT
+#pragma once
+#include "Qpc.h"
+#include "PrecisionWaiter.h"
+#include <chrono>
+
+namespace pmon::util
+{
+	class IntervalWaiter
+	{
+	public:
+		IntervalWaiter(double intervalSeconds, double waitBuffer = PrecisionWaiter::standardWaitBuffer);
+		IntervalWaiter(const IntervalWaiter&) = delete;
+		IntervalWaiter & operator=(const IntervalWaiter&) = delete;
+		IntervalWaiter(IntervalWaiter&&) = delete;
+		IntervalWaiter & operator=(IntervalWaiter&&) = delete;
+		~IntervalWaiter() = default;
+		void SetInterval(double intervalSeconds);
+		void SetInterval(std::chrono::nanoseconds interval);
+		void Wait();
+	private:
+		double intervalSeconds_;
+		double lastTargetTime_ = 0.;
+		PrecisionWaiter waiter_;
+		QpcTimer timer_;
+	};
+}