dedicated diagnostics demo and level improvements

planetchili · planetchili · commit 765fd557200a · 2024-05-29T08:28:10.000+09:00
diff --git a/IntelPresentMon/AppCef/source/SchemeFileHandler.cpp b/IntelPresentMon/AppCef/source/SchemeFileHandler.cpp
@@ -58,7 +58,7 @@ namespace p2c::client::cef
             return false;
         }
 
-        pmlog_info(std::format(L"Opening file: {}", file_path_.wstring()));
+        pmlog_dbg(std::format(L"Opening file: {}", file_path_.wstring()));
         return true;
     }
 
diff --git a/IntelPresentMon/AppCef/source/SchemeHandlerFactory.cpp b/IntelPresentMon/AppCef/source/SchemeHandlerFactory.cpp
@@ -70,7 +70,7 @@ namespace p2c::client::cef
                 return nullptr;
             }
             else {
-                pmlog_info(std::format(L"Processing request URL: {}", request->GetURL().ToWString()));
+                pmlog_dbg(std::format(L"Processing request URL: {}", request->GetURL().ToWString()));
             }
             return new SchemeFileHandler(baseDir_);
         }
diff --git a/IntelPresentMon/CommonUtilities/Exception.cpp b/IntelPresentMon/CommonUtilities/Exception.cpp
@@ -78,7 +78,7 @@ namespace pmon::util
 				std::rethrow_exception(pEx);
 			}
 			catch (const std::exception& e) {
-				return std::format("[{}]\n{}", typeid(e).name(), e.what());
+				return std::format("[{}] {}", typeid(e).name(), e.what());
 			}
 			catch (...) {
 				return "Unrecognized exception";
diff --git a/IntelPresentMon/CommonUtilities/log/GlobalPolicy.cpp b/IntelPresentMon/CommonUtilities/log/GlobalPolicy.cpp
@@ -41,6 +41,10 @@ namespace pmon::util::log
 	{
 		traceLevel_ = level;
 	}
+	void GlobalPolicy::SetTraceLevelDefault() noexcept
+	{
+		SetTraceLevel(Level::Error);
+	}
 	bool GlobalPolicy::GetResolveTraceInClientThread() const noexcept
 	{
 		return resolveTraceInClientThread_;
diff --git a/IntelPresentMon/CommonUtilities/log/GlobalPolicy.h b/IntelPresentMon/CommonUtilities/log/GlobalPolicy.h
@@ -13,6 +13,7 @@ namespace pmon::util::log
 		void SetLogLevelDefault() noexcept;
 		Level GetTraceLevel() const noexcept;
 		void SetTraceLevel(Level level) noexcept;
+		void SetTraceLevelDefault() noexcept;
 		bool GetResolveTraceInClientThread() const noexcept;
 		void SetResolveTraceInClientThread(bool setting) noexcept;
 		bool GetExceptionTrace() const noexcept;
diff --git a/IntelPresentMon/PresentMonAPI2/PresentMonAPI.cpp b/IntelPresentMon/PresentMonAPI2/PresentMonAPI.cpp
@@ -297,8 +297,12 @@ PRESENTMON_API2_EXPORT PM_STATUS pmRegisterDynamicQuery(PM_SESSION_HANDLE sessio
 	PM_QUERY_ELEMENT* pElements, uint64_t numElements, double windowSizeMs, double metricOffsetMs)
 {
 	try {
-		if (!pElements || !numElements) {
-			// TODO: error code for bad args
+		if (!pElements) {
+			pmlog_error(L"null pointer to query element array argument").diag();
+			return PM_STATUS_FAILURE;
+		}
+		if (!numElements) {
+			pmlog_error(L"zero length query element array").diag();
 			return PM_STATUS_FAILURE;
 		}
 		const auto queryHandle = LookupMiddleware_(sessionHandle).RegisterDynamicQuery(
diff --git a/IntelPresentMon/PresentMonAPIWrapper/DiagnosticHandler.cpp b/IntelPresentMon/PresentMonAPIWrapper/DiagnosticHandler.cpp
@@ -51,11 +51,11 @@ namespace pmapi
 		PM_DIAGNOSTIC_LEVEL filterLevel,
 		int outputFlags,
 		std::function<void(const PM_DIAGNOSTIC_MESSAGE&)> callback,
+		int gracePeriodMs,
 		std::span<PM_DIAGNOSTIC_SUBSYSTEM> allowList,
 		bool enableTimestamp,
 		bool enableTrace,
-		bool enableLocation,
-		int gracePeriodMs
+		bool enableLocation
 	) : gracePeriodMs_{ gracePeriodMs } {
 		const PM_DIAGNOSTIC_CONFIGURATION config{
 			.filterLevel = filterLevel,
diff --git a/IntelPresentMon/PresentMonAPIWrapper/DiagnosticHandler.h b/IntelPresentMon/PresentMonAPIWrapper/DiagnosticHandler.h
@@ -6,7 +6,7 @@
 
 namespace pmapi
 {
-	// DiagnosticHandler is simplifies the process of setting up the debug diagnostic layer
+	// DiagnosticHandler simplifies the process of setting up the debug diagnostic layer
 	// when you supply a callback, this class will spawn a thread to process messages from
 	// the diagnostic queue (sleeping while none are available)
 	// make sure that any resources accessed by this callback are done so in a thread-safe manner
@@ -21,16 +21,16 @@ namespace pmapi
 			int outputFlags = PM_DIAGNOSTIC_OUTPUT_FLAGS_DEBUGGER,
 			// callback that will process messages received into the queue
 			std::function<void(const PM_DIAGNOSTIC_MESSAGE&)> callback = {},
+			// add a grace period to wait for final messages before destroying diagnostics (ms)
+			int gracePeriodMs = 10,
 			// span of subsystems to allow, ignore all not in this span (empty span to accept all)
 			std::span<PM_DIAGNOSTIC_SUBSYSTEM> allowList = {},
 			// capture timestamps as a string and add to all non-queue outputs
 			bool enableTimestamp = true,
 			// capture stack traces as a string when available (typically for error-level messages)
 			bool enableTrace = false,
 			// capture source file and line number as a string
-			bool enableLocation = false,
-			// add a grace period to wait for final messages before destroying diagnostics (ms)
-			int gracePeriodMs = 50
+			bool enableLocation = false
 		);
 		~DiagnosticHandler();
 	private:
diff --git a/IntelPresentMon/PresentMonAPIWrapper/Session.h b/IntelPresentMon/PresentMonAPIWrapper/Session.h
@@ -52,7 +52,7 @@ namespace pmapi
         // begin tracking a process, necessary to consume frame data or query metrics involving that process
         ProcessTracker TrackProcess(uint32_t pid);
         // register (build/compile) a dynamic query used to poll metrics
-        DynamicQuery RegisterDyanamicQuery(std::span<PM_QUERY_ELEMENT> elements, double winSizeMs, double metricOffsetMs);
+        DynamicQuery RegisterDyanamicQuery(std::span<PM_QUERY_ELEMENT> elements, double winSizeMs = 1000, double metricOffsetMs = 1020);
         // register (build/compile) a frame query used to consume frame events
         FrameQuery RegisterFrameQuery(std::span<PM_QUERY_ELEMENT> elements);
         // set the rate at which the service polls device telemetry data
diff --git a/IntelPresentMon/PresentMonAPIWrapperCommon/Introspection.cpp b/IntelPresentMon/PresentMonAPIWrapperCommon/Introspection.cpp
@@ -2,6 +2,7 @@
 #include <format>
 #include <cassert>
 #include "Exception.h"
+#include "../CommonUtilities/log/Log.h"
 
 
 namespace pmapi::intro
@@ -523,6 +524,7 @@ namespace pmapi::intro
     MetricView Root::FindMetric(PM_METRIC metricId) const
     {
         if (auto i = metricMap.find(metricId); i == metricMap.end()) {
+            pmlog_error(std::format(L"Cannot find metric id={} in introspection data", (int)metricId)).diag();
             throw LookupException{ std::format("unable to find metric ID={}", (int)metricId) };
         }
         else {
diff --git a/IntelPresentMon/PresentMonMiddleware/ConcreteMiddleware.cpp b/IntelPresentMon/PresentMonMiddleware/ConcreteMiddleware.cpp
@@ -27,13 +27,15 @@
 #include "FrameEventQuery.h"
 #include "Exception.h"
 #include "../CommonUtilities/mt/Thread.h"
+#include "../CommonUtilities/log/Log.h"
 
 #define GLOG_NO_ABBREVIATED_SEVERITIES
 #include <glog/logging.h>
 
 namespace pmon::mid
 {
     using namespace ipc::intro;
+    using namespace util;
 
     static const uint32_t kMaxRespBufferSize = 4096;
 	static const uint64_t kClientFrameDeltaQPCThreshold = 50000000;
@@ -541,6 +543,8 @@ namespace pmon::mid
                 //pQuery->accumCpuBits.set(static_cast<size_t>(CpuTelemetryCapBits::cpu_power));
                 break;
             default:
+                pmlog_warn(std::format(L"ignoring invalid metric [{}] while building dynamic query", 
+                    str::ToWide(metricView.Introspect().GetSymbol()))).diag();
                 break;
             }
 
@@ -983,7 +987,9 @@ void ReportMetrics(
         auto& ispec = GetIntrospectionRoot();
         auto metricView = ispec.FindMetric(element.metric);
         if (metricView.GetType() != int(PM_METRIC_TYPE_STATIC)) {
-            throw std::runtime_error{ "dynamic metric in static query poll" };
+            pmlog_error(std::format(L"dynamic metric [{}] in static query poll",
+                str::ToWide(metricView.Introspect().GetSymbol()))).diag();
+            throw Except<util::Exception>("dynamic metric in static query poll");
         }
 
         auto elementSize = GetDataTypeSize(metricView.GetDataTypeInfo().GetPolledType());
@@ -1026,14 +1032,16 @@ void ReportMetrics(
                 << "Stream client for process " << processId
                 << " doesn't exist. Please call pmStartStream to initialize the "
                 "client.";
-            throw std::runtime_error{ "Failed to find stream for pid in ConsumeFrameEvents" };
+            pmlog_error(L"Stream client for process {} doesn't exist. Please call pmStartStream to initialize the client.").diag();
+            throw Except<util::Exception>(std::format("Failed to find stream for pid {} in ConsumeFrameEvents", processId));
         }
 
         const auto nsm_view = pShmClient->GetNamedSharedMemView();
         const auto nsm_hdr = nsm_view->GetHeader();
         if (!nsm_hdr->process_active) {
             StopStreaming(processId);
-            throw std::runtime_error{ "Process died cannot consume frame events" };
+            pmlog_info(L"Process death detected while consuming frame events").diag();
+            throw Except<util::Exception>("Process died cannot consume frame events");
         }
 
         const auto last_frame_idx = pShmClient->GetLatestFrameIndex();
@@ -1059,7 +1067,8 @@ void ReportMetrics(
             const auto status = pShmClient->ConsumePtrToNextNsmFrameData(&pCurrentFrameData, 
                 &pFrameDataOfNextDisplayed, &pFrameDataOfLastPresented, &pFrameDataOfLastDisplayed, &pPreviousFrameDataOfLastDisplayed);
             if (status != PM_STATUS::PM_STATUS_SUCCESS) {
-                throw std::runtime_error{ "Error while trying to get frame data from shared memory" };
+                pmlog_error(L"Error while trying to get frame data from shared memory").diag();
+                throw Except<util::Exception>("Error while trying to get frame data from shared memory");
             }
             if (!pCurrentFrameData) {
                 break;
diff --git a/IntelPresentMon/PresentMonMiddleware/FrameEventQuery.cpp b/IntelPresentMon/PresentMonMiddleware/FrameEventQuery.cpp
@@ -4,13 +4,16 @@
 #include "../PresentMonUtils/PresentMonNamedPipe.h"
 #include "FrameEventQuery.h"
 #include "../PresentMonAPIWrapperCommon/Introspection.h"
-#include "../CommonUtilities//Memory.h"
-#include "../CommonUtilities//Meta.h"
+#include "../CommonUtilities/Memory.h"
+#include "../CommonUtilities/Meta.h"
+#include "../CommonUtilities/log/Log.h"
+#include "../CommonUtilities/Exception.h"
 #include <algorithm>
 #include <cstddef>
 #include <limits>
 
 using namespace pmon;
+using namespace pmon::util;
 using Context = PM_FRAME_QUERY::Context;
 
 namespace pmon::mid
@@ -485,14 +488,18 @@ PM_FRAME_QUERY::PM_FRAME_QUERY(std::span<PM_QUERY_ELEMENT> queryElements)
 				referencedDevice_ = q.deviceId;
 			}
 			else if (*referencedDevice_ != q.deviceId) {
-				throw std::runtime_error{ "Cannot specify 2 different non-universal devices in the same query" };
+				pmlog_error(L"Cannot specify 2 different non-universal devices in the same query")
+					.pmwatch(*referencedDevice_).pmwatch(q.deviceId).diag();
+				throw Except<Exception>("2 different non-universal devices in same query");
 			}
 		}
-		gatherCommands_.push_back(MapQueryElementToGatherCommand_(q, blobSize_));
-		const auto& cmd = gatherCommands_.back();
-		q.dataSize = cmd->GetDataSize();
-		q.dataOffset = cmd->GetOutputOffset();
-		blobSize_ += cmd->GetTotalSize();
+		if (auto pElement = MapQueryElementToGatherCommand_(q, blobSize_)) {
+			gatherCommands_.push_back(std::move(pElement));
+			const auto& cmd = gatherCommands_.back();
+			q.dataSize = cmd->GetDataSize();
+			q.dataOffset = cmd->GetOutputOffset();
+			blobSize_ += cmd->GetTotalSize();
+		}
 	}
 	// make sure blobs are a multiple of 16 so that blobs in array always start 16-aligned
 	blobSize_ += util::GetPadding(blobSize_, 16);
@@ -640,7 +647,9 @@ std::unique_ptr<mid::GatherCommand_> PM_FRAME_QUERY::MapQueryElementToGatherComm
 	case PM_METRIC_CLICK_TO_PHOTON_LATENCY:
 		return std::make_unique<QpcDifferenceGatherCommand_<&Pre::InputTime, &Pre::ScreenTime, 1, 1, 0>>(pos);
 
-	default: return {};
+	default:
+		pmlog_error(L"unknown metric id").pmwatch((int)q.metric).diag();
+		return {};
 	}
 }
 
@@ -657,20 +666,23 @@ void PM_FRAME_QUERY::Context::UpdateSourceData(const PmNsmFrameData* pSourceFram
 	}
 	else {
 		// TODO: log issue or invalidate related columns or drop frame (or some combination)
+		pmlog_info(L"null pFrameDataOfLastPresented");
 		cpuFrameQpc = 0;
 	}
 	if (pFrameDataOfNextDisplayed) {
 		nextDisplayedQpc = pFrameDataOfNextDisplayed->present_event.ScreenTime;
 	}
 	else {
 		// TODO: log issue or invalidate related columns or drop frame (or some combination)
+		pmlog_info(L"null pFrameDataOfNextDisplayed");
 		nextDisplayedQpc = 0;
 	}
 	if (pFrameDataOfLastDisplayed) {
 		previousDisplayedQpc = pFrameDataOfLastDisplayed->present_event.ScreenTime;
 	}
 	else {
 		// TODO: log issue or invalidate related columns or drop frame (or some combination)
+		pmlog_info(L"null pFrameDataOfLastDisplayed");
 		previousDisplayedQpc = 0;
 	}
 	if (pPreviousFrameDataOfLastDisplayed) {
diff --git a/IntelPresentMon/PresentMonMiddleware/LogSetup.cpp b/IntelPresentMon/PresentMonMiddleware/LogSetup.cpp
@@ -26,7 +26,6 @@ namespace pmon::util::log
 		// creates an independent logging channel or a copy channel, resets log level to default
 		std::shared_ptr<IChannel> MakeChannel_(std::shared_ptr<IChannel> pCopyTargetChannel = {})
 		{
-			GlobalPolicy::Get().SetLogLevelDefault();
 			// channel
 			auto pChannel = std::make_shared<Channel>();
 			// error resolver
@@ -62,7 +61,6 @@ namespace pmon::util::log
 		// creates a channel for debug diagnostic purposes
 		std::shared_ptr<IChannel> MakeDiagnosticChannel_(std::shared_ptr<DiagnosticDriver> pDiag)
 		{
-			GlobalPolicy::Get().SetLogLevelDefault();
 			// channel
 			auto pChannel = std::make_shared<Channel>();
 			// make and add the line-tracking policy
@@ -74,6 +72,7 @@ namespace pmon::util::log
 		// creates a null channel and configures logging to be disabled as much as possible
 		std::shared_ptr<IChannel> MakeNullChannel_()
 		{
+			// disable logging globally
 			GlobalPolicy::Get().SetLogLevel(Level::None);
 			return {};
 		}
@@ -86,11 +85,17 @@ namespace pmon::util::log
 
 	void InjectCopyChannel(std::shared_ptr<IChannel> pCopyTargetChannel) noexcept
 	{
+		// reset logging level when channel is explicitly requested
+		GlobalPolicy::Get().SetLogLevelDefault();
+		GlobalPolicy::Get().SetTraceLevelDefault();
 		InjectDefaultChannel(MakeChannel_(std::move(pCopyTargetChannel)));
 	}
 
 	void InjectStandaloneChannel() noexcept
 	{
+		// reset logging level when channel is explicitly requested
+		GlobalPolicy::Get().SetLogLevelDefault();
+		GlobalPolicy::Get().SetTraceLevelDefault();
 		InjectDefaultChannel(MakeChannel_());
 	}
 
@@ -108,6 +113,10 @@ namespace pmon::util::log
 		else { // otherwise make a minimal channel for diagnostic handling
 			InjectDefaultChannel(MakeDiagnosticChannel_(pDiagnostics_));
 		}
+		GlobalPolicy::Get().SetLogLevel((Level)pConfig->filterLevel);
+		if (!pConfig->enableTrace) {
+			GlobalPolicy::Get().SetTraceLevel(Level::None);
+		}
 	}
 
 	std::shared_ptr<class DiagnosticDriver> GetDiagnostics()
diff --git a/IntelPresentMon/SampleClient/CliOptions.h b/IntelPresentMon/SampleClient/CliOptions.h
@@ -25,6 +25,7 @@ namespace clio
 		Option<std::string> processName{ this, "--process-name", "", "Name of process to use for polling or frame data capture" };
 		Option<std::string> metric{ this, "--metric", "", "PM_METRIC, ex. PM_METRIC_PRESENTED_FPS" };
 		Option<int> logDemo{ this, "--log-demo", 0, "Demos of log utility features" };
+		Option<int> diagDemo{ this, "--diag-demo", 0, "Demos of debug diagnostic layer interface" };
 
 		Option<log::Level> logLevel{ this, "--log-level", log::Level::Error, "Severity to log at", CLI::CheckedTransformer{ log::GetLevelMapNarrow(), CLI::ignore_case } };
 		Option<log::Level> logTraceLevel{ this, "--log-trace-level", log::Level::Error, "Severity to print stacktrace at", CLI::CheckedTransformer{ log::GetLevelMapNarrow(), CLI::ignore_case } };
diff --git a/IntelPresentMon/SampleClient/DiagnosticDemo.cpp b/IntelPresentMon/SampleClient/DiagnosticDemo.cpp
diff --git a/IntelPresentMon/SampleClient/DiagnosticDemo.h b/IntelPresentMon/SampleClient/DiagnosticDemo.h
diff --git a/IntelPresentMon/SampleClient/LogDemo.cpp b/IntelPresentMon/SampleClient/LogDemo.cpp
diff --git a/IntelPresentMon/SampleClient/SampleClient.args.json b/IntelPresentMon/SampleClient/SampleClient.args.json
diff --git a/IntelPresentMon/SampleClient/SampleClient.cpp b/IntelPresentMon/SampleClient/SampleClient.cpp
diff --git a/IntelPresentMon/SampleClient/SampleClient.vcxproj b/IntelPresentMon/SampleClient/SampleClient.vcxproj
diff --git a/IntelPresentMon/SampleClient/SampleClient.vcxproj.filters b/IntelPresentMon/SampleClient/SampleClient.vcxproj.filters

Original file line number	Diff line number	Diff line change
`@@ -58,7 +58,7 @@ namespace p2c::client::cef`
`58`	`58`	`return false;`
`59`	`59`	`}`
`60`	`60`
`61`		`- pmlog_info(std::format(L"Opening file: {}", file_path_.wstring()));`
	`61`	`+ pmlog_dbg(std::format(L"Opening file: {}", file_path_.wstring()));`
`62`	`62`	`return true;`
`63`	`63`	`}`
`64`	`64`
Original file line number	Diff line number	Diff line change
`@@ -70,7 +70,7 @@ namespace p2c::client::cef`
`70`	`70`	`return nullptr;`
`71`	`71`	`}`
`72`	`72`	`else {`
`73`		`- pmlog_info(std::format(L"Processing request URL: {}", request->GetURL().ToWString()));`
	`73`	`+ pmlog_dbg(std::format(L"Processing request URL: {}", request->GetURL().ToWString()));`
`74`	`74`	`}`
`75`	`75`	`return new SchemeFileHandler(baseDir_);`
`76`	`76`	`}`
Original file line number	Diff line number	Diff line change
`@@ -78,7 +78,7 @@ namespace pmon::util`
`78`	`78`	`std::rethrow_exception(pEx);`
`79`	`79`	`}`
`80`	`80`	`catch (const std::exception& e) {`
`81`		`- return std::format("[{}]\n{}", typeid(e).name(), e.what());`
	`81`	`+ return std::format("[{}] {}", typeid(e).name(), e.what());`
`82`	`82`	`}`
`83`	`83`	`catch (...) {`
`84`	`84`	`return "Unrecognized exception";`
Original file line number	Diff line number	Diff line change
`@@ -41,6 +41,10 @@ namespace pmon::util::log`
`41`	`41`	`{`
`42`	`42`	`traceLevel_ = level;`
`43`	`43`	`}`
	`44`	`+ void GlobalPolicy::SetTraceLevelDefault() noexcept`
	`45`	`+ {`
	`46`	`+ SetTraceLevel(Level::Error);`
	`47`	`+ }`
`44`	`48`	`bool GlobalPolicy::GetResolveTraceInClientThread() const noexcept`
`45`	`49`	`{`
`46`	`50`	`return resolveTraceInClientThread_;`
Original file line number	Diff line number	Diff line change
`@@ -2,6 +2,7 @@`
`2`	`2`	`#include <format>`
`3`	`3`	`#include <cassert>`
`4`	`4`	`#include "Exception.h"`
	`5`	`+#include "../CommonUtilities/log/Log.h"`
`5`	`6`
`6`	`7`
`7`	`8`	`namespace pmapi::intro`
`@@ -523,6 +524,7 @@ namespace pmapi::intro`
`523`	`524`	`MetricView Root::FindMetric(PM_METRIC metricId) const`
`524`	`525`	`{`
`525`	`526`	`if (auto i = metricMap.find(metricId); i == metricMap.end()) {`
	`527`	`+ pmlog_error(std::format(L"Cannot find metric id={} in introspection data", (int)metricId)).diag();`
`526`	`528`	`throw LookupException{ std::format("unable to find metric ID={}", (int)metricId) };`
`527`	`529`	`}`
`528`	`530`	`else {`