From f7d1fd5caab5d66e64046aac4f54888c3f826e03 Mon Sep 17 00:00:00 2001 From: ivberg Date: Mon, 20 Nov 2023 16:57:18 -0800 Subject: [PATCH 01/22] Initial version of dynamic ETW logger --- .../onnxruntime/core/common/logging/logging.h | 5 + onnxruntime/core/common/logging/logging.cc | 20 ++++ .../common/logging/sinks/composite_sink.h | 8 ++ .../core/platform/windows/logging/etw_sink.cc | 111 ++++++++++++++---- .../core/platform/windows/logging/etw_sink.h | 69 +++++++++++ .../providers/qnn/qnn_execution_provider.cc | 20 +++- onnxruntime/core/session/inference_session.cc | 23 +++- onnxruntime/core/session/ort_env.cc | 26 ++-- 8 files changed, 237 insertions(+), 45 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index bea3fa1d09cc2..648b392ab5018 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -333,5 +333,10 @@ unsigned int GetThreadId(); */ unsigned int GetProcessId(); +/** + If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled. If so, adds to the existing logger. +*/ +std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger); + } // namespace logging } // namespace onnxruntime diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 6c6e2f48557ef..ae742316a910b 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -12,6 +12,8 @@ #ifdef _WIN32 #include +#include "core/platform/windows/logging/etw_sink.h" +#include "core/common/logging/sinks/composite_sink.h" #else #include #if defined(__MACH__) || defined(__wasm__) || defined(_AIX) @@ -243,5 +245,23 @@ unsigned int GetProcessId() { #endif } + +std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger) { +#ifdef _WIN32 + auto& manager = EtwRegistrationManager::Instance(); + if (manager.IsEnabled()) { + auto compositeSink = std::make_unique(); + compositeSink->AddSink(std::move(existingLogger)); + compositeSink->AddSink(std::make_unique()); + return compositeSink; + } else { + return existingLogger; + } +#else + // On non-Windows platforms, just return the existing logger + return existingLogger; +#endif // _WIN32 +} + } // namespace logging } // namespace onnxruntime diff --git a/onnxruntime/core/common/logging/sinks/composite_sink.h b/onnxruntime/core/common/logging/sinks/composite_sink.h index f27abb9e6aad5..c0c37833fba00 100644 --- a/onnxruntime/core/common/logging/sinks/composite_sink.h +++ b/onnxruntime/core/common/logging/sinks/composite_sink.h @@ -33,6 +33,14 @@ class CompositeSink : public ISink { return *this; } + /// + /// Gets a const reference to the collection of sinks. + /// + /// A const reference to the vector of unique_ptr to ISink. + const std::vector>& GetSinks() const { + return sinks_; + } + private: void SendImpl(const Timestamp& timestamp, const std::string& logger_id, const Capture& message) override { for (auto& sink : sinks_) { diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.cc b/onnxruntime/core/platform/windows/logging/etw_sink.cc index 396695e6c570c..018ea0ec9ecb1 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.cc +++ b/onnxruntime/core/platform/windows/logging/etw_sink.cc @@ -58,42 +58,100 @@ TRACELOGGING_DEFINE_PROVIDER(etw_provider_handle, "ONNXRuntimeTraceLoggingProvid #pragma warning(pop) #endif -// Class to unregister ETW provider at shutdown. -// We expect one static instance to be created for the lifetime of the program. -class EtwRegistrationManager { - public: - static EtwRegistrationManager& Register() { - const HRESULT etw_status = ::TraceLoggingRegister(etw_provider_handle); - - if (FAILED(etw_status)) { - ORT_THROW("ETW registration failed. Logging will be broken: " + std::to_string(etw_status)); - } - // return an instance that is just used to unregister as the program exits - static EtwRegistrationManager instance(etw_status); +EtwRegistrationManager& EtwRegistrationManager::Instance() { + static EtwRegistrationManager instance; + instance.LazyInitialize(); return instance; - } +} + +bool EtwRegistrationManager::IsEnabled() const { + std::lock_guard lock(provider_change_mutex_); + return is_enabled_; +} + +UCHAR EtwRegistrationManager::Level() const { + std::lock_guard lock(provider_change_mutex_); + return level_; +} - const HRESULT Status() const noexcept { +Severity EtwRegistrationManager::MapLevelToSeverity() { + switch (level_) { + case TRACE_LEVEL_NONE: return Severity::kFATAL; // There is no none severity option + case TRACE_LEVEL_VERBOSE: return Severity::kVERBOSE; + case TRACE_LEVEL_INFORMATION: return Severity::kINFO; + case TRACE_LEVEL_WARNING: return Severity::kWARNING; + case TRACE_LEVEL_ERROR: return Severity::kERROR; + case TRACE_LEVEL_CRITICAL: return Severity::kFATAL; + default: return Severity::kVERBOSE; // Default case, or handle it as you see fit + } +} + +ULONGLONG EtwRegistrationManager::Keyword() const { + std::lock_guard lock(provider_change_mutex_); + return keyword_; +} + +HRESULT EtwRegistrationManager::Status() const { return etw_status_; - } +} - ~EtwRegistrationManager() { +void EtwRegistrationManager::RegisterInternalCallback(const EtwInternalCallback& callback) { + std::lock_guard lock(callbacks_mutex_); + callbacks_.push_back(callback); +} + +void NTAPI EtwRegistrationManager::ORT_TL_EtwEnableCallback( + _In_ LPCGUID SourceId, + _In_ ULONG IsEnabled, + _In_ UCHAR Level, + _In_ ULONGLONG MatchAnyKeyword, + _In_ ULONGLONG MatchAllKeyword, + _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, + _In_opt_ PVOID CallbackContext) +{ + auto& manager = EtwRegistrationManager::Instance(); + { + std::lock_guard lock(manager.provider_change_mutex_); + manager.is_enabled_ = (IsEnabled != 0); + manager.level_ = Level; + manager.keyword_ = MatchAnyKeyword; + } + manager.InvokeCallbacks(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); +} + +EtwRegistrationManager::~EtwRegistrationManager() { ::TraceLoggingUnregister(etw_provider_handle); - } +} - private: - ORT_DISALLOW_COPY_ASSIGNMENT_AND_MOVE(EtwRegistrationManager); +EtwRegistrationManager::EtwRegistrationManager() { +} + +void EtwRegistrationManager::LazyInitialize() { + if (!initialized_) { + std::lock_guard lock(init_mutex_); + if (!initialized_) { // Double-check locking pattern + initialized_ = true; + etw_status_ = ::TraceLoggingRegisterEx(etw_provider_handle, ORT_TL_EtwEnableCallback, nullptr); + if (FAILED(etw_status_)) { + ORT_THROW("ETW registration failed. Logging will be broken: " + std::to_string(etw_status_)); + } + } + } +} - EtwRegistrationManager(const HRESULT status) noexcept : etw_status_{status} {} - const HRESULT etw_status_; -}; +void EtwRegistrationManager::InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext) { + std::lock_guard lock(callbacks_mutex_); + for (const auto& callback : callbacks_) { + callback(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); + } +} void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, const Capture& message) { UNREFERENCED_PARAMETER(timestamp); // register on first usage - static EtwRegistrationManager& etw_manager = EtwRegistrationManager::Register(); + static EtwRegistrationManager& etw_manager = EtwRegistrationManager::Instance(); // do something (not that meaningful) with etw_manager so it doesn't get optimized out // as we want an instance around to do the unregister @@ -101,9 +159,8 @@ void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, return; } - // Do we want to output Verbose level messages via ETW at any point it time? // TODO: Validate if this filtering makes sense. - if (message.Severity() <= Severity::kVERBOSE || message.DataType() == DataType::USER) { + if (message.DataType() == DataType::USER) { return; } @@ -115,7 +172,9 @@ void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, // forcing us to use an ugly macro for the call. #define ETW_EVENT_NAME "ONNXRuntimeLogEvent" #define TRACE_LOG_WRITE(level) \ - TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, TraceLoggingLevel(level), \ + TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ + TraceLoggingKeyword(static_cast(Keyword::Logs)), \ + TraceLoggingLevel(level), \ TraceLoggingString(logger_id.c_str(), "logger"), \ TraceLoggingString(message.Category(), "category"), \ TraceLoggingString(message.Location().ToString().c_str(), "location"), \ diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index 1e4f49a619302..5e4e48aa7a6b1 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.h +++ b/onnxruntime/core/platform/windows/logging/etw_sink.h @@ -3,7 +3,9 @@ #pragma once +#include #include +#include // check for Windows 10 SDK or later // https://stackoverflow.com/questions/2665755/how-can-i-determine-the-version-of-the-windows-sdk-installed-on-my-computer @@ -18,6 +20,7 @@ #include #include #include +#include #include "core/common/logging/capture.h" #include "core/common/logging/isink.h" @@ -25,8 +28,17 @@ namespace onnxruntime { namespace logging { +enum class Keyword : unsigned long long { + Logs = 0x1, + Reserved1 = 0x2, + Reserved2 = 0x4, + Reserved3 = 0x8, + EP = 0x10 +}; + class EtwSink : public ISink { public: + EtwSink() = default; ~EtwSink() = default; @@ -41,6 +53,63 @@ class EtwSink : public ISink { // EtwTracingManager to ensure we cleanly unregister it static std::atomic_flag have_instance_; }; + +class EtwRegistrationManager { + public: + using EtwInternalCallback = std::function; + + // Singleton instance access + static EtwRegistrationManager& Instance(); + + // Check if ETW logging is enabled + bool IsEnabled() const; + + // Get the current logging level + UCHAR Level() const; + + Severity MapLevelToSeverity(); + + // Get the current keyword + ULONGLONG Keyword() const; + + // Get the ETW registration status + HRESULT Status() const; + + void RegisterInternalCallback(const EtwInternalCallback& callback); + + private: + EtwRegistrationManager(); + ~EtwRegistrationManager(); + void LazyInitialize(); + + // Copy and move constructors/operators are disabled + EtwRegistrationManager(const EtwRegistrationManager&) = delete; + EtwRegistrationManager& operator=(const EtwRegistrationManager&) = delete; + EtwRegistrationManager(EtwRegistrationManager&&) = delete; + EtwRegistrationManager& operator=(EtwRegistrationManager&&) = delete; + + void InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext); + + static void NTAPI ORT_TL_EtwEnableCallback( + _In_ LPCGUID SourceId, + _In_ ULONG IsEnabled, + _In_ UCHAR Level, + _In_ ULONGLONG MatchAnyKeyword, + _In_ ULONGLONG MatchAllKeyword, + _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, + _In_opt_ PVOID CallbackContext); + + std::vector callbacks_; + std::mutex callbacks_mutex_; + mutable std::mutex provider_change_mutex_; + std::mutex init_mutex_; + bool initialized_ = false; + bool is_enabled_; + UCHAR level_; + ULONGLONG keyword_; + HRESULT etw_status_; +}; + } // namespace logging } // namespace onnxruntime diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index c72012fd4a19b..aa5532a246002 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -146,9 +146,25 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio static const std::string PROFILING_LEVEL = "profiling_level"; qnn::ProfilingLevel profiling_level = qnn::ProfilingLevel::OFF; + auto& manager = logging::EtwRegistrationManager::Instance(); + if (manager.IsEnabled()) { + auto level = manager.Level(); + auto keyword = manager.Keyword(); + if ((manager.Keyword() & static_cast(logging::Keyword::EP)) != 0) { + if (level != 0) { + if (level == 1) { + ParseProfilingLevel("basic", profiling_level); + } else { + ParseProfilingLevel("detailed", profiling_level); + } + } + } + } + else { auto profiling_level_pos = provider_options_map.find(PROFILING_LEVEL); - if (profiling_level_pos != provider_options_map.end()) { - ParseProfilingLevel(profiling_level_pos->second, profiling_level); + if (profiling_level_pos != provider_options_map.end()) { + ParseProfilingLevel(profiling_level_pos->second, profiling_level); + } } static const std::string RPC_CONTROL_LANTENCY = "rpc_control_latency"; diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 665cdbc36a963..4e62d81a4e7cb 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -69,6 +69,11 @@ #include "core/util/protobuf_parsing_utils.h" #include "core/util/thread_utils.h" +#ifdef _WIN32 +#include "core/platform/windows/logging/etw_sink.h" +#include "core/common/logging/sinks/composite_sink.h" +#endif + // custom ops are not available in a minimal build unless ORT_MINIMAL_BUILD_CUSTOM_OPS is set #if !defined(ORT_MINIMAL_BUILD) || defined(ORT_MINIMAL_BUILD_CUSTOM_OPS) #include "core/framework/customregistry.h" @@ -307,6 +312,7 @@ static Status FinalizeSessionOptions(const SessionOptions& user_provided_session logging::Severity GetSeverity(const SessionOptions& session_options) { logging::Severity severity = logging::Severity::kWARNING; + if (session_options.session_log_severity_level == -1) { severity = logging::LoggingManager::DefaultLogger().GetSeverity(); } else { @@ -316,16 +322,27 @@ logging::Severity GetSeverity(const SessionOptions& session_options) { session_options.session_log_severity_level); severity = static_cast(session_options.session_log_severity_level); } +#ifdef _WIN32 + auto& manager = logging::EtwRegistrationManager::Instance(); + if (manager.IsEnabled() && (manager.Keyword() & static_cast(logging::Keyword::Logs)) != 0) { + severity = manager.MapLevelToSeverity(); + // LOGS(*session_logger_, INFO) << "Overriding ...." + } +#endif // _WIN32 return severity; } void InferenceSession::SetLoggingManager(const SessionOptions& session_options, const Environment& session_env) { logging_manager_ = session_env.GetLoggingManager(); + std::unique_ptr sink; + if (session_options.user_logging_function) { - std::unique_ptr user_sink = std::make_unique(session_options.user_logging_function, - session_options.user_logging_param); - user_logging_manager_ = std::make_unique(std::move(user_sink), + sink = std::make_unique(session_options.user_logging_function, + session_options.user_logging_param); + sink = EnhanceLoggerWithEtw(std::move(sink)); + + user_logging_manager_ = std::make_unique(std::move(sink), GetSeverity(session_options), false, logging::LoggingManager::InstanceType::Temporal, diff --git a/onnxruntime/core/session/ort_env.cc b/onnxruntime/core/session/ort_env.cc index e3957baa990f8..e837394eb9d5c 100644 --- a/onnxruntime/core/session/ort_env.cc +++ b/onnxruntime/core/session/ort_env.cc @@ -39,23 +39,21 @@ OrtEnv* OrtEnv::GetInstance(const OrtEnv::LoggingManagerConstructionInfo& lm_inf if (!p_instance_) { std::unique_ptr lmgr; std::string name = lm_info.logid; + + std::unique_ptr sink = nullptr; if (lm_info.logging_function) { - std::unique_ptr logger = std::make_unique(lm_info.logging_function, - lm_info.logger_param); - lmgr = std::make_unique(std::move(logger), - static_cast(lm_info.default_warning_level), - false, - LoggingManager::InstanceType::Default, - &name); - } else { - auto sink = MakePlatformDefaultLogSink(); + sink = std::make_unique(lm_info.logging_function, lm_info.logger_param); - lmgr = std::make_unique(std::move(sink), - static_cast(lm_info.default_warning_level), - false, - LoggingManager::InstanceType::Default, - &name); + } else { + sink = MakePlatformDefaultLogSink(); } + sink = EnhanceLoggerWithEtw(std::move(sink)); + lmgr = std::make_unique(std::move(sink), + static_cast(lm_info.default_warning_level), + false, + LoggingManager::InstanceType::Default, + &name); + std::unique_ptr env; if (!tp_options) { status = onnxruntime::Environment::Create(std::move(lmgr), env); From 5c9af58f447aeb098978af9cb81ab40b1906a92f Mon Sep 17 00:00:00 2001 From: ivberg Date: Tue, 21 Nov 2023 14:56:52 -0800 Subject: [PATCH 02/22] Also fix logger created with CreateEnvWithCustomLogger API --- include/onnxruntime/core/common/logging/logging.h | 7 ++++++- onnxruntime/core/common/logging/logging.cc | 11 +++++++++++ onnxruntime/core/session/inference_session.cc | 9 +-------- onnxruntime/core/session/ort_env.cc | 2 +- 4 files changed, 19 insertions(+), 10 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index 648b392ab5018..74571338927d4 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -334,9 +334,14 @@ unsigned int GetThreadId(); unsigned int GetProcessId(); /** - If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled. If so, adds to the existing logger. + If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then adds to the existing logger. */ std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger); +/** + If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then can override the logging level +*/ +Severity OverrideLevelWithEtw(Severity originalSeverity); + } // namespace logging } // namespace onnxruntime diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index ae742316a910b..95f83814cc7ed 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -263,5 +263,16 @@ std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogge #endif // _WIN32 } +Severity OverrideLevelWithEtw(Severity originalSeverity) { +#ifdef _WIN32 + auto& manager = logging::EtwRegistrationManager::Instance(); + if (manager.IsEnabled() && (manager.Keyword() & static_cast(logging::Keyword::Logs)) != 0) { + return manager.MapLevelToSeverity(); + // LOGS(*session_logger_, INFO) << "Overriding ...." + } +#endif // _WIN32 + return originalSeverity; +} + } // namespace logging } // namespace onnxruntime diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 4e62d81a4e7cb..9c20241d952ba 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -322,14 +322,7 @@ logging::Severity GetSeverity(const SessionOptions& session_options) { session_options.session_log_severity_level); severity = static_cast(session_options.session_log_severity_level); } -#ifdef _WIN32 - auto& manager = logging::EtwRegistrationManager::Instance(); - if (manager.IsEnabled() && (manager.Keyword() & static_cast(logging::Keyword::Logs)) != 0) { - severity = manager.MapLevelToSeverity(); - // LOGS(*session_logger_, INFO) << "Overriding ...." - } -#endif // _WIN32 - return severity; + return logging::OverrideLevelWithEtw(severity); } void InferenceSession::SetLoggingManager(const SessionOptions& session_options, diff --git a/onnxruntime/core/session/ort_env.cc b/onnxruntime/core/session/ort_env.cc index e837394eb9d5c..e6734984f923c 100644 --- a/onnxruntime/core/session/ort_env.cc +++ b/onnxruntime/core/session/ort_env.cc @@ -49,7 +49,7 @@ OrtEnv* OrtEnv::GetInstance(const OrtEnv::LoggingManagerConstructionInfo& lm_inf } sink = EnhanceLoggerWithEtw(std::move(sink)); lmgr = std::make_unique(std::move(sink), - static_cast(lm_info.default_warning_level), + logging::OverrideLevelWithEtw(static_cast(lm_info.default_warning_level)), false, LoggingManager::InstanceType::Default, &name); From b9e95b58467bfceb409568d61072e67b027e4d3d Mon Sep 17 00:00:00 2001 From: ivberg Date: Thu, 30 Nov 2023 10:45:40 -0800 Subject: [PATCH 03/22] Add support to Telemetry provider to expose if enabled, level, keyword and use that in QNN EP to set profiling level --- .../onnxruntime/core/common/logging/logging.h | 8 ++++ onnxruntime/core/common/logging/logging.cc | 2 +- onnxruntime/core/platform/telemetry.cc | 14 ++++++ onnxruntime/core/platform/telemetry.h | 8 ++++ .../core/platform/windows/logging/etw_sink.cc | 16 +++---- .../core/platform/windows/logging/etw_sink.h | 15 ++----- .../core/platform/windows/telemetry.cc | 44 ++++++++++++++++++- onnxruntime/core/platform/windows/telemetry.h | 26 +++++++++++ .../providers/qnn/qnn_execution_provider.cc | 16 ++++--- 9 files changed, 121 insertions(+), 28 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index 74571338927d4..0f0e7f6988f33 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -75,6 +75,14 @@ struct Category { // TODO: What other high level categories are meaningful? Model? Optimizer? Execution? }; +enum class TLKeyword : unsigned long long { + Logs = 0x1, + Reserved1 = 0x2, + Reserved2 = 0x4, + Reserved3 = 0x8, + EP = 0x10 +}; + class ISink; class Logger; class Capture; diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 95f83814cc7ed..06729291f4a21 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -266,7 +266,7 @@ std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogge Severity OverrideLevelWithEtw(Severity originalSeverity) { #ifdef _WIN32 auto& manager = logging::EtwRegistrationManager::Instance(); - if (manager.IsEnabled() && (manager.Keyword() & static_cast(logging::Keyword::Logs)) != 0) { + if (manager.IsEnabled() && (manager.Keyword() & static_cast(onnxruntime::logging::TLKeyword::Logs)) != 0) { return manager.MapLevelToSeverity(); // LOGS(*session_logger_, INFO) << "Overriding ...." } diff --git a/onnxruntime/core/platform/telemetry.cc b/onnxruntime/core/platform/telemetry.cc index a99261d1d1caa..9070200e49f58 100644 --- a/onnxruntime/core/platform/telemetry.cc +++ b/onnxruntime/core/platform/telemetry.cc @@ -12,6 +12,20 @@ void LogRuntimeError(uint32_t sessionId, const common::Status& status, const cha env.GetTelemetryProvider().LogRuntimeError(sessionId, status, file, function, line); } +bool Telemetry::IsEnabled() const { + return false; +} + +// Get the current logging level +unsigned char Telemetry::Level() const { + return 0; +} + +// Get the current keyword +unsigned long long Telemetry::Keyword() const { + return 0; +} + void Telemetry::EnableTelemetryEvents() const { } diff --git a/onnxruntime/core/platform/telemetry.h b/onnxruntime/core/platform/telemetry.h index da808e73d97c3..7b2c24d3930ad 100644 --- a/onnxruntime/core/platform/telemetry.h +++ b/onnxruntime/core/platform/telemetry.h @@ -38,6 +38,14 @@ class Telemetry { virtual void DisableTelemetryEvents() const; virtual void SetLanguageProjection(uint32_t projection) const; + virtual bool IsEnabled() const; + + // Get the current logging level + virtual unsigned char Level() const; + + // Get the current keyword + virtual unsigned long long Keyword() const; + virtual void LogProcessInfo() const; virtual void LogSessionCreationStart() const; diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.cc b/onnxruntime/core/platform/windows/logging/etw_sink.cc index 018ea0ec9ecb1..314b64484f38e 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.cc +++ b/onnxruntime/core/platform/windows/logging/etw_sink.cc @@ -66,12 +66,12 @@ EtwRegistrationManager& EtwRegistrationManager::Instance() { } bool EtwRegistrationManager::IsEnabled() const { - std::lock_guard lock(provider_change_mutex_); + std::lock_guard lock(provider_change_mutex_); return is_enabled_; } UCHAR EtwRegistrationManager::Level() const { - std::lock_guard lock(provider_change_mutex_); + std::lock_guard lock(provider_change_mutex_); return level_; } @@ -88,7 +88,7 @@ Severity EtwRegistrationManager::MapLevelToSeverity() { } ULONGLONG EtwRegistrationManager::Keyword() const { - std::lock_guard lock(provider_change_mutex_); + std::lock_guard lock(provider_change_mutex_); return keyword_; } @@ -97,7 +97,7 @@ HRESULT EtwRegistrationManager::Status() const { } void EtwRegistrationManager::RegisterInternalCallback(const EtwInternalCallback& callback) { - std::lock_guard lock(callbacks_mutex_); + std::lock_guard lock(callbacks_mutex_); callbacks_.push_back(callback); } @@ -112,7 +112,7 @@ void NTAPI EtwRegistrationManager::ORT_TL_EtwEnableCallback( { auto& manager = EtwRegistrationManager::Instance(); { - std::lock_guard lock(manager.provider_change_mutex_); + std::lock_guard lock(manager.provider_change_mutex_); manager.is_enabled_ = (IsEnabled != 0); manager.level_ = Level; manager.keyword_ = MatchAnyKeyword; @@ -129,7 +129,7 @@ EtwRegistrationManager::EtwRegistrationManager() { void EtwRegistrationManager::LazyInitialize() { if (!initialized_) { - std::lock_guard lock(init_mutex_); + std::lock_guard lock(init_mutex_); if (!initialized_) { // Double-check locking pattern initialized_ = true; etw_status_ = ::TraceLoggingRegisterEx(etw_provider_handle, ORT_TL_EtwEnableCallback, nullptr); @@ -141,7 +141,7 @@ void EtwRegistrationManager::LazyInitialize() { } void EtwRegistrationManager::InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext) { - std::lock_guard lock(callbacks_mutex_); + std::lock_guard lock(callbacks_mutex_); for (const auto& callback : callbacks_) { callback(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); } @@ -173,7 +173,7 @@ void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, #define ETW_EVENT_NAME "ONNXRuntimeLogEvent" #define TRACE_LOG_WRITE(level) \ TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ - TraceLoggingKeyword(static_cast(Keyword::Logs)), \ + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Logs)), \ TraceLoggingLevel(level), \ TraceLoggingString(logger_id.c_str(), "logger"), \ TraceLoggingString(message.Category(), "category"), \ diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index 5e4e48aa7a6b1..b8f904d08a10a 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.h +++ b/onnxruntime/core/platform/windows/logging/etw_sink.h @@ -24,18 +24,11 @@ #include "core/common/logging/capture.h" #include "core/common/logging/isink.h" +#include "core/platform/ort_mutex.h" namespace onnxruntime { namespace logging { -enum class Keyword : unsigned long long { - Logs = 0x1, - Reserved1 = 0x2, - Reserved2 = 0x4, - Reserved3 = 0x8, - EP = 0x10 -}; - class EtwSink : public ISink { public: @@ -100,9 +93,9 @@ class EtwRegistrationManager { _In_opt_ PVOID CallbackContext); std::vector callbacks_; - std::mutex callbacks_mutex_; - mutable std::mutex provider_change_mutex_; - std::mutex init_mutex_; + OrtMutex callbacks_mutex_; + mutable OrtMutex provider_change_mutex_; + OrtMutex init_mutex_; bool initialized_ = false; bool is_enabled_; UCHAR level_; diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index ec49c2edc2125..1bb9efb1bf6c9 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -55,15 +55,18 @@ TRACELOGGING_DEFINE_PROVIDER(telemetry_provider_handle, "Microsoft.ML.ONNXRuntim #endif OrtMutex WindowsTelemetry::mutex_; +OrtMutex WindowsTelemetry::provider_change_mutex_; uint32_t WindowsTelemetry::global_register_count_ = 0; bool WindowsTelemetry::enabled_ = true; uint32_t WindowsTelemetry::projection_ = 0; +UCHAR WindowsTelemetry::level_ = 0; +ULONGLONG WindowsTelemetry::keyword_ = 0; WindowsTelemetry::WindowsTelemetry() { std::lock_guard lock(mutex_); if (global_register_count_ == 0) { // TraceLoggingRegister is fancy in that you can only register once GLOBALLY for the whole process - HRESULT hr = TraceLoggingRegister(telemetry_provider_handle); + HRESULT hr = TraceLoggingRegisterEx(telemetry_provider_handle, ORT_TL_EtwEnableCallback, nullptr); if (SUCCEEDED(hr)) { global_register_count_ += 1; } @@ -80,6 +83,45 @@ WindowsTelemetry::~WindowsTelemetry() { } } +bool WindowsTelemetry::IsEnabled() const { + std::lock_guard lock(provider_change_mutex_); + return enabled_; +} + +UCHAR WindowsTelemetry::Level() const { + std::lock_guard lock(provider_change_mutex_); + return level_; +} + +ULONGLONG WindowsTelemetry::Keyword() const { + std::lock_guard lock(provider_change_mutex_); + return keyword_; +} + +// HRESULT WindowsTelemetry::Status() { +// return etw_status_; +// } + +void NTAPI WindowsTelemetry::ORT_TL_EtwEnableCallback( + _In_ LPCGUID SourceId, + _In_ ULONG IsEnabled, + _In_ UCHAR Level, + _In_ ULONGLONG MatchAnyKeyword, + _In_ ULONGLONG MatchAllKeyword, + _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, + _In_opt_ PVOID CallbackContext) +{ + (void)SourceId; + (void)MatchAllKeyword; + (void)FilterData; + (void)CallbackContext; + + std::lock_guard lock(provider_change_mutex_); + enabled_ = (IsEnabled != 0); + level_ = Level; + keyword_ = MatchAnyKeyword; +} + void WindowsTelemetry::EnableTelemetryEvents() const { enabled_ = true; } diff --git a/onnxruntime/core/platform/windows/telemetry.h b/onnxruntime/core/platform/windows/telemetry.h index 08e48214c85b3..d997a389ebf39 100644 --- a/onnxruntime/core/platform/windows/telemetry.h +++ b/onnxruntime/core/platform/windows/telemetry.h @@ -3,6 +3,8 @@ #pragma once #include "core/platform/telemetry.h" +#include +#include #include "core/platform/ort_mutex.h" #include "core/platform/windows/TraceLoggingConfig.h" #include @@ -22,6 +24,17 @@ class WindowsTelemetry : public Telemetry { void DisableTelemetryEvents() const override; void SetLanguageProjection(uint32_t projection) const override; + bool IsEnabled() const override; + + // Get the current logging level + unsigned char Level() const override; + + // Get the current keyword + unsigned long long Keyword() const override; + + // Get the ETW registration status + // static HRESULT Status(); + void LogProcessInfo() const override; void LogSessionCreationStart() const override; @@ -50,6 +63,19 @@ class WindowsTelemetry : public Telemetry { static uint32_t global_register_count_; static bool enabled_; static uint32_t projection_; + + static OrtMutex provider_change_mutex_; + static UCHAR level_; + static ULONGLONG keyword_; + + static void NTAPI ORT_TL_EtwEnableCallback( + _In_ LPCGUID SourceId, + _In_ ULONG IsEnabled, + _In_ UCHAR Level, + _In_ ULONGLONG MatchAnyKeyword, + _In_ ULONGLONG MatchAllKeyword, + _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, + _In_opt_ PVOID CallbackContext); }; } // namespace onnxruntime diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index aa5532a246002..6aae85f49fe3f 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -4,12 +4,13 @@ #include "qnn_execution_provider.h" #include -#include "core/providers/common.h" #include "core/framework/compute_capability.h" #include "core/graph/graph_viewer.h" #include "core/session/onnxruntime_session_options_config_keys.h" #include "core/session/onnxruntime_cxx_api.h" #include "core/framework/kernel_registry.h" +#include "core/platform/env.h" +#include "core/providers/common.h" #include "core/providers/partitioning_utils.h" #include "core/providers/qnn/builder/op_builder_factory.h" #include "core/providers/partitioning_utils.h" @@ -146,11 +147,12 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio static const std::string PROFILING_LEVEL = "profiling_level"; qnn::ProfilingLevel profiling_level = qnn::ProfilingLevel::OFF; - auto& manager = logging::EtwRegistrationManager::Instance(); - if (manager.IsEnabled()) { - auto level = manager.Level(); - auto keyword = manager.Keyword(); - if ((manager.Keyword() & static_cast(logging::Keyword::EP)) != 0) { + const Env& env = Env::Default(); + auto& provider = env.GetTelemetryProvider(); + if (provider.IsEnabled()) { + auto level = provider.Level(); + auto keyword = provider.Keyword(); + if ((keyword & static_cast(onnxruntime::logging::TLKeyword::EP)) != 0) { if (level != 0) { if (level == 1) { ParseProfilingLevel("basic", profiling_level); @@ -161,7 +163,7 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio } } else { - auto profiling_level_pos = provider_options_map.find(PROFILING_LEVEL); + auto profiling_level_pos = provider_options_map.find(PROFILING_LEVEL); if (profiling_level_pos != provider_options_map.end()) { ParseProfilingLevel(profiling_level_pos->second, profiling_level); } From 421249d25db0b529e5024ee532fd7d2e794814eb Mon Sep 17 00:00:00 2001 From: ivberg Date: Thu, 30 Nov 2023 11:49:57 -0800 Subject: [PATCH 04/22] Support CompositeSink having seperate min severity so that ETWSink can have more detail that what session options got passed in by default --- .../onnxruntime/core/common/logging/logging.h | 2 +- onnxruntime/core/common/logging/logging.cc | 6 +++--- .../common/logging/sinks/composite_sink.h | 21 +++++++++++-------- .../providers/qnn/qnn_execution_provider.cc | 13 ++++++------ .../providers/qnn/qnn_execution_provider.h | 1 + onnxruntime/core/session/inference_session.cc | 6 ++++-- onnxruntime/core/session/ort_env.cc | 5 +++-- onnxruntime/test/common/logging/sinks_test.cc | 2 +- .../platform/windows/logging/etw_sink_test.cc | 4 ++-- 9 files changed, 34 insertions(+), 26 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index 0f0e7f6988f33..e9aee65d51ae2 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -344,7 +344,7 @@ unsigned int GetProcessId(); /** If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then adds to the existing logger. */ -std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger); +std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, logging::Severity etwSeverity); /** If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then can override the logging level diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 06729291f4a21..53d2bb27647f5 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -246,13 +246,13 @@ unsigned int GetProcessId() { } -std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger) { +std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, logging::Severity etwSeverity) { #ifdef _WIN32 auto& manager = EtwRegistrationManager::Instance(); if (manager.IsEnabled()) { auto compositeSink = std::make_unique(); - compositeSink->AddSink(std::move(existingLogger)); - compositeSink->AddSink(std::make_unique()); + compositeSink->AddSink(std::move(existingLogger), originalSeverity); + compositeSink->AddSink(std::make_unique(), etwSeverity); return compositeSink; } else { return existingLogger; diff --git a/onnxruntime/core/common/logging/sinks/composite_sink.h b/onnxruntime/core/common/logging/sinks/composite_sink.h index c0c37833fba00..284bfa5f322b3 100644 --- a/onnxruntime/core/common/logging/sinks/composite_sink.h +++ b/onnxruntime/core/common/logging/sinks/composite_sink.h @@ -27,28 +27,31 @@ class CompositeSink : public ISink { /// Adds a sink. Takes ownership of the sink (so pass unique_ptr by value). /// /// The sink. + /// The min severity to send a message to that sink /// This instance to allow chaining. - CompositeSink& AddSink(std::unique_ptr sink) { - sinks_.push_back(std::move(sink)); + CompositeSink& AddSink(std::unique_ptr sink, logging::Severity severity) { + sinks_with_severity_.emplace_back(std::move(sink), severity); return *this; } /// - /// Gets a const reference to the collection of sinks. + /// Gets a const reference to the collection of sinks and min severity for that sink /// - /// A const reference to the vector of unique_ptr to ISink. - const std::vector>& GetSinks() const { - return sinks_; + /// A const reference to the vector pair of unique_ptr to ISink and severity. + const std::vector, logging::Severity>>& GetSinks() const { + return sinks_with_severity_; } private: void SendImpl(const Timestamp& timestamp, const std::string& logger_id, const Capture& message) override { - for (auto& sink : sinks_) { - sink->Send(timestamp, logger_id, message); + for (auto& sink_pair : sinks_with_severity_) { + if (message.Severity() >= sink_pair.second) { + sink_pair.first->Send(timestamp, logger_id, message); + } } } - std::vector> sinks_; + std::vector, logging::Severity>> sinks_with_severity_; }; } // namespace logging } // namespace onnxruntime diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index 6aae85f49fe3f..d7a843aea688a 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -153,13 +153,14 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio auto level = provider.Level(); auto keyword = provider.Keyword(); if ((keyword & static_cast(onnxruntime::logging::TLKeyword::EP)) != 0) { - if (level != 0) { - if (level == 1) { - ParseProfilingLevel("basic", profiling_level); - } else { - ParseProfilingLevel("detailed", profiling_level); - } + tracelogging_provider_ep_enabled_ = true; + if (level != 0) { + if (level == 1) { + ParseProfilingLevel("basic", profiling_level); + } else { + ParseProfilingLevel("detailed", profiling_level); } + } } } else { diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.h b/onnxruntime/core/providers/qnn/qnn_execution_provider.h index 8b5d0929209ee..7aa82123b1a67 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.h +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.h @@ -64,6 +64,7 @@ class QNNExecutionProvider : public IExecutionProvider { bool context_cache_enabled_ = false; std::string context_cache_path_cfg_ = ""; bool disable_cpu_ep_fallback_ = false; // True if CPU EP fallback has been disabled for this session. + bool tracelogging_provider_ep_enabled_ = false; bool qnn_context_embed_mode_ = true; int32_t vtcm_size_in_mb_ = 0; }; diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 9c20241d952ba..3232e17547f61 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -333,10 +333,12 @@ void InferenceSession::SetLoggingManager(const SessionOptions& session_options, if (session_options.user_logging_function) { sink = std::make_unique(session_options.user_logging_function, session_options.user_logging_param); - sink = EnhanceLoggerWithEtw(std::move(sink)); + auto sessionSeverity = GetSeverity(session_options); + auto etwOverrideSeverity = logging::OverrideLevelWithEtw(sessionSeverity); + sink = EnhanceLoggerWithEtw(std::move(sink), sessionSeverity, etwOverrideSeverity); user_logging_manager_ = std::make_unique(std::move(sink), - GetSeverity(session_options), + etwOverrideSeverity, false, logging::LoggingManager::InstanceType::Temporal, &session_options.session_logid); diff --git a/onnxruntime/core/session/ort_env.cc b/onnxruntime/core/session/ort_env.cc index e6734984f923c..6a48551522318 100644 --- a/onnxruntime/core/session/ort_env.cc +++ b/onnxruntime/core/session/ort_env.cc @@ -47,9 +47,10 @@ OrtEnv* OrtEnv::GetInstance(const OrtEnv::LoggingManagerConstructionInfo& lm_inf } else { sink = MakePlatformDefaultLogSink(); } - sink = EnhanceLoggerWithEtw(std::move(sink)); + auto etwOverrideSeverity = logging::OverrideLevelWithEtw(static_cast(lm_info.default_warning_level)); + sink = EnhanceLoggerWithEtw(std::move(sink), static_cast(lm_info.default_warning_level), etwOverrideSeverity); lmgr = std::make_unique(std::move(sink), - logging::OverrideLevelWithEtw(static_cast(lm_info.default_warning_level)), + etwOverrideSeverity, false, LoggingManager::InstanceType::Default, &name); diff --git a/onnxruntime/test/common/logging/sinks_test.cc b/onnxruntime/test/common/logging/sinks_test.cc index 28fb407bc2f0e..7ca8d5fc1152c 100644 --- a/onnxruntime/test/common/logging/sinks_test.cc +++ b/onnxruntime/test/common/logging/sinks_test.cc @@ -156,7 +156,7 @@ TEST(LoggingTests, TestCompositeSink) { EXPECT_CALL(*sink_ptr2, SendImpl(testing::_, testing::_, testing::_)).Times(1); CompositeSink* sink = new CompositeSink(); - sink->AddSink(std::unique_ptr{sink_ptr1}).AddSink(std::unique_ptr{sink_ptr2}); + sink->AddSink(std::unique_ptr{sink_ptr1}, min_log_level).AddSink(std::unique_ptr{sink_ptr2}, min_log_level); LoggingManager manager{std::unique_ptr(sink), min_log_level, false, InstanceType::Temporal}; auto logger = manager.CreateLogger(logid); diff --git a/onnxruntime/test/platform/windows/logging/etw_sink_test.cc b/onnxruntime/test/platform/windows/logging/etw_sink_test.cc index 7436ac5bd1729..05ef81d05f4ef 100644 --- a/onnxruntime/test/platform/windows/logging/etw_sink_test.cc +++ b/onnxruntime/test/platform/windows/logging/etw_sink_test.cc @@ -47,8 +47,8 @@ TEST(LoggingTests, TestEtwSink) { /// TEST(LoggingTests, TestEtwSinkCtor) { CompositeSink* sinks = new CompositeSink(); - sinks->AddSink(std::unique_ptr(new EtwSink())) - .AddSink(std::unique_ptr(new EtwSink())); + sinks->AddSink(std::unique_ptr(new EtwSink()), Severity::kWARNING) + .AddSink(std::unique_ptr(new EtwSink()), Severity::kWARNING); LoggingManager manager{std::unique_ptr{sinks}, Severity::kWARNING, From 1231a32804557f7df3bd73533fc21d7f61c7eb49 Mon Sep 17 00:00:00 2001 From: ivberg Date: Thu, 30 Nov 2023 14:31:30 -0800 Subject: [PATCH 05/22] Support writing QNN profiling events to ETW if the provider is enabled --- .../qnn/builder/qnn_backend_manager.cc | 155 +++++++++++++----- .../qnn/builder/qnn_backend_manager.h | 16 +- .../providers/qnn/qnn_execution_provider.cc | 1 - .../providers/qnn/qnn_execution_provider.h | 1 - 4 files changed, 125 insertions(+), 48 deletions(-) diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index 38d74909db86b..e032cd0ed4cc2 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -17,6 +17,7 @@ #include "core/framework/endian_utils.h" #include "core/common/logging/capture.h" #include "core/providers/qnn/builder/onnx_ctx_model_helper.h" +#include "core/platform/tracing.h" // Flag to determine if Backend should do node validation for each opNode added #define DO_GRAPH_NODE_VALIDATIONS 1 @@ -843,28 +844,45 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() { LOGS(*logger_, VERBOSE) << "The QNN backend does not support extended event data."; } - // Write to CSV in append mode - const char* profilingCsvFilename = "qnn-profiling-data.csv"; - std::ifstream infile(profilingCsvFilename); - bool exists = infile.good(); - infile.close(); - - std::ofstream outfile(profilingCsvFilename, std::ios_base::app); - ORT_RETURN_IF(!outfile.is_open(), "Failed to open qnn-profiling-data.csv"); - // If file didn't exist before, write the header - if (!exists) { - outfile << "Msg Timestamp,Message,Time,Unit of Measurement,Timing Source,Event Level,Event Identifier\n"; + bool tracelogging_provider_ep_enabled = false; + const Env& env = Env::Default(); + auto& provider = env.GetTelemetryProvider(); + if (provider.IsEnabled()) { + auto keyword = provider.Keyword(); + if ((keyword & static_cast(onnxruntime::logging::TLKeyword::EP)) != 0) { + tracelogging_provider_ep_enabled = true; + } + } + std::ofstream outfile; + if (!tracelogging_provider_ep_enabled) { + // Write to CSV in append mode + const char* profilingCsvFilename = "qnn-profiling-data.csv"; + std::ifstream infile(profilingCsvFilename); + bool exists = infile.good(); + infile.close(); + + outfile.open(profilingCsvFilename, std::ios_base::app); + ORT_RETURN_IF(!outfile.is_open(), "Failed to open qnn-profiling-data.csv"); + // If file didn't exist before, write the header + if (!exists) { + outfile << "Msg Timestamp,Message,Time,Unit of Measurement,Timing Source,Event Level,Event Identifier\n"; + } } for (size_t event_idx = 0; event_idx < num_events; event_idx++) { ORT_RETURN_IF_ERROR( - ExtractProfilingEvent(*(profile_events + event_idx), "ROOT", outfile, backendSupportsExtendedEventData)); + ExtractProfilingEvent(*(profile_events + event_idx), "ROOT", outfile, backendSupportsExtendedEventData, tracelogging_provider_ep_enabled)); ORT_RETURN_IF_ERROR( - ExtractProfilingSubEvents(*(profile_events + event_idx), outfile, backendSupportsExtendedEventData)); + ExtractProfilingSubEvents(*(profile_events + event_idx), outfile, backendSupportsExtendedEventData, tracelogging_provider_ep_enabled)); } - outfile.close(); - LOGS(*logger_, INFO) << "Wrote QNN profiling events (" << num_events << ") to qnn-profiling-data.csv"; + if (!tracelogging_provider_ep_enabled) { + outfile.close(); + LOGS(*logger_, INFO) << "Wrote QNN profiling events (" << num_events << ") to qnn-profiling-data.csv"; + } + else { + LOGS(*logger_, INFO) << "Wrote QNN profiling events (" << num_events << ") to ETW"; + } } return Status::OK(); @@ -873,7 +891,8 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() { Status QnnBackendManager::ExtractProfilingSubEvents( QnnProfile_EventId_t profile_event_id, std::ofstream& outfile, - bool useExtendedEventData) { + bool useExtendedEventData, + bool tracelogging_provider_ep_enabled) { const QnnProfile_EventId_t* profile_sub_events{nullptr}; uint32_t num_sub_events{0}; auto result = qnn_interface_.profileGetSubEvents(profile_event_id, &profile_sub_events, &num_sub_events); @@ -884,12 +903,12 @@ Status QnnBackendManager::ExtractProfilingSubEvents( for (size_t sub_event_idx = 0; sub_event_idx < num_sub_events; sub_event_idx++) { ORT_RETURN_IF_ERROR( - ExtractProfilingEvent(*(profile_sub_events + sub_event_idx), "SUB-EVENT", outfile, useExtendedEventData)); + ExtractProfilingEvent(*(profile_sub_events + sub_event_idx), "SUB-EVENT", outfile, useExtendedEventData, tracelogging_provider_ep_enabled)); ORT_RETURN_IF_ERROR( - ExtractProfilingSubEvents(*(profile_sub_events + sub_event_idx), outfile, useExtendedEventData)); + ExtractProfilingSubEvents(*(profile_sub_events + sub_event_idx), outfile, useExtendedEventData, tracelogging_provider_ep_enabled)); } - LOGS(*logger_, INFO) << "Wrote QNN profiling sub events (" << num_sub_events << ") to qnn-profiling-data.csv"; + LOGS(*logger_, INFO) << "Wrote QNN profiling sub events (" << num_sub_events << ")"; } return Status::OK(); @@ -899,18 +918,20 @@ Status QnnBackendManager::ExtractProfilingEvent( QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile, - bool useExtendedEventData) { + bool useExtendedEventData, + bool tracelogging_provider_ep_enabled) { if (useExtendedEventData) { - return ExtractProfilingEventExtended(profile_event_id, eventLevel, outfile); + return ExtractProfilingEventExtended(profile_event_id, eventLevel, outfile, tracelogging_provider_ep_enabled); } else { - return ExtractProfilingEventBasic(profile_event_id, eventLevel, outfile); + return ExtractProfilingEventBasic(profile_event_id, eventLevel, outfile, tracelogging_provider_ep_enabled); } } Status QnnBackendManager::ExtractProfilingEventBasic( QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, - std::ofstream& outfile) { + std::ofstream& outfile, + bool tracelogging_provider_ep_enabled) { QnnProfile_EventData_t event_data; auto result = qnn_interface_.profileGetEventData(profile_event_id, &event_data); QnnProfile_Error_t errorCode = static_cast(result & 0xFFFF); @@ -919,15 +940,28 @@ Status QnnBackendManager::ExtractProfilingEventBasic( std::string message = GetEventTypeString(event_data.type); std::string unit = GetUnitString(event_data.unit); - outfile << "UNKNOWN" - << "," - << message << "," - << event_data.value << "," - << unit << "," - << "BACKEND" - << "," - << eventLevel << "," - << (event_data.identifier ? event_data.identifier : "NULL") << "\n"; + if (!tracelogging_provider_ep_enabled) { + outfile << "UNKNOWN" + << "," + << message << "," + << event_data.value << "," + << unit << "," + << "BACKEND" + << "," + << eventLevel << "," + << (event_data.identifier ? event_data.identifier : "NULL") << "\n"; + } + else { + LogQnnProfileEventAsTraceLogging( + (uint64_t) 0, + message, + std::to_string(event_data.value), + unit, + "BACKEND", + eventLevel, + (event_data.identifier ? event_data.identifier : "NULL") + ); + } return Status::OK(); } @@ -935,7 +969,8 @@ Status QnnBackendManager::ExtractProfilingEventBasic( Status QnnBackendManager::ExtractProfilingEventExtended( QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, - std::ofstream& outfile) { + std::ofstream& outfile, + bool tracelogging_provider_ep_enabled) { QnnProfile_ExtendedEventData_t event_data_extended; auto resultGetExtendedEventData = qnn_interface_.profileGetExtendedEventData(profile_event_id, &event_data_extended); QnnProfile_Error_t errorCode = static_cast(resultGetExtendedEventData & 0xFFFF); @@ -944,20 +979,56 @@ Status QnnBackendManager::ExtractProfilingEventExtended( std::string message = GetEventTypeString(event_data_extended.v1.type); std::string unit = GetUnitString(event_data_extended.v1.unit); - if (event_data_extended.version == QNN_PROFILE_DATA_VERSION_1) { - outfile << event_data_extended.v1.timestamp << "," - << message << "," - << ExtractQnnScalarValue(event_data_extended.v1.value) << "," - << unit << "," - << "BACKEND" - << "," - << eventLevel << "," - << (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL") << "\n"; + if (!tracelogging_provider_ep_enabled) { + if (event_data_extended.version == QNN_PROFILE_DATA_VERSION_1) { + outfile << event_data_extended.v1.timestamp << "," + << message << "," + << ExtractQnnScalarValue(event_data_extended.v1.value) << "," + << unit << "," + << "BACKEND" + << "," + << eventLevel << "," + << (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL") << "\n"; + } + } + else { + LogQnnProfileEventAsTraceLogging( + event_data_extended.v1.timestamp, + message, + ExtractQnnScalarValue(event_data_extended.v1.value), + unit, + "BACKEND", + eventLevel, + (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL") + ); } return Status::OK(); } +void QnnBackendManager::LogQnnProfileEventAsTraceLogging( + uint64_t timestamp, + const std::string& message, + const std::string& qnnScalarValue, + const std::string& unit, + const std::string& timingSource, + const std::string& eventLevel, + const char* eventIdentifier) { + TraceLoggingWrite( + telemetry_provider_handle, + "QNNProfilingEvent", + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::EP)), + //TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), + TraceLoggingValue(timestamp, "Timestamp"), + TraceLoggingString(message.c_str(), "Message"), + TraceLoggingString(qnnScalarValue.c_str(), "Value"), + TraceLoggingString(unit.c_str(), "Unit of Measurement"), + TraceLoggingString(timingSource.c_str(), "Timing Source"), + TraceLoggingString(eventLevel.c_str(), "Event Level"), + TraceLoggingString(eventIdentifier, "Event Identifier") + ); +} + const std::string& QnnBackendManager::GetUnitString(QnnProfile_EventUnit_t unitType) { const auto& unitStringMap = GetUnitStringMap(); auto it = unitStringMap.find(unitType); diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h index bc05820da2f73..fd644630b60db 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h @@ -117,8 +117,8 @@ class QnnBackendManager { void Split(std::vector& split_string, const std::string& tokenized_string, const char separator); Status ExtractBackendProfilingInfo(); - Status ExtractProfilingSubEvents(QnnProfile_EventId_t profile_event_id, std::ofstream& outfile, bool backendSupportsExtendedEventData); - Status ExtractProfilingEvent(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile, bool backendSupportsExtendedEventData); + Status ExtractProfilingSubEvents(QnnProfile_EventId_t profile_event_id, std::ofstream& outfile, bool backendSupportsExtendedEventData, bool tracelogging_provider_ep_enabled); + Status ExtractProfilingEvent(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile, bool backendSupportsExtendedEventData, bool tracelogging_provider_ep_enabled); void SetQnnBackendType(uint32_t backend_id); QnnBackendType GetQnnBackendType() { return qnn_backend_type_; } @@ -175,13 +175,21 @@ class QnnBackendManager { return (backend_build_id == nullptr ? std::string("") : std::string(backend_build_id)); } - Status ExtractProfilingEventBasic(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile); - Status ExtractProfilingEventExtended(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile); + Status ExtractProfilingEventBasic(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile, bool tracelogging_provider_ep_enabled); + Status ExtractProfilingEventExtended(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile, bool tracelogging_provider_ep_enabled); static const std::string& GetUnitString(QnnProfile_EventUnit_t unitType); static const std::unordered_map& GetUnitStringMap(); static const std::string GetEventTypeString(QnnProfile_EventType_t eventType); static const std::string ExtractQnnScalarValue(const Qnn_Scalar_t& scalar); const char* QnnProfileErrorToString(QnnProfile_Error_t error); + void LogQnnProfileEventAsTraceLogging( + uint64_t timestamp, + const std::string& message, + const std::string& qnnScalarValue, + const std::string& unit, + const std::string& timingSource, + const std::string& eventLevel, + const char* eventIdentifier); private: const std::string backend_path_; diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index d7a843aea688a..68e7c7f8bb694 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -153,7 +153,6 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio auto level = provider.Level(); auto keyword = provider.Keyword(); if ((keyword & static_cast(onnxruntime::logging::TLKeyword::EP)) != 0) { - tracelogging_provider_ep_enabled_ = true; if (level != 0) { if (level == 1) { ParseProfilingLevel("basic", profiling_level); diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.h b/onnxruntime/core/providers/qnn/qnn_execution_provider.h index 7aa82123b1a67..8b5d0929209ee 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.h +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.h @@ -64,7 +64,6 @@ class QNNExecutionProvider : public IExecutionProvider { bool context_cache_enabled_ = false; std::string context_cache_path_cfg_ = ""; bool disable_cpu_ep_fallback_ = false; // True if CPU EP fallback has been disabled for this session. - bool tracelogging_provider_ep_enabled_ = false; bool qnn_context_embed_mode_ = true; int32_t vtcm_size_in_mb_ = 0; }; From ffec546556e29178d11626cdc1bd060e53f33cf4 Mon Sep 17 00:00:00 2001 From: ivberg Date: Thu, 30 Nov 2023 16:26:54 -0800 Subject: [PATCH 06/22] Fix forgotten override we removed after refactor --- onnxruntime/core/session/inference_session.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 3232e17547f61..4a6f8ffd942c2 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -322,7 +322,7 @@ logging::Severity GetSeverity(const SessionOptions& session_options) { session_options.session_log_severity_level); severity = static_cast(session_options.session_log_severity_level); } - return logging::OverrideLevelWithEtw(severity); + return severity; } void InferenceSession::SetLoggingManager(const SessionOptions& session_options, From f40530edfbd96949fa2a67becda2f3366febb675 Mon Sep 17 00:00:00 2001 From: ivberg Date: Fri, 1 Dec 2023 11:43:38 -0800 Subject: [PATCH 07/22] Take the min of the severity as we don't know which one is more verbose --- onnxruntime/core/session/inference_session.cc | 4 ++-- onnxruntime/core/session/ort_env.cc | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 4a6f8ffd942c2..73a56f66c4330 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -332,13 +332,13 @@ void InferenceSession::SetLoggingManager(const SessionOptions& session_options, if (session_options.user_logging_function) { sink = std::make_unique(session_options.user_logging_function, - session_options.user_logging_param); + session_options.user_logging_param); auto sessionSeverity = GetSeverity(session_options); auto etwOverrideSeverity = logging::OverrideLevelWithEtw(sessionSeverity); sink = EnhanceLoggerWithEtw(std::move(sink), sessionSeverity, etwOverrideSeverity); user_logging_manager_ = std::make_unique(std::move(sink), - etwOverrideSeverity, + std::min(sessionSeverity, etwOverrideSeverity), false, logging::LoggingManager::InstanceType::Temporal, &session_options.session_logid); diff --git a/onnxruntime/core/session/ort_env.cc b/onnxruntime/core/session/ort_env.cc index 6a48551522318..78d476e460b7f 100644 --- a/onnxruntime/core/session/ort_env.cc +++ b/onnxruntime/core/session/ort_env.cc @@ -50,7 +50,7 @@ OrtEnv* OrtEnv::GetInstance(const OrtEnv::LoggingManagerConstructionInfo& lm_inf auto etwOverrideSeverity = logging::OverrideLevelWithEtw(static_cast(lm_info.default_warning_level)); sink = EnhanceLoggerWithEtw(std::move(sink), static_cast(lm_info.default_warning_level), etwOverrideSeverity); lmgr = std::make_unique(std::move(sink), - etwOverrideSeverity, + std::min(static_cast(lm_info.default_warning_level), etwOverrideSeverity), false, LoggingManager::InstanceType::Default, &name); From fe208eeefbbb279d5d48cd648cf8f12c5e9787ea Mon Sep 17 00:00:00 2001 From: ivberg Date: Fri, 1 Dec 2023 11:54:08 -0800 Subject: [PATCH 08/22] LintRunner --- .../onnxruntime/core/common/logging/logging.h | 10 +- onnxruntime/core/common/logging/logging.cc | 30 +++-- .../core/platform/windows/logging/etw_sink.cc | 111 +++++++++--------- .../core/platform/windows/logging/etw_sink.h | 107 +++++++++-------- .../core/platform/windows/telemetry.cc | 33 +++--- onnxruntime/core/platform/windows/telemetry.h | 14 +-- .../qnn/builder/qnn_backend_manager.cc | 60 +++++----- .../qnn/builder/qnn_backend_manager.h | 14 +-- .../providers/qnn/qnn_execution_provider.cc | 7 +- 9 files changed, 190 insertions(+), 196 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index e9aee65d51ae2..2a3fba71199d1 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -76,11 +76,11 @@ struct Category { }; enum class TLKeyword : unsigned long long { - Logs = 0x1, - Reserved1 = 0x2, - Reserved2 = 0x4, - Reserved3 = 0x8, - EP = 0x10 + Logs = 0x1, + Reserved1 = 0x2, + Reserved2 = 0x4, + Reserved3 = 0x8, + EP = 0x10 }; class ISink; diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 53d2bb27647f5..6f4ba1a3c52b1 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -245,32 +245,30 @@ unsigned int GetProcessId() { #endif } - std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, logging::Severity etwSeverity) { #ifdef _WIN32 - auto& manager = EtwRegistrationManager::Instance(); - if (manager.IsEnabled()) { - auto compositeSink = std::make_unique(); - compositeSink->AddSink(std::move(existingLogger), originalSeverity); - compositeSink->AddSink(std::make_unique(), etwSeverity); - return compositeSink; - } else { - return existingLogger; - } -#else - // On non-Windows platforms, just return the existing logger + auto& manager = EtwRegistrationManager::Instance(); + if (manager.IsEnabled()) { + auto compositeSink = std::make_unique(); + compositeSink->AddSink(std::move(existingLogger), originalSeverity); + compositeSink->AddSink(std::make_unique(), etwSeverity); + return compositeSink; + } else { return existingLogger; -#endif // _WIN32 + } +#else + // On non-Windows platforms, just return the existing logger + return existingLogger; +#endif // _WIN32 } Severity OverrideLevelWithEtw(Severity originalSeverity) { #ifdef _WIN32 auto& manager = logging::EtwRegistrationManager::Instance(); if (manager.IsEnabled() && (manager.Keyword() & static_cast(onnxruntime::logging::TLKeyword::Logs)) != 0) { - return manager.MapLevelToSeverity(); - // LOGS(*session_logger_, INFO) << "Overriding ...." + return manager.MapLevelToSeverity(); } -#endif // _WIN32 +#endif // _WIN32 return originalSeverity; } diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.cc b/onnxruntime/core/platform/windows/logging/etw_sink.cc index 314b64484f38e..4151a87afc7b9 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.cc +++ b/onnxruntime/core/platform/windows/logging/etw_sink.cc @@ -58,47 +58,53 @@ TRACELOGGING_DEFINE_PROVIDER(etw_provider_handle, "ONNXRuntimeTraceLoggingProvid #pragma warning(pop) #endif - EtwRegistrationManager& EtwRegistrationManager::Instance() { - static EtwRegistrationManager instance; - instance.LazyInitialize(); - return instance; + static EtwRegistrationManager instance; + instance.LazyInitialize(); + return instance; } bool EtwRegistrationManager::IsEnabled() const { - std::lock_guard lock(provider_change_mutex_); - return is_enabled_; + std::lock_guard lock(provider_change_mutex_); + return is_enabled_; } UCHAR EtwRegistrationManager::Level() const { - std::lock_guard lock(provider_change_mutex_); - return level_; + std::lock_guard lock(provider_change_mutex_); + return level_; } Severity EtwRegistrationManager::MapLevelToSeverity() { - switch (level_) { - case TRACE_LEVEL_NONE: return Severity::kFATAL; // There is no none severity option - case TRACE_LEVEL_VERBOSE: return Severity::kVERBOSE; - case TRACE_LEVEL_INFORMATION: return Severity::kINFO; - case TRACE_LEVEL_WARNING: return Severity::kWARNING; - case TRACE_LEVEL_ERROR: return Severity::kERROR; - case TRACE_LEVEL_CRITICAL: return Severity::kFATAL; - default: return Severity::kVERBOSE; // Default case, or handle it as you see fit - } + switch (level_) { + case TRACE_LEVEL_NONE: + return Severity::kFATAL; // There is no none severity option + case TRACE_LEVEL_VERBOSE: + return Severity::kVERBOSE; + case TRACE_LEVEL_INFORMATION: + return Severity::kINFO; + case TRACE_LEVEL_WARNING: + return Severity::kWARNING; + case TRACE_LEVEL_ERROR: + return Severity::kERROR; + case TRACE_LEVEL_CRITICAL: + return Severity::kFATAL; + default: + return Severity::kVERBOSE; // Default case, or handle it as you see fit + } } ULONGLONG EtwRegistrationManager::Keyword() const { - std::lock_guard lock(provider_change_mutex_); - return keyword_; + std::lock_guard lock(provider_change_mutex_); + return keyword_; } HRESULT EtwRegistrationManager::Status() const { - return etw_status_; + return etw_status_; } void EtwRegistrationManager::RegisterInternalCallback(const EtwInternalCallback& callback) { - std::lock_guard lock(callbacks_mutex_); - callbacks_.push_back(callback); + std::lock_guard lock(callbacks_mutex_); + callbacks_.push_back(callback); } void NTAPI EtwRegistrationManager::ORT_TL_EtwEnableCallback( @@ -108,43 +114,42 @@ void NTAPI EtwRegistrationManager::ORT_TL_EtwEnableCallback( _In_ ULONGLONG MatchAnyKeyword, _In_ ULONGLONG MatchAllKeyword, _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, - _In_opt_ PVOID CallbackContext) -{ - auto& manager = EtwRegistrationManager::Instance(); - { - std::lock_guard lock(manager.provider_change_mutex_); - manager.is_enabled_ = (IsEnabled != 0); - manager.level_ = Level; - manager.keyword_ = MatchAnyKeyword; - } - manager.InvokeCallbacks(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); + _In_opt_ PVOID CallbackContext) { + auto& manager = EtwRegistrationManager::Instance(); + { + std::lock_guard lock(manager.provider_change_mutex_); + manager.is_enabled_ = (IsEnabled != 0); + manager.level_ = Level; + manager.keyword_ = MatchAnyKeyword; + } + manager.InvokeCallbacks(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); } EtwRegistrationManager::~EtwRegistrationManager() { - ::TraceLoggingUnregister(etw_provider_handle); + ::TraceLoggingUnregister(etw_provider_handle); } EtwRegistrationManager::EtwRegistrationManager() { } void EtwRegistrationManager::LazyInitialize() { - if (!initialized_) { - std::lock_guard lock(init_mutex_); - if (!initialized_) { // Double-check locking pattern - initialized_ = true; - etw_status_ = ::TraceLoggingRegisterEx(etw_provider_handle, ORT_TL_EtwEnableCallback, nullptr); - if (FAILED(etw_status_)) { - ORT_THROW("ETW registration failed. Logging will be broken: " + std::to_string(etw_status_)); - } - } + if (!initialized_) { + std::lock_guard lock(init_mutex_); + if (!initialized_) { // Double-check locking pattern + initialized_ = true; + etw_status_ = ::TraceLoggingRegisterEx(etw_provider_handle, ORT_TL_EtwEnableCallback, nullptr); + if (FAILED(etw_status_)) { + ORT_THROW("ETW registration failed. Logging will be broken: " + std::to_string(etw_status_)); + } } + } } void EtwRegistrationManager::InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext) { - std::lock_guard lock(callbacks_mutex_); - for (const auto& callback : callbacks_) { - callback(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); - } + std::lock_guard lock(callbacks_mutex_); + for (const auto& callback : callbacks_) { + callback(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); + } } void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, const Capture& message) { @@ -171,13 +176,13 @@ void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, // TraceLoggingWrite requires (painfully) a compile time constant for the TraceLoggingLevel, // forcing us to use an ugly macro for the call. #define ETW_EVENT_NAME "ONNXRuntimeLogEvent" -#define TRACE_LOG_WRITE(level) \ - TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Logs)), \ - TraceLoggingLevel(level), \ - TraceLoggingString(logger_id.c_str(), "logger"), \ - TraceLoggingString(message.Category(), "category"), \ - TraceLoggingString(message.Location().ToString().c_str(), "location"), \ +#define TRACE_LOG_WRITE(level) \ + TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Logs)), \ + TraceLoggingLevel(level), \ + TraceLoggingString(logger_id.c_str(), "logger"), \ + TraceLoggingString(message.Category(), "category"), \ + TraceLoggingString(message.Location().ToString().c_str(), "location"), \ TraceLoggingString(message.Message().c_str(), "message")) const auto severity{message.Severity()}; diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index b8f904d08a10a..e54767b647e7e 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.h +++ b/onnxruntime/core/platform/windows/logging/etw_sink.h @@ -31,7 +31,6 @@ namespace logging { class EtwSink : public ISink { public: - EtwSink() = default; ~EtwSink() = default; @@ -48,59 +47,59 @@ class EtwSink : public ISink { }; class EtwRegistrationManager { - public: - using EtwInternalCallback = std::function; - - // Singleton instance access - static EtwRegistrationManager& Instance(); - - // Check if ETW logging is enabled - bool IsEnabled() const; - - // Get the current logging level - UCHAR Level() const; - - Severity MapLevelToSeverity(); - - // Get the current keyword - ULONGLONG Keyword() const; - - // Get the ETW registration status - HRESULT Status() const; - - void RegisterInternalCallback(const EtwInternalCallback& callback); - - private: - EtwRegistrationManager(); - ~EtwRegistrationManager(); - void LazyInitialize(); - - // Copy and move constructors/operators are disabled - EtwRegistrationManager(const EtwRegistrationManager&) = delete; - EtwRegistrationManager& operator=(const EtwRegistrationManager&) = delete; - EtwRegistrationManager(EtwRegistrationManager&&) = delete; - EtwRegistrationManager& operator=(EtwRegistrationManager&&) = delete; - - void InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext); - - static void NTAPI ORT_TL_EtwEnableCallback( - _In_ LPCGUID SourceId, - _In_ ULONG IsEnabled, - _In_ UCHAR Level, - _In_ ULONGLONG MatchAnyKeyword, - _In_ ULONGLONG MatchAllKeyword, - _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, - _In_opt_ PVOID CallbackContext); - - std::vector callbacks_; - OrtMutex callbacks_mutex_; - mutable OrtMutex provider_change_mutex_; - OrtMutex init_mutex_; - bool initialized_ = false; - bool is_enabled_; - UCHAR level_; - ULONGLONG keyword_; - HRESULT etw_status_; + public: + using EtwInternalCallback = std::function; + + // Singleton instance access + static EtwRegistrationManager& Instance(); + + // Check if ETW logging is enabled + bool IsEnabled() const; + + // Get the current logging level + UCHAR Level() const; + + Severity MapLevelToSeverity(); + + // Get the current keyword + ULONGLONG Keyword() const; + + // Get the ETW registration status + HRESULT Status() const; + + void RegisterInternalCallback(const EtwInternalCallback& callback); + + private: + EtwRegistrationManager(); + ~EtwRegistrationManager(); + void LazyInitialize(); + + // Copy and move constructors/operators are disabled + EtwRegistrationManager(const EtwRegistrationManager&) = delete; + EtwRegistrationManager& operator=(const EtwRegistrationManager&) = delete; + EtwRegistrationManager(EtwRegistrationManager&&) = delete; + EtwRegistrationManager& operator=(EtwRegistrationManager&&) = delete; + + void InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext); + + static void NTAPI ORT_TL_EtwEnableCallback( + _In_ LPCGUID SourceId, + _In_ ULONG IsEnabled, + _In_ UCHAR Level, + _In_ ULONGLONG MatchAnyKeyword, + _In_ ULONGLONG MatchAllKeyword, + _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, + _In_opt_ PVOID CallbackContext); + + std::vector callbacks_; + OrtMutex callbacks_mutex_; + mutable OrtMutex provider_change_mutex_; + OrtMutex init_mutex_; + bool initialized_ = false; + bool is_enabled_; + UCHAR level_; + ULONGLONG keyword_; + HRESULT etw_status_; }; } // namespace logging diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index 1bb9efb1bf6c9..f1540c56c558a 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -84,18 +84,18 @@ WindowsTelemetry::~WindowsTelemetry() { } bool WindowsTelemetry::IsEnabled() const { - std::lock_guard lock(provider_change_mutex_); - return enabled_; + std::lock_guard lock(provider_change_mutex_); + return enabled_; } UCHAR WindowsTelemetry::Level() const { - std::lock_guard lock(provider_change_mutex_); - return level_; + std::lock_guard lock(provider_change_mutex_); + return level_; } ULONGLONG WindowsTelemetry::Keyword() const { - std::lock_guard lock(provider_change_mutex_); - return keyword_; + std::lock_guard lock(provider_change_mutex_); + return keyword_; } // HRESULT WindowsTelemetry::Status() { @@ -109,17 +109,16 @@ void NTAPI WindowsTelemetry::ORT_TL_EtwEnableCallback( _In_ ULONGLONG MatchAnyKeyword, _In_ ULONGLONG MatchAllKeyword, _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, - _In_opt_ PVOID CallbackContext) -{ - (void)SourceId; - (void)MatchAllKeyword; - (void)FilterData; - (void)CallbackContext; - - std::lock_guard lock(provider_change_mutex_); - enabled_ = (IsEnabled != 0); - level_ = Level; - keyword_ = MatchAnyKeyword; + _In_opt_ PVOID CallbackContext) { + (void)SourceId; + (void)MatchAllKeyword; + (void)FilterData; + (void)CallbackContext; + + std::lock_guard lock(provider_change_mutex_); + enabled_ = (IsEnabled != 0); + level_ = Level; + keyword_ = MatchAnyKeyword; } void WindowsTelemetry::EnableTelemetryEvents() const { diff --git a/onnxruntime/core/platform/windows/telemetry.h b/onnxruntime/core/platform/windows/telemetry.h index d997a389ebf39..526971ebd0f7c 100644 --- a/onnxruntime/core/platform/windows/telemetry.h +++ b/onnxruntime/core/platform/windows/telemetry.h @@ -69,13 +69,13 @@ class WindowsTelemetry : public Telemetry { static ULONGLONG keyword_; static void NTAPI ORT_TL_EtwEnableCallback( - _In_ LPCGUID SourceId, - _In_ ULONG IsEnabled, - _In_ UCHAR Level, - _In_ ULONGLONG MatchAnyKeyword, - _In_ ULONGLONG MatchAllKeyword, - _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, - _In_opt_ PVOID CallbackContext); + _In_ LPCGUID SourceId, + _In_ ULONG IsEnabled, + _In_ UCHAR Level, + _In_ ULONGLONG MatchAnyKeyword, + _In_ ULONGLONG MatchAllKeyword, + _In_opt_ PEVENT_FILTER_DESCRIPTOR FilterData, + _In_opt_ PVOID CallbackContext); }; } // namespace onnxruntime diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index e032cd0ed4cc2..2d7f493cd657f 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -879,8 +879,7 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() { if (!tracelogging_provider_ep_enabled) { outfile.close(); LOGS(*logger_, INFO) << "Wrote QNN profiling events (" << num_events << ") to qnn-profiling-data.csv"; - } - else { + } else { LOGS(*logger_, INFO) << "Wrote QNN profiling events (" << num_events << ") to ETW"; } } @@ -950,17 +949,15 @@ Status QnnBackendManager::ExtractProfilingEventBasic( << "," << eventLevel << "," << (event_data.identifier ? event_data.identifier : "NULL") << "\n"; - } - else { + } else { LogQnnProfileEventAsTraceLogging( - (uint64_t) 0, - message, - std::to_string(event_data.value), - unit, - "BACKEND", - eventLevel, - (event_data.identifier ? event_data.identifier : "NULL") - ); + (uint64_t)0, + message, + std::to_string(event_data.value), + unit, + "BACKEND", + eventLevel, + (event_data.identifier ? event_data.identifier : "NULL")); } return Status::OK(); @@ -990,43 +987,40 @@ Status QnnBackendManager::ExtractProfilingEventExtended( << eventLevel << "," << (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL") << "\n"; } - } - else { + } else { LogQnnProfileEventAsTraceLogging( - event_data_extended.v1.timestamp, - message, - ExtractQnnScalarValue(event_data_extended.v1.value), - unit, - "BACKEND", - eventLevel, - (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL") - ); + event_data_extended.v1.timestamp, + message, + ExtractQnnScalarValue(event_data_extended.v1.value), + unit, + "BACKEND", + eventLevel, + (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL")); } return Status::OK(); } void QnnBackendManager::LogQnnProfileEventAsTraceLogging( - uint64_t timestamp, - const std::string& message, - const std::string& qnnScalarValue, - const std::string& unit, - const std::string& timingSource, - const std::string& eventLevel, - const char* eventIdentifier) { - TraceLoggingWrite( + uint64_t timestamp, + const std::string& message, + const std::string& qnnScalarValue, + const std::string& unit, + const std::string& timingSource, + const std::string& eventLevel, + const char* eventIdentifier) { + TraceLoggingWrite( telemetry_provider_handle, "QNNProfilingEvent", TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::EP)), - //TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), + // TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), TraceLoggingValue(timestamp, "Timestamp"), TraceLoggingString(message.c_str(), "Message"), TraceLoggingString(qnnScalarValue.c_str(), "Value"), TraceLoggingString(unit.c_str(), "Unit of Measurement"), TraceLoggingString(timingSource.c_str(), "Timing Source"), TraceLoggingString(eventLevel.c_str(), "Event Level"), - TraceLoggingString(eventIdentifier, "Event Identifier") - ); + TraceLoggingString(eventIdentifier, "Event Identifier")); } const std::string& QnnBackendManager::GetUnitString(QnnProfile_EventUnit_t unitType) { diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h index fd644630b60db..ada3e8ff2dba6 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h @@ -183,13 +183,13 @@ class QnnBackendManager { static const std::string ExtractQnnScalarValue(const Qnn_Scalar_t& scalar); const char* QnnProfileErrorToString(QnnProfile_Error_t error); void LogQnnProfileEventAsTraceLogging( - uint64_t timestamp, - const std::string& message, - const std::string& qnnScalarValue, - const std::string& unit, - const std::string& timingSource, - const std::string& eventLevel, - const char* eventIdentifier); + uint64_t timestamp, + const std::string& message, + const std::string& qnnScalarValue, + const std::string& unit, + const std::string& timingSource, + const std::string& eventLevel, + const char* eventIdentifier); private: const std::string backend_path_; diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index 68e7c7f8bb694..5ab9cc1dd4d4e 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -155,14 +155,13 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio if ((keyword & static_cast(onnxruntime::logging::TLKeyword::EP)) != 0) { if (level != 0) { if (level == 1) { - ParseProfilingLevel("basic", profiling_level); + ParseProfilingLevel("basic", profiling_level); } else { - ParseProfilingLevel("detailed", profiling_level); + ParseProfilingLevel("detailed", profiling_level); } } } - } - else { + } else { auto profiling_level_pos = provider_options_map.find(PROFILING_LEVEL); if (profiling_level_pos != provider_options_map.end()) { ParseProfilingLevel(profiling_level_pos->second, profiling_level); From 4efea8b254c423aa094e34b5dfd6205d1a0eff3b Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Wed, 13 Dec 2023 16:27:50 -0800 Subject: [PATCH 09/22] move per inference very verbose log statements to VLOGs --- onnxruntime/core/framework/sequential_executor.cc | 6 +++--- onnxruntime/core/framework/stream_execution_context.cc | 2 +- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/onnxruntime/core/framework/sequential_executor.cc b/onnxruntime/core/framework/sequential_executor.cc index ba68bc1d7d834..9ded6dc23d0e4 100644 --- a/onnxruntime/core/framework/sequential_executor.cc +++ b/onnxruntime/core/framework/sequential_executor.cc @@ -181,7 +181,7 @@ class SessionScope { } auto& logger = session_state_.Logger(); - LOGS(logger, VERBOSE) << "Begin execution"; + VLOGS(logger, VERBOSE) << "Begin execution"; const SequentialExecutionPlan& seq_exec_plan = *session_state_.GetExecutionPlan(); const auto& exec_plan_vec = seq_exec_plan.execution_plan; VLOGS(logger, 1) << "Size of execution plan vector: " << exec_plan_vec.size(); @@ -515,7 +515,7 @@ onnxruntime::Status ExecuteKernel(StreamExecutionContext& ctx, return Status(status.Category(), status.Code(), msg_string); } ctx.RecycleNodeInputs(idx); - LOGS(logger, VERBOSE) << "stream " << stream_idx << " launch kernel with idx " << idx; + VLOGS(logger, VERBOSE) << "stream " << stream_idx << " launch kernel with idx " << idx; return Status::OK(); } @@ -531,7 +531,7 @@ onnxruntime::Status ExecuteThePlan(const SessionState& session_state, gsl::span< const bool only_execute_path_to_fetches, bool single_thread_mode) { auto* execution_plan = session_state.GetExecutionPlan(); - LOGS(logger, VERBOSE) << "Number of streams: " << execution_plan->execution_plan.size(); + VLOGS(logger, VERBOSE) << "Number of streams: " << execution_plan->execution_plan.size(); int32_t valid_streams = 0; for (auto& stream : execution_plan->execution_plan) { if (stream && stream->steps_.size() > 0) diff --git a/onnxruntime/core/framework/stream_execution_context.cc b/onnxruntime/core/framework/stream_execution_context.cc index 4ff5ee5db865d..4eef9639a2339 100644 --- a/onnxruntime/core/framework/stream_execution_context.cc +++ b/onnxruntime/core/framework/stream_execution_context.cc @@ -168,7 +168,7 @@ void StreamExecutionContext::RecycleNodeInputs(onnxruntime::NodeIndex node_index for (auto idx : execution_plan->node_release_list[node_index]) { if (--release_plan_[idx] == 0) { ORT_ENFORCE(frame_.ReleaseMLValue(static_cast(execution_plan->release_actions[idx].value_index)).IsOK()); - LOGS(*logger_, VERBOSE) << "ort value " << execution_plan->release_actions[idx].value_index << " released"; + VLOGS(*logger_, VERBOSE) << "ort value " << execution_plan->release_actions[idx].value_index << " released"; } } } From 0a92598913ce0a540d2760d425b984db19ac656d Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Wed, 13 Dec 2023 17:21:26 -0800 Subject: [PATCH 10/22] Mark all ETW events with appropiate keyword and level. Cleanup --- .../onnxruntime/core/common/logging/logging.h | 17 +++++++++++------ .../core/framework/execution_providers.h | 3 +++ .../core/platform/windows/logging/etw_sink.cc | 2 +- .../qnn/builder/qnn_backend_manager.cc | 10 +++++++--- .../providers/qnn/qnn_execution_provider.cc | 2 +- onnxruntime/core/session/inference_session.cc | 6 ++++++ .../core/session/provider_registration.cc | 4 ++++ 7 files changed, 33 insertions(+), 11 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index 2a3fba71199d1..8ff08c9789d52 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -76,11 +76,15 @@ struct Category { }; enum class TLKeyword : unsigned long long { - Logs = 0x1, - Reserved1 = 0x2, - Reserved2 = 0x4, - Reserved3 = 0x8, - EP = 0x10 + Session = 0x1, + Logs = 0x2, + Reserved1 = 0x4, + Reserved2 = 0x8, + Reserved3 = 0x10, + Reserved4 = 0x20, + Reserved5 = 0x40, + Reserved6 = 0x80, + Profiling = 0x100 }; class ISink; @@ -347,7 +351,8 @@ unsigned int GetProcessId(); std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, logging::Severity etwSeverity); /** - If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then can override the logging level + If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then can override the logging level. + But this overrided level only applies to the ETW sink. The original logger(s) retain their original logging level */ Severity OverrideLevelWithEtw(Severity originalSeverity); diff --git a/onnxruntime/core/framework/execution_providers.h b/onnxruntime/core/framework/execution_providers.h index d97953fd9d5ea..0320715a0c7a5 100644 --- a/onnxruntime/core/framework/execution_providers.h +++ b/onnxruntime/core/framework/execution_providers.h @@ -14,6 +14,7 @@ #include "core/common/logging/logging.h" #ifdef _WIN32 #include "core/platform/tracing.h" +#include "winmeta.h" #endif namespace onnxruntime { @@ -47,6 +48,8 @@ class ExecutionProviders { TraceLoggingWrite( telemetry_provider_handle, "ProviderOptions", + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(provider_id.c_str(), "ProviderId"), TraceLoggingString(config_pair.first.c_str(), "Key"), TraceLoggingString(config_pair.second.c_str(), "Value")); diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.cc b/onnxruntime/core/platform/windows/logging/etw_sink.cc index 4151a87afc7b9..c2e853b0c9c00 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.cc +++ b/onnxruntime/core/platform/windows/logging/etw_sink.cc @@ -89,7 +89,7 @@ Severity EtwRegistrationManager::MapLevelToSeverity() { case TRACE_LEVEL_CRITICAL: return Severity::kFATAL; default: - return Severity::kVERBOSE; // Default case, or handle it as you see fit + return Severity::kVERBOSE; } } diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index 2d7f493cd657f..d6203846886f3 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -17,7 +17,11 @@ #include "core/framework/endian_utils.h" #include "core/common/logging/capture.h" #include "core/providers/qnn/builder/onnx_ctx_model_helper.h" + +#ifdef _WIN32 #include "core/platform/tracing.h" +#include "winmeta.h" +#endif // Flag to determine if Backend should do node validation for each opNode added #define DO_GRAPH_NODE_VALIDATIONS 1 @@ -849,7 +853,7 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() { auto& provider = env.GetTelemetryProvider(); if (provider.IsEnabled()) { auto keyword = provider.Keyword(); - if ((keyword & static_cast(onnxruntime::logging::TLKeyword::EP)) != 0) { + if ((keyword & static_cast(onnxruntime::logging::TLKeyword::Profiling)) != 0) { tracelogging_provider_ep_enabled = true; } } @@ -1012,8 +1016,8 @@ void QnnBackendManager::LogQnnProfileEventAsTraceLogging( TraceLoggingWrite( telemetry_provider_handle, "QNNProfilingEvent", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::EP)), - // TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Profiling)), + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), TraceLoggingValue(timestamp, "Timestamp"), TraceLoggingString(message.c_str(), "Message"), TraceLoggingString(qnnScalarValue.c_str(), "Value"), diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index 5ab9cc1dd4d4e..72c8af4fe220f 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -152,7 +152,7 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio if (provider.IsEnabled()) { auto level = provider.Level(); auto keyword = provider.Keyword(); - if ((keyword & static_cast(onnxruntime::logging::TLKeyword::EP)) != 0) { + if ((keyword & static_cast(onnxruntime::logging::TLKeyword::Profiling)) != 0) { if (level != 0) { if (level == 1) { ParseProfilingLevel("basic", profiling_level); diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 73a56f66c4330..86136315418ac 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -479,6 +479,8 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options #ifdef _WIN32 TraceLoggingWrite(telemetry_provider_handle, "SessionOptions", + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingUInt8(static_cast(session_options.execution_mode), "execution_mode"), TraceLoggingUInt8(static_cast(session_options.execution_order), "execution_order"), TraceLoggingBoolean(session_options.enable_profiling, "enable_profiling"), @@ -499,6 +501,8 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingWrite( telemetry_provider_handle, "SessionOptions_IntraOrtThreadPoolParams", + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingInt32(session_options.intra_op_param.thread_pool_size, "thread_pool_size"), TraceLoggingBoolean(session_options.intra_op_param.auto_set_affinity, "auto_set_affinity"), TraceLoggingBoolean(session_options.intra_op_param.allow_spinning, "allow_spinning"), @@ -511,6 +515,8 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingWrite( telemetry_provider_handle, "SessionOptions_ConfigEntry", + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(config_pair.first.c_str(), "Key"), TraceLoggingString(config_pair.second.c_str(), "Value")); } diff --git a/onnxruntime/core/session/provider_registration.cc b/onnxruntime/core/session/provider_registration.cc index 2e9af9f1f9bb2..49c24dcd6b3a6 100644 --- a/onnxruntime/core/session/provider_registration.cc +++ b/onnxruntime/core/session/provider_registration.cc @@ -4,6 +4,7 @@ #include #include "core/common/common.h" +#include "core/common/logging/logging.h" #include "core/framework/error_code_helper.h" #include "core/framework/provider_options.h" #include "core/providers/provider_factory_creators.h" @@ -14,6 +15,7 @@ #ifdef _WIN32 #include "core/platform/tracing.h" +#include "winmeta.h" #endif #if defined(USE_DML) @@ -75,6 +77,8 @@ ORT_API_STATUS_IMPL(OrtApis::SessionOptionsAppendExecutionProvider, TraceLoggingWrite( telemetry_provider_handle, "ProviderOptionsAppendExecutionProvider", + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(provider_name, "ProviderName"), TraceLoggingString(config_pair.first.c_str(), "Key"), TraceLoggingString(config_pair.second.c_str(), "Value")); From e56d9519b61a97dd91b528507064a53451b5c6bd Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Fri, 15 Dec 2023 14:59:36 -0800 Subject: [PATCH 11/22] Fine-tune QNN Profiling and logging to be aware of common ETW levels without much impacting perf of inference say during a tight loop like onnxruntime_perf_test.exe --- .../qnn/builder/qnn_backend_manager.cc | 6 ++-- .../providers/qnn/qnn_execution_provider.cc | 11 +++++-- .../logging/HowToValidateEtwSinkOutput.md | 31 ++++++++++++++----- 3 files changed, 35 insertions(+), 13 deletions(-) diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index d6203846886f3..0709814275c2c 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -882,9 +882,9 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() { if (!tracelogging_provider_ep_enabled) { outfile.close(); - LOGS(*logger_, INFO) << "Wrote QNN profiling events (" << num_events << ") to qnn-profiling-data.csv"; + LOGS(*logger_, VERBOSE) << "Wrote QNN profiling events (" << num_events << ") to qnn-profiling-data.csv"; } else { - LOGS(*logger_, INFO) << "Wrote QNN profiling events (" << num_events << ") to ETW"; + LOGS(*logger_, VERBOSE) << "Wrote QNN profiling events (" << num_events << ") to ETW"; } } @@ -911,7 +911,7 @@ Status QnnBackendManager::ExtractProfilingSubEvents( ExtractProfilingSubEvents(*(profile_sub_events + sub_event_idx), outfile, useExtendedEventData, tracelogging_provider_ep_enabled)); } - LOGS(*logger_, INFO) << "Wrote QNN profiling sub events (" << num_sub_events << ")"; + LOGS(*logger_, VERBOSE) << "Wrote QNN profiling sub events (" << num_sub_events << ")"; } return Status::OK(); diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index 72c8af4fe220f..e6d36f4b7f2ef 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -29,7 +29,7 @@ static void ParseProfilingLevel(std::string profiling_level_string, profiling_level_string.end(), profiling_level_string.begin(), [](unsigned char c) { return static_cast(std::tolower(c)); }); - LOGS_DEFAULT(VERBOSE) << "profiling_level: " << profiling_level_string; + LOGS_DEFAULT(INFO) << "profiling_level: " << profiling_level_string; if (profiling_level_string == "off") { profiling_level = qnn::ProfilingLevel::OFF; } else if (profiling_level_string == "basic") { @@ -154,9 +154,14 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio auto keyword = provider.Keyword(); if ((keyword & static_cast(onnxruntime::logging::TLKeyword::Profiling)) != 0) { if (level != 0) { - if (level == 1) { + if (level == 5) { + LOGS_DEFAULT(INFO) << "Overriding profiling to basic based on ETW level: " << static_cast(level); ParseProfilingLevel("basic", profiling_level); - } else { + } else if (level < 5) { + LOGS_DEFAULT(INFO) << "QNN Profiler ETW level not supported below level 5. Level: " << static_cast(level); + } + else { + LOGS_DEFAULT(INFO) << "Overriding profiling to detailed based on ETW level: " << static_cast(level); ParseProfilingLevel("detailed", profiling_level); } } diff --git a/onnxruntime/test/platform/windows/logging/HowToValidateEtwSinkOutput.md b/onnxruntime/test/platform/windows/logging/HowToValidateEtwSinkOutput.md index 2f8d06d66d576..6048fffa558f8 100644 --- a/onnxruntime/test/platform/windows/logging/HowToValidateEtwSinkOutput.md +++ b/onnxruntime/test/platform/windows/logging/HowToValidateEtwSinkOutput.md @@ -1,10 +1,19 @@ -## Validating ETW Sink unit test output +## About the ETW Sink -## Setup -Install Windows Performance Toolkit from -You get to select components when installing, so can select just the performance toolkit. +The ETW Sink (ONNXRuntimeTraceLoggingProvider) allows ONNX semi-structured printf style logs to be output via ETW. -Overview of the steps is at if you want more detail. +ETW makes it easy and useful to only enable and listen for events with great performance, and when you need them instead of only at compile time. +Therefore ONNX will preserve any existing loggers and log severity [provided at compile time](docs/FAQ.md?plain=1#L7). + +However, when the provider is enabled a new ETW logger sink will also be added and the severity seperately controlled via ETW dynamically. + +- Provider GUID: 929DD115-1ECB-4CB5-B060-EBD4983C421D +- Keyword: Logs (0x2) keyword per [logging.h](include\onnxruntime\core\common\logging\logging.h) +- Level: 1-5 ([CRITICAL through VERBOSE](https://learn.microsoft.com/en-us/windows/win32/api/evntprov/ns-evntprov-event_descriptor)) [mapping](onnxruntime\core\platform\windows\logging\etw_sink.cc) to [ONNX severity](include\onnxruntime\core\common\logging\severity.h) in an intuitive manner + +Notes: +- The ETW provider must be enabled prior to session creation, as that as when internal logging setup is complete +- Other structured ETW logs are output via the other Microsoft.ML.ONNXRuntime ETW provider. Both used together are recommended ## Capturing ETW trace output @@ -25,9 +34,17 @@ Run the ETW sink unit tests Stop the ETW tracing `\onnxruntime\test\platform\windows\logging> wpr -stop TraceCaptureFile.etl EtwSinkTest` -## View the output +## View the trace output + +### Setup +- Install Windows Performance Analyzer (Preview) from the Windows Store - +- Or from the ADK + - You get to select components when installing, so can select just the performance toolkit. + - Overview of the steps is at if you want more detail. + +### Viewing -Open TraceCaptureFile.etl file Windows Performance Analyzer. +Open TraceCaptureFile.etl file in Windows Performance Analyzer. Expand the "System Activity" dropdown in the left pane, and double-click "Generic Events". That should open events in an Analysis window in the right pane. You should see an event From 7e67f71ae625e6b7e4ae853783677c57df4d86bf Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Fri, 15 Dec 2023 15:01:51 -0800 Subject: [PATCH 12/22] Introduce appropiate ETW levels of some existing "Telemetry" events from the default of VERBOSE to say ERROR or INFO. This is so that the appropiate level of events show up when an ETW user specifies a lower level when listening for events --- onnxruntime/core/platform/windows/telemetry.cc | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index f1540c56c558a..063ddc32591f2 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -2,6 +2,7 @@ // Licensed under the MIT License. #include "core/platform/windows/telemetry.h" +#include "core/common/logging/logging.h" #include "onnxruntime_config.h" // ETW includes @@ -16,6 +17,7 @@ #include #include +#include "winmeta.h" // Seems this workaround can be dropped when we drop support for VS2017 toolchains // https://developercommunity.visualstudio.com/content/problem/85934/traceloggingproviderh-is-incompatible-with-utf-8.html @@ -151,6 +153,7 @@ void WindowsTelemetry::LogProcessInfo() const { TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage), TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), + TraceLoggingLevel(WINEVENT_LEVEL_INFO), // Telemetry info TraceLoggingUInt8(0, "schemaVersion"), TraceLoggingString(ORT_VERSION, "runtimeVersion"), @@ -167,7 +170,8 @@ void WindowsTelemetry::LogSessionCreationStart() const { "SessionCreationStart", TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage), - TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES)); + TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), + TraceLoggingLevel(WINEVENT_LEVEL_INFO)); } void WindowsTelemetry::LogEvaluationStop() const { @@ -175,7 +179,8 @@ void WindowsTelemetry::LogEvaluationStop() const { return; TraceLoggingWrite(telemetry_provider_handle, - "EvaluationStop"); + "EvaluationStop", + ); } void WindowsTelemetry::LogEvaluationStart() const { @@ -240,6 +245,8 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage), TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingLevel(WINEVENT_LEVEL_INFO), // Telemetry info TraceLoggingUInt8(0, "schemaVersion"), TraceLoggingUInt32(session_id, "sessionId"), @@ -268,6 +275,7 @@ void WindowsTelemetry::LogRuntimeError(uint32_t session_id, const common::Status TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), + TraceLoggingLevel(WINEVENT_LEVEL_ERROR), // Telemetry info TraceLoggingUInt8(0, "schemaVersion"), TraceLoggingHResult(hr, "hResult"), @@ -284,6 +292,7 @@ void WindowsTelemetry::LogRuntimeError(uint32_t session_id, const common::Status TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), TelemetryPrivacyDataTag(PDT_ProductAndServicePerformance), TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), + TraceLoggingLevel(WINEVENT_LEVEL_ERROR), // Telemetry info TraceLoggingUInt8(0, "schemaVersion"), TraceLoggingUInt32(session_id, "sessionId"), From 281d624dc3290a50159cf06b47c49d64c5f9dd17 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Tue, 19 Dec 2023 14:58:42 -0800 Subject: [PATCH 13/22] Change ORT.wprp to level 5 --- ort.wprp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/ort.wprp b/ort.wprp index 8738efeb599ad..b82ec5882c60d 100644 --- a/ort.wprp +++ b/ort.wprp @@ -8,12 +8,12 @@ - + + Name="3a26b1ff-7484-7484-7484-15261f42614d" Level="5" /> From d7f4d5a78d7cedf92f2f7bce572195f0603a69ac Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Tue, 19 Dec 2023 16:51:27 -0800 Subject: [PATCH 14/22] LintRunner --- onnxruntime/core/platform/windows/telemetry.cc | 3 +-- onnxruntime/core/providers/qnn/qnn_execution_provider.cc | 3 +-- 2 files changed, 2 insertions(+), 4 deletions(-) diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index 063ddc32591f2..ed65d23c8cbae 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -179,8 +179,7 @@ void WindowsTelemetry::LogEvaluationStop() const { return; TraceLoggingWrite(telemetry_provider_handle, - "EvaluationStop", - ); + "EvaluationStop", ); } void WindowsTelemetry::LogEvaluationStart() const { diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index e6d36f4b7f2ef..a2abcf500a360 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -159,8 +159,7 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio ParseProfilingLevel("basic", profiling_level); } else if (level < 5) { LOGS_DEFAULT(INFO) << "QNN Profiler ETW level not supported below level 5. Level: " << static_cast(level); - } - else { + } else { LOGS_DEFAULT(INFO) << "Overriding profiling to detailed based on ETW level: " << static_cast(level); ParseProfilingLevel("detailed", profiling_level); } From 17fad57ae72cb296a383b4c75553efcc86d6e921 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Wed, 20 Dec 2023 11:51:23 -0800 Subject: [PATCH 15/22] Fixes for PR cross-platform build, cpplint --- .../onnxruntime/core/common/logging/logging.h | 3 ++- onnxruntime/core/common/logging/logging.cc | 5 ++++- .../core/common/logging/sinks/composite_sink.h | 2 ++ .../core/framework/execution_providers.h | 4 ++-- .../core/framework/sequential_executor.cc | 6 +++--- .../core/framework/stream_execution_context.cc | 2 +- onnxruntime/core/platform/telemetry.cc | 2 +- onnxruntime/core/platform/telemetry.h | 2 +- .../core/platform/windows/logging/etw_sink.cc | 18 ++++++++++-------- .../core/platform/windows/logging/etw_sink.h | 2 +- onnxruntime/core/platform/windows/telemetry.cc | 6 +++--- onnxruntime/core/platform/windows/telemetry.h | 2 +- .../qnn/builder/qnn_backend_manager.cc | 10 ++++++++-- onnxruntime/core/session/inference_session.cc | 6 +++--- .../core/session/provider_registration.cc | 2 +- .../logging/HowToValidateEtwSinkOutput.md | 2 +- 16 files changed, 44 insertions(+), 30 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index 8ff08c9789d52..b67fb5a84e831 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -348,7 +348,8 @@ unsigned int GetProcessId(); /** If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then adds to the existing logger. */ -std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, logging::Severity etwSeverity); +std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, + logging::Severity etwSeverity); /** If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then can override the logging level. diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 6f4ba1a3c52b1..982040e44c245 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -245,7 +245,8 @@ unsigned int GetProcessId() { #endif } -std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, logging::Severity etwSeverity) { +std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, + logging::Severity etwSeverity) { #ifdef _WIN32 auto& manager = EtwRegistrationManager::Instance(); if (manager.IsEnabled()) { @@ -258,6 +259,8 @@ std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogge } #else // On non-Windows platforms, just return the existing logger + (void)originalSeverity; + (void)etwSeverity; return existingLogger; #endif // _WIN32 } diff --git a/onnxruntime/core/common/logging/sinks/composite_sink.h b/onnxruntime/core/common/logging/sinks/composite_sink.h index 284bfa5f322b3..9d18eb527ffdd 100644 --- a/onnxruntime/core/common/logging/sinks/composite_sink.h +++ b/onnxruntime/core/common/logging/sinks/composite_sink.h @@ -5,6 +5,8 @@ #include #include +#include +#include #include "core/common/logging/isink.h" #include "core/common/logging/logging.h" diff --git a/onnxruntime/core/framework/execution_providers.h b/onnxruntime/core/framework/execution_providers.h index 0320715a0c7a5..38e1790808456 100644 --- a/onnxruntime/core/framework/execution_providers.h +++ b/onnxruntime/core/framework/execution_providers.h @@ -13,8 +13,8 @@ #include "core/graph/graph_viewer.h" #include "core/common/logging/logging.h" #ifdef _WIN32 +#include #include "core/platform/tracing.h" -#include "winmeta.h" #endif namespace onnxruntime { @@ -48,7 +48,7 @@ class ExecutionProviders { TraceLoggingWrite( telemetry_provider_handle, "ProviderOptions", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(provider_id.c_str(), "ProviderId"), TraceLoggingString(config_pair.first.c_str(), "Key"), diff --git a/onnxruntime/core/framework/sequential_executor.cc b/onnxruntime/core/framework/sequential_executor.cc index 9ded6dc23d0e4..ea7f1397c961b 100644 --- a/onnxruntime/core/framework/sequential_executor.cc +++ b/onnxruntime/core/framework/sequential_executor.cc @@ -181,7 +181,7 @@ class SessionScope { } auto& logger = session_state_.Logger(); - VLOGS(logger, VERBOSE) << "Begin execution"; + VLOGS(logger, 0) << "Begin execution"; const SequentialExecutionPlan& seq_exec_plan = *session_state_.GetExecutionPlan(); const auto& exec_plan_vec = seq_exec_plan.execution_plan; VLOGS(logger, 1) << "Size of execution plan vector: " << exec_plan_vec.size(); @@ -515,7 +515,7 @@ onnxruntime::Status ExecuteKernel(StreamExecutionContext& ctx, return Status(status.Category(), status.Code(), msg_string); } ctx.RecycleNodeInputs(idx); - VLOGS(logger, VERBOSE) << "stream " << stream_idx << " launch kernel with idx " << idx; + VLOGS(logger, 0) << "stream " << stream_idx << " launch kernel with idx " << idx; return Status::OK(); } @@ -531,7 +531,7 @@ onnxruntime::Status ExecuteThePlan(const SessionState& session_state, gsl::span< const bool only_execute_path_to_fetches, bool single_thread_mode) { auto* execution_plan = session_state.GetExecutionPlan(); - VLOGS(logger, VERBOSE) << "Number of streams: " << execution_plan->execution_plan.size(); + VLOGS(logger, 0) << "Number of streams: " << execution_plan->execution_plan.size(); int32_t valid_streams = 0; for (auto& stream : execution_plan->execution_plan) { if (stream && stream->steps_.size() > 0) diff --git a/onnxruntime/core/framework/stream_execution_context.cc b/onnxruntime/core/framework/stream_execution_context.cc index 4eef9639a2339..875e7f395bfa8 100644 --- a/onnxruntime/core/framework/stream_execution_context.cc +++ b/onnxruntime/core/framework/stream_execution_context.cc @@ -168,7 +168,7 @@ void StreamExecutionContext::RecycleNodeInputs(onnxruntime::NodeIndex node_index for (auto idx : execution_plan->node_release_list[node_index]) { if (--release_plan_[idx] == 0) { ORT_ENFORCE(frame_.ReleaseMLValue(static_cast(execution_plan->release_actions[idx].value_index)).IsOK()); - VLOGS(*logger_, VERBOSE) << "ort value " << execution_plan->release_actions[idx].value_index << " released"; + VLOGS(*logger_, 0) << "ort value " << execution_plan->release_actions[idx].value_index << " released"; } } } diff --git a/onnxruntime/core/platform/telemetry.cc b/onnxruntime/core/platform/telemetry.cc index 9070200e49f58..8dcdae21a36d6 100644 --- a/onnxruntime/core/platform/telemetry.cc +++ b/onnxruntime/core/platform/telemetry.cc @@ -22,7 +22,7 @@ unsigned char Telemetry::Level() const { } // Get the current keyword -unsigned long long Telemetry::Keyword() const { +uint64_t Telemetry::Keyword() const { return 0; } diff --git a/onnxruntime/core/platform/telemetry.h b/onnxruntime/core/platform/telemetry.h index 7b2c24d3930ad..7b61de9d54073 100644 --- a/onnxruntime/core/platform/telemetry.h +++ b/onnxruntime/core/platform/telemetry.h @@ -44,7 +44,7 @@ class Telemetry { virtual unsigned char Level() const; // Get the current keyword - virtual unsigned long long Keyword() const; + virtual uint64_t Keyword() const; virtual void LogProcessInfo() const; diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.cc b/onnxruntime/core/platform/windows/logging/etw_sink.cc index c2e853b0c9c00..d2f21978df41f 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.cc +++ b/onnxruntime/core/platform/windows/logging/etw_sink.cc @@ -145,7 +145,9 @@ void EtwRegistrationManager::LazyInitialize() { } } -void EtwRegistrationManager::InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext) { +void EtwRegistrationManager::InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, + ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, + PVOID CallbackContext) { std::lock_guard lock(callbacks_mutex_); for (const auto& callback : callbacks_) { callback(SourceId, IsEnabled, Level, MatchAnyKeyword, MatchAllKeyword, FilterData, CallbackContext); @@ -176,13 +178,13 @@ void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, // TraceLoggingWrite requires (painfully) a compile time constant for the TraceLoggingLevel, // forcing us to use an ugly macro for the call. #define ETW_EVENT_NAME "ONNXRuntimeLogEvent" -#define TRACE_LOG_WRITE(level) \ - TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Logs)), \ - TraceLoggingLevel(level), \ - TraceLoggingString(logger_id.c_str(), "logger"), \ - TraceLoggingString(message.Category(), "category"), \ - TraceLoggingString(message.Location().ToString().c_str(), "location"), \ +#define TRACE_LOG_WRITE(level) \ + TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Logs)), \ + TraceLoggingLevel(level), \ + TraceLoggingString(logger_id.c_str(), "logger"), \ + TraceLoggingString(message.Category(), "category"), \ + TraceLoggingString(message.Location().ToString().c_str(), "location"), \ TraceLoggingString(message.Message().c_str(), "message")) const auto severity{message.Severity()}; diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index e54767b647e7e..4744bcde22465 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.h +++ b/onnxruntime/core/platform/windows/logging/etw_sink.h @@ -62,7 +62,7 @@ class EtwRegistrationManager { Severity MapLevelToSeverity(); // Get the current keyword - ULONGLONG Keyword() const; + uint64_t Keyword() const; // Get the ETW registration status HRESULT Status() const; diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index ed65d23c8cbae..500cb14d6b629 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -62,7 +62,7 @@ uint32_t WindowsTelemetry::global_register_count_ = 0; bool WindowsTelemetry::enabled_ = true; uint32_t WindowsTelemetry::projection_ = 0; UCHAR WindowsTelemetry::level_ = 0; -ULONGLONG WindowsTelemetry::keyword_ = 0; +UINT64 WindowsTelemetry::keyword_ = 0; WindowsTelemetry::WindowsTelemetry() { std::lock_guard lock(mutex_); @@ -95,7 +95,7 @@ UCHAR WindowsTelemetry::Level() const { return level_; } -ULONGLONG WindowsTelemetry::Keyword() const { +UINT64 WindowsTelemetry::Keyword() const { std::lock_guard lock(provider_change_mutex_); return keyword_; } @@ -244,7 +244,7 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage), TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), // Telemetry info TraceLoggingUInt8(0, "schemaVersion"), diff --git a/onnxruntime/core/platform/windows/telemetry.h b/onnxruntime/core/platform/windows/telemetry.h index 526971ebd0f7c..c3798943d491d 100644 --- a/onnxruntime/core/platform/windows/telemetry.h +++ b/onnxruntime/core/platform/windows/telemetry.h @@ -30,7 +30,7 @@ class WindowsTelemetry : public Telemetry { unsigned char Level() const override; // Get the current keyword - unsigned long long Keyword() const override; + UINT64 Keyword() const override; // Get the ETW registration status // static HRESULT Status(); diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index 0709814275c2c..d4563718a2551 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -19,8 +19,8 @@ #include "core/providers/qnn/builder/onnx_ctx_model_helper.h" #ifdef _WIN32 +#include #include "core/platform/tracing.h" -#include "winmeta.h" #endif // Flag to determine if Backend should do node validation for each opNode added @@ -943,6 +943,10 @@ Status QnnBackendManager::ExtractProfilingEventBasic( std::string message = GetEventTypeString(event_data.type); std::string unit = GetUnitString(event_data.unit); +#ifndef _WIN32 + tracelogging_provider_ep_enabled = false; +#endif + if (!tracelogging_provider_ep_enabled) { outfile << "UNKNOWN" << "," @@ -1013,10 +1017,11 @@ void QnnBackendManager::LogQnnProfileEventAsTraceLogging( const std::string& timingSource, const std::string& eventLevel, const char* eventIdentifier) { +#ifdef _WIN32 TraceLoggingWrite( telemetry_provider_handle, "QNNProfilingEvent", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Profiling)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Profiling)), TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), TraceLoggingValue(timestamp, "Timestamp"), TraceLoggingString(message.c_str(), "Message"), @@ -1025,6 +1030,7 @@ void QnnBackendManager::LogQnnProfileEventAsTraceLogging( TraceLoggingString(timingSource.c_str(), "Timing Source"), TraceLoggingString(eventLevel.c_str(), "Event Level"), TraceLoggingString(eventIdentifier, "Event Identifier")); +#endif } const std::string& QnnBackendManager::GetUnitString(QnnProfile_EventUnit_t unitType) { diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 86136315418ac..4a06c8e61a192 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -479,7 +479,7 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options #ifdef _WIN32 TraceLoggingWrite(telemetry_provider_handle, "SessionOptions", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingUInt8(static_cast(session_options.execution_mode), "execution_mode"), TraceLoggingUInt8(static_cast(session_options.execution_order), "execution_order"), @@ -501,7 +501,7 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingWrite( telemetry_provider_handle, "SessionOptions_IntraOrtThreadPoolParams", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingInt32(session_options.intra_op_param.thread_pool_size, "thread_pool_size"), TraceLoggingBoolean(session_options.intra_op_param.auto_set_affinity, "auto_set_affinity"), @@ -515,7 +515,7 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingWrite( telemetry_provider_handle, "SessionOptions_ConfigEntry", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(config_pair.first.c_str(), "Key"), TraceLoggingString(config_pair.second.c_str(), "Value")); diff --git a/onnxruntime/core/session/provider_registration.cc b/onnxruntime/core/session/provider_registration.cc index 49c24dcd6b3a6..900629fedd702 100644 --- a/onnxruntime/core/session/provider_registration.cc +++ b/onnxruntime/core/session/provider_registration.cc @@ -77,7 +77,7 @@ ORT_API_STATUS_IMPL(OrtApis::SessionOptionsAppendExecutionProvider, TraceLoggingWrite( telemetry_provider_handle, "ProviderOptionsAppendExecutionProvider", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(provider_name, "ProviderName"), TraceLoggingString(config_pair.first.c_str(), "Key"), diff --git a/onnxruntime/test/platform/windows/logging/HowToValidateEtwSinkOutput.md b/onnxruntime/test/platform/windows/logging/HowToValidateEtwSinkOutput.md index 6048fffa558f8..59fe946b929f2 100644 --- a/onnxruntime/test/platform/windows/logging/HowToValidateEtwSinkOutput.md +++ b/onnxruntime/test/platform/windows/logging/HowToValidateEtwSinkOutput.md @@ -5,7 +5,7 @@ The ETW Sink (ONNXRuntimeTraceLoggingProvider) allows ONNX semi-structured print ETW makes it easy and useful to only enable and listen for events with great performance, and when you need them instead of only at compile time. Therefore ONNX will preserve any existing loggers and log severity [provided at compile time](docs/FAQ.md?plain=1#L7). -However, when the provider is enabled a new ETW logger sink will also be added and the severity seperately controlled via ETW dynamically. +However, when the provider is enabled a new ETW logger sink will also be added and the severity separately controlled via ETW dynamically. - Provider GUID: 929DD115-1ECB-4CB5-B060-EBD4983C421D - Keyword: Logs (0x2) keyword per [logging.h](include\onnxruntime\core\common\logging\logging.h) From e083dcc6cc6292636c523da6574eb74487df913e Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Wed, 20 Dec 2023 12:05:54 -0800 Subject: [PATCH 16/22] Lintrunner --- .../core/platform/windows/logging/etw_sink.cc | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.cc b/onnxruntime/core/platform/windows/logging/etw_sink.cc index d2f21978df41f..fe2f285f7fc95 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.cc +++ b/onnxruntime/core/platform/windows/logging/etw_sink.cc @@ -178,13 +178,13 @@ void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, // TraceLoggingWrite requires (painfully) a compile time constant for the TraceLoggingLevel, // forcing us to use an ugly macro for the call. #define ETW_EVENT_NAME "ONNXRuntimeLogEvent" -#define TRACE_LOG_WRITE(level) \ - TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ +#define TRACE_LOG_WRITE(level) \ + TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Logs)), \ - TraceLoggingLevel(level), \ - TraceLoggingString(logger_id.c_str(), "logger"), \ - TraceLoggingString(message.Category(), "category"), \ - TraceLoggingString(message.Location().ToString().c_str(), "location"), \ + TraceLoggingLevel(level), \ + TraceLoggingString(logger_id.c_str(), "logger"), \ + TraceLoggingString(message.Category(), "category"), \ + TraceLoggingString(message.Location().ToString().c_str(), "location"), \ TraceLoggingString(message.Message().c_str(), "message")) const auto severity{message.Severity()}; From e757042fd0f3bfdff271d1e7d5a930709e52530c Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Wed, 20 Dec 2023 12:56:06 -0800 Subject: [PATCH 17/22] More PR fixes lintcpp and Linux build --- onnxruntime/core/platform/windows/logging/etw_sink.h | 9 ++++++--- onnxruntime/core/platform/windows/telemetry.cc | 4 ++-- .../providers/qnn/builder/qnn_backend_manager.cc | 12 +++++++----- onnxruntime/core/session/provider_registration.cc | 2 +- 4 files changed, 16 insertions(+), 11 deletions(-) diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index 4744bcde22465..722870864f5a7 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.h +++ b/onnxruntime/core/platform/windows/logging/etw_sink.h @@ -20,7 +20,7 @@ #include #include #include -#include +#include #include "core/common/logging/capture.h" #include "core/common/logging/isink.h" @@ -48,7 +48,9 @@ class EtwSink : public ISink { class EtwRegistrationManager { public: - using EtwInternalCallback = std::function; + using EtwInternalCallback = std::function; // Singleton instance access static EtwRegistrationManager& Instance(); @@ -80,7 +82,8 @@ class EtwRegistrationManager { EtwRegistrationManager(EtwRegistrationManager&&) = delete; EtwRegistrationManager& operator=(EtwRegistrationManager&&) = delete; - void InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext); + void InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, + ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext); static void NTAPI ORT_TL_EtwEnableCallback( _In_ LPCGUID SourceId, diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index 500cb14d6b629..b6549207124b4 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -17,7 +17,7 @@ #include #include -#include "winmeta.h" +#include // Seems this workaround can be dropped when we drop support for VS2017 toolchains // https://developercommunity.visualstudio.com/content/problem/85934/traceloggingproviderh-is-incompatible-with-utf-8.html @@ -179,7 +179,7 @@ void WindowsTelemetry::LogEvaluationStop() const { return; TraceLoggingWrite(telemetry_provider_handle, - "EvaluationStop", ); + "EvaluationStop"); } void WindowsTelemetry::LogEvaluationStart() const { diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index d4563718a2551..73786c048bd64 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -853,7 +853,7 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() { auto& provider = env.GetTelemetryProvider(); if (provider.IsEnabled()) { auto keyword = provider.Keyword(); - if ((keyword & static_cast(onnxruntime::logging::TLKeyword::Profiling)) != 0) { + if ((keyword & static_cast(onnxruntime::logging::TLKeyword::Profiling)) != 0) { tracelogging_provider_ep_enabled = true; } } @@ -875,9 +875,11 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() { for (size_t event_idx = 0; event_idx < num_events; event_idx++) { ORT_RETURN_IF_ERROR( - ExtractProfilingEvent(*(profile_events + event_idx), "ROOT", outfile, backendSupportsExtendedEventData, tracelogging_provider_ep_enabled)); + ExtractProfilingEvent(*(profile_events + event_idx), "ROOT", outfile, backendSupportsExtendedEventData, + tracelogging_provider_ep_enabled)); ORT_RETURN_IF_ERROR( - ExtractProfilingSubEvents(*(profile_events + event_idx), outfile, backendSupportsExtendedEventData, tracelogging_provider_ep_enabled)); + ExtractProfilingSubEvents(*(profile_events + event_idx), outfile, backendSupportsExtendedEventData, + tracelogging_provider_ep_enabled)); } if (!tracelogging_provider_ep_enabled) { @@ -996,6 +998,7 @@ Status QnnBackendManager::ExtractProfilingEventExtended( << (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL") << "\n"; } } else { +#ifdef _WIN32 LogQnnProfileEventAsTraceLogging( event_data_extended.v1.timestamp, message, @@ -1004,6 +1007,7 @@ Status QnnBackendManager::ExtractProfilingEventExtended( "BACKEND", eventLevel, (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL")); +#endif } return Status::OK(); @@ -1017,7 +1021,6 @@ void QnnBackendManager::LogQnnProfileEventAsTraceLogging( const std::string& timingSource, const std::string& eventLevel, const char* eventIdentifier) { -#ifdef _WIN32 TraceLoggingWrite( telemetry_provider_handle, "QNNProfilingEvent", @@ -1030,7 +1033,6 @@ void QnnBackendManager::LogQnnProfileEventAsTraceLogging( TraceLoggingString(timingSource.c_str(), "Timing Source"), TraceLoggingString(eventLevel.c_str(), "Event Level"), TraceLoggingString(eventIdentifier, "Event Identifier")); -#endif } const std::string& QnnBackendManager::GetUnitString(QnnProfile_EventUnit_t unitType) { diff --git a/onnxruntime/core/session/provider_registration.cc b/onnxruntime/core/session/provider_registration.cc index 900629fedd702..d4f5cd02edbd4 100644 --- a/onnxruntime/core/session/provider_registration.cc +++ b/onnxruntime/core/session/provider_registration.cc @@ -14,8 +14,8 @@ #include "core/providers/openvino/openvino_provider_factory_creator.h" #ifdef _WIN32 +#include #include "core/platform/tracing.h" -#include "winmeta.h" #endif #if defined(USE_DML) From dc2fb4d5a669122217a8c713fcc02a4fac8e2b02 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Wed, 20 Dec 2023 13:52:13 -0800 Subject: [PATCH 18/22] More PR fixes for lintcpp and Linux build --- .../onnxruntime/core/common/logging/logging.h | 2 +- .../qnn/builder/qnn_backend_manager.cc | 14 +++++++++++-- .../qnn/builder/qnn_backend_manager.h | 20 +++++++++++++++---- .../providers/qnn/qnn_execution_provider.cc | 5 +++-- onnxruntime/core/session/ort_env.cc | 3 ++- 5 files changed, 34 insertions(+), 10 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index b67fb5a84e831..d14658e28fab3 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -75,7 +75,7 @@ struct Category { // TODO: What other high level categories are meaningful? Model? Optimizer? Execution? }; -enum class TLKeyword : unsigned long long { +enum class TLKeyword : uint64_t { Session = 0x1, Logs = 0x2, Reserved1 = 0x4, diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index 73786c048bd64..d13f8c8b150a9 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -908,9 +908,11 @@ Status QnnBackendManager::ExtractProfilingSubEvents( for (size_t sub_event_idx = 0; sub_event_idx < num_sub_events; sub_event_idx++) { ORT_RETURN_IF_ERROR( - ExtractProfilingEvent(*(profile_sub_events + sub_event_idx), "SUB-EVENT", outfile, useExtendedEventData, tracelogging_provider_ep_enabled)); + ExtractProfilingEvent(*(profile_sub_events + sub_event_idx), "SUB-EVENT", outfile, useExtendedEventData, + tracelogging_provider_ep_enabled)); ORT_RETURN_IF_ERROR( - ExtractProfilingSubEvents(*(profile_sub_events + sub_event_idx), outfile, useExtendedEventData, tracelogging_provider_ep_enabled)); + ExtractProfilingSubEvents(*(profile_sub_events + sub_event_idx), outfile, useExtendedEventData, + tracelogging_provider_ep_enabled)); } LOGS(*logger_, VERBOSE) << "Wrote QNN profiling sub events (" << num_sub_events << ")"; @@ -960,6 +962,7 @@ Status QnnBackendManager::ExtractProfilingEventBasic( << eventLevel << "," << (event_data.identifier ? event_data.identifier : "NULL") << "\n"; } else { +#ifdef _WIN32 LogQnnProfileEventAsTraceLogging( (uint64_t)0, message, @@ -968,6 +971,7 @@ Status QnnBackendManager::ExtractProfilingEventBasic( "BACKEND", eventLevel, (event_data.identifier ? event_data.identifier : "NULL")); +#endif } return Status::OK(); @@ -986,6 +990,10 @@ Status QnnBackendManager::ExtractProfilingEventExtended( std::string message = GetEventTypeString(event_data_extended.v1.type); std::string unit = GetUnitString(event_data_extended.v1.unit); +#ifndef _WIN32 + tracelogging_provider_ep_enabled = false; +#endif + if (!tracelogging_provider_ep_enabled) { if (event_data_extended.version == QNN_PROFILE_DATA_VERSION_1) { outfile << event_data_extended.v1.timestamp << "," @@ -1013,6 +1021,7 @@ Status QnnBackendManager::ExtractProfilingEventExtended( return Status::OK(); } +#ifdef _WIN32 void QnnBackendManager::LogQnnProfileEventAsTraceLogging( uint64_t timestamp, const std::string& message, @@ -1034,6 +1043,7 @@ void QnnBackendManager::LogQnnProfileEventAsTraceLogging( TraceLoggingString(eventLevel.c_str(), "Event Level"), TraceLoggingString(eventIdentifier, "Event Identifier")); } +#endif const std::string& QnnBackendManager::GetUnitString(QnnProfile_EventUnit_t unitType) { const auto& unitStringMap = GetUnitStringMap(); diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h index ada3e8ff2dba6..58f207efb9e95 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h @@ -6,10 +6,15 @@ #include #include #include +#include #else #include #endif +#include +#include +#include +#include #include "HTP/QnnHtpDevice.h" #include "QnnLog.h" #include "System/QnnSystemInterface.h" @@ -117,8 +122,11 @@ class QnnBackendManager { void Split(std::vector& split_string, const std::string& tokenized_string, const char separator); Status ExtractBackendProfilingInfo(); - Status ExtractProfilingSubEvents(QnnProfile_EventId_t profile_event_id, std::ofstream& outfile, bool backendSupportsExtendedEventData, bool tracelogging_provider_ep_enabled); - Status ExtractProfilingEvent(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile, bool backendSupportsExtendedEventData, bool tracelogging_provider_ep_enabled); + Status ExtractProfilingSubEvents(QnnProfile_EventId_t profile_event_id, std::ofstream& outfile, + bool backendSupportsExtendedEventData, bool tracelogging_provider_ep_enabled); + Status ExtractProfilingEvent(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, + std::ofstream& outfile, bool backendSupportsExtendedEventData, + bool tracelogging_provider_ep_enabled); void SetQnnBackendType(uint32_t backend_id); QnnBackendType GetQnnBackendType() { return qnn_backend_type_; } @@ -175,13 +183,16 @@ class QnnBackendManager { return (backend_build_id == nullptr ? std::string("") : std::string(backend_build_id)); } - Status ExtractProfilingEventBasic(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile, bool tracelogging_provider_ep_enabled); - Status ExtractProfilingEventExtended(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, std::ofstream& outfile, bool tracelogging_provider_ep_enabled); + Status ExtractProfilingEventBasic(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, + std::ofstream& outfile, bool tracelogging_provider_ep_enabled); + Status ExtractProfilingEventExtended(QnnProfile_EventId_t profile_event_id, const std::string& eventLevel, + std::ofstream& outfile, bool tracelogging_provider_ep_enabled); static const std::string& GetUnitString(QnnProfile_EventUnit_t unitType); static const std::unordered_map& GetUnitStringMap(); static const std::string GetEventTypeString(QnnProfile_EventType_t eventType); static const std::string ExtractQnnScalarValue(const Qnn_Scalar_t& scalar); const char* QnnProfileErrorToString(QnnProfile_Error_t error); +#ifdef _WIN32 void LogQnnProfileEventAsTraceLogging( uint64_t timestamp, const std::string& message, @@ -190,6 +201,7 @@ class QnnBackendManager { const std::string& timingSource, const std::string& eventLevel, const char* eventIdentifier); +#endif private: const std::string backend_path_; diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index a2abcf500a360..9d3faf6afd095 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -152,13 +152,14 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio if (provider.IsEnabled()) { auto level = provider.Level(); auto keyword = provider.Keyword(); - if ((keyword & static_cast(onnxruntime::logging::TLKeyword::Profiling)) != 0) { + if ((keyword & static_cast(onnxruntime::logging::TLKeyword::Profiling)) != 0) { if (level != 0) { if (level == 5) { LOGS_DEFAULT(INFO) << "Overriding profiling to basic based on ETW level: " << static_cast(level); ParseProfilingLevel("basic", profiling_level); } else if (level < 5) { - LOGS_DEFAULT(INFO) << "QNN Profiler ETW level not supported below level 5. Level: " << static_cast(level); + LOGS_DEFAULT(INFO) << "QNN Profiler ETW level not supported below level 5. Level: " + << static_cast(level); } else { LOGS_DEFAULT(INFO) << "Overriding profiling to detailed based on ETW level: " << static_cast(level); ParseProfilingLevel("detailed", profiling_level); diff --git a/onnxruntime/core/session/ort_env.cc b/onnxruntime/core/session/ort_env.cc index 78d476e460b7f..331f1db26a029 100644 --- a/onnxruntime/core/session/ort_env.cc +++ b/onnxruntime/core/session/ort_env.cc @@ -48,7 +48,8 @@ OrtEnv* OrtEnv::GetInstance(const OrtEnv::LoggingManagerConstructionInfo& lm_inf sink = MakePlatformDefaultLogSink(); } auto etwOverrideSeverity = logging::OverrideLevelWithEtw(static_cast(lm_info.default_warning_level)); - sink = EnhanceLoggerWithEtw(std::move(sink), static_cast(lm_info.default_warning_level), etwOverrideSeverity); + sink = EnhanceLoggerWithEtw(std::move(sink), static_cast(lm_info.default_warning_level), + etwOverrideSeverity); lmgr = std::make_unique(std::move(sink), std::min(static_cast(lm_info.default_warning_level), etwOverrideSeverity), false, From b0701341ba4059de04c97a391aaf53cd86c02f12 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Mon, 8 Jan 2024 13:45:25 -0800 Subject: [PATCH 19/22] Small changes for PR comments --- include/onnxruntime/core/common/logging/logging.h | 7 ++++--- onnxruntime/core/platform/windows/logging/etw_sink.h | 6 +----- 2 files changed, 5 insertions(+), 8 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index d14658e28fab3..9a2c9383cba26 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -75,16 +75,17 @@ struct Category { // TODO: What other high level categories are meaningful? Model? Optimizer? Execution? }; +// TraceLogging keywords for categories of dynamic logging enablement enum class TLKeyword : uint64_t { - Session = 0x1, - Logs = 0x2, + Session = 0x1, // ORT Session TraceLoggingWrite + Logs = 0x2, // LOGS() Macro ORT logs. Pair with an appropiate level depending on detail required Reserved1 = 0x4, Reserved2 = 0x8, Reserved3 = 0x10, Reserved4 = 0x20, Reserved5 = 0x40, Reserved6 = 0x80, - Profiling = 0x100 + Profiling = 0x100 // Enables profiling. At higher levels >5 can impact inference performance }; class ISink; diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index 722870864f5a7..143c3fcfdfc52 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.h +++ b/onnxruntime/core/platform/windows/logging/etw_sink.h @@ -76,11 +76,7 @@ class EtwRegistrationManager { ~EtwRegistrationManager(); void LazyInitialize(); - // Copy and move constructors/operators are disabled - EtwRegistrationManager(const EtwRegistrationManager&) = delete; - EtwRegistrationManager& operator=(const EtwRegistrationManager&) = delete; - EtwRegistrationManager(EtwRegistrationManager&&) = delete; - EtwRegistrationManager& operator=(EtwRegistrationManager&&) = delete; + ORT_DISALLOW_COPY_ASSIGNMENT_AND_MOVE(EtwRegistrationManager); void InvokeCallbacks(LPCGUID SourceId, ULONG IsEnabled, UCHAR Level, ULONGLONG MatchAnyKeyword, ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext); From 80f08b5c09dbcd4502d80157a7fc67b73e9ea564 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Mon, 8 Jan 2024 14:27:57 -0800 Subject: [PATCH 20/22] Lintrunner strikes again --- include/onnxruntime/core/common/logging/logging.h | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index 9a2c9383cba26..33ec0259facf5 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -77,15 +77,15 @@ struct Category { // TraceLogging keywords for categories of dynamic logging enablement enum class TLKeyword : uint64_t { - Session = 0x1, // ORT Session TraceLoggingWrite - Logs = 0x2, // LOGS() Macro ORT logs. Pair with an appropiate level depending on detail required + Session = 0x1, // ORT Session TraceLoggingWrite + Logs = 0x2, // LOGS() Macro ORT logs. Pair with an appropiate level depending on detail required Reserved1 = 0x4, Reserved2 = 0x8, Reserved3 = 0x10, Reserved4 = 0x20, Reserved5 = 0x40, Reserved6 = 0x80, - Profiling = 0x100 // Enables profiling. At higher levels >5 can impact inference performance + Profiling = 0x100 // Enables profiling. At higher levels >5 can impact inference performance }; class ISink; From be85e9d8fbff6e2736619deb75677e2be852dd7f Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Mon, 8 Jan 2024 15:50:54 -0800 Subject: [PATCH 21/22] Address PR comments with renames and comments --- include/onnxruntime/core/common/logging/logging.h | 12 +++++++----- onnxruntime/core/common/logging/logging.cc | 2 +- onnxruntime/core/framework/execution_providers.h | 2 +- onnxruntime/core/platform/telemetry.cc | 1 + .../core/platform/windows/logging/etw_sink.cc | 14 +++++++------- onnxruntime/core/platform/windows/telemetry.cc | 2 +- .../providers/qnn/builder/qnn_backend_manager.cc | 4 ++-- .../core/providers/qnn/qnn_execution_provider.cc | 2 +- onnxruntime/core/session/inference_session.cc | 6 +++--- onnxruntime/core/session/provider_registration.cc | 2 +- 10 files changed, 25 insertions(+), 22 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index 33ec0259facf5..e8d888f31665c 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -75,11 +75,13 @@ struct Category { // TODO: What other high level categories are meaningful? Model? Optimizer? Execution? }; -// TraceLogging keywords for categories of dynamic logging enablement -enum class TLKeyword : uint64_t { - Session = 0x1, // ORT Session TraceLoggingWrite - Logs = 0x2, // LOGS() Macro ORT logs. Pair with an appropiate level depending on detail required - Reserved1 = 0x4, +/// +/// TraceLogging keywords for categories of dynamic logging enablement +/// +enum class TraceLoggingKeyword : uint64_t { + Session = 0x1, // ORT Session TraceLoggingWrite + Logs = 0x2, // LOGS() Macro ORT logs. Pair with an appropiate level depending on detail required + Reserved1 = 0x4, // Reserved if we want to add some specific sub-categories instead of just LOGS() or other uses Reserved2 = 0x8, Reserved3 = 0x10, Reserved4 = 0x20, diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 982040e44c245..c7ca157c3c3a7 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -268,7 +268,7 @@ std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogge Severity OverrideLevelWithEtw(Severity originalSeverity) { #ifdef _WIN32 auto& manager = logging::EtwRegistrationManager::Instance(); - if (manager.IsEnabled() && (manager.Keyword() & static_cast(onnxruntime::logging::TLKeyword::Logs)) != 0) { + if (manager.IsEnabled() && (manager.Keyword() & static_cast(onnxruntime::logging::TraceLoggingKeyword::Logs)) != 0) { return manager.MapLevelToSeverity(); } #endif // _WIN32 diff --git a/onnxruntime/core/framework/execution_providers.h b/onnxruntime/core/framework/execution_providers.h index 38e1790808456..500055ea903d5 100644 --- a/onnxruntime/core/framework/execution_providers.h +++ b/onnxruntime/core/framework/execution_providers.h @@ -48,7 +48,7 @@ class ExecutionProviders { TraceLoggingWrite( telemetry_provider_handle, "ProviderOptions", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(provider_id.c_str(), "ProviderId"), TraceLoggingString(config_pair.first.c_str(), "Key"), diff --git a/onnxruntime/core/platform/telemetry.cc b/onnxruntime/core/platform/telemetry.cc index 8dcdae21a36d6..dc3b011cc7968 100644 --- a/onnxruntime/core/platform/telemetry.cc +++ b/onnxruntime/core/platform/telemetry.cc @@ -17,6 +17,7 @@ bool Telemetry::IsEnabled() const { } // Get the current logging level +// The Level defined as uchar is coming from the ETW Enable callback in TraceLoggingRegisterEx. unsigned char Telemetry::Level() const { return 0; } diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.cc b/onnxruntime/core/platform/windows/logging/etw_sink.cc index fe2f285f7fc95..9b4cbd1628a55 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.cc +++ b/onnxruntime/core/platform/windows/logging/etw_sink.cc @@ -178,13 +178,13 @@ void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, // TraceLoggingWrite requires (painfully) a compile time constant for the TraceLoggingLevel, // forcing us to use an ugly macro for the call. #define ETW_EVENT_NAME "ONNXRuntimeLogEvent" -#define TRACE_LOG_WRITE(level) \ - TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Logs)), \ - TraceLoggingLevel(level), \ - TraceLoggingString(logger_id.c_str(), "logger"), \ - TraceLoggingString(message.Category(), "category"), \ - TraceLoggingString(message.Location().ToString().c_str(), "location"), \ +#define TRACE_LOG_WRITE(level) \ + TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ + TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Logs)), \ + TraceLoggingLevel(level), \ + TraceLoggingString(logger_id.c_str(), "logger"), \ + TraceLoggingString(message.Category(), "category"), \ + TraceLoggingString(message.Location().ToString().c_str(), "location"), \ TraceLoggingString(message.Message().c_str(), "message")) const auto severity{message.Severity()}; diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index b6549207124b4..a70b24d50e943 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -244,7 +244,7 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage), TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), // Telemetry info TraceLoggingUInt8(0, "schemaVersion"), diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index d13f8c8b150a9..f7c429a91c69c 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -853,7 +853,7 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() { auto& provider = env.GetTelemetryProvider(); if (provider.IsEnabled()) { auto keyword = provider.Keyword(); - if ((keyword & static_cast(onnxruntime::logging::TLKeyword::Profiling)) != 0) { + if ((keyword & static_cast(onnxruntime::logging::TraceLoggingKeyword::Profiling)) != 0) { tracelogging_provider_ep_enabled = true; } } @@ -1033,7 +1033,7 @@ void QnnBackendManager::LogQnnProfileEventAsTraceLogging( TraceLoggingWrite( telemetry_provider_handle, "QNNProfilingEvent", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Profiling)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Profiling)), TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), TraceLoggingValue(timestamp, "Timestamp"), TraceLoggingString(message.c_str(), "Message"), diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index 9d3faf6afd095..ef612d22f6b09 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -152,7 +152,7 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio if (provider.IsEnabled()) { auto level = provider.Level(); auto keyword = provider.Keyword(); - if ((keyword & static_cast(onnxruntime::logging::TLKeyword::Profiling)) != 0) { + if ((keyword & static_cast(onnxruntime::logging::TraceLoggingKeyword::Profiling)) != 0) { if (level != 0) { if (level == 5) { LOGS_DEFAULT(INFO) << "Overriding profiling to basic based on ETW level: " << static_cast(level); diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 4a06c8e61a192..b4671ddd0713b 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -479,7 +479,7 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options #ifdef _WIN32 TraceLoggingWrite(telemetry_provider_handle, "SessionOptions", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingUInt8(static_cast(session_options.execution_mode), "execution_mode"), TraceLoggingUInt8(static_cast(session_options.execution_order), "execution_order"), @@ -501,7 +501,7 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingWrite( telemetry_provider_handle, "SessionOptions_IntraOrtThreadPoolParams", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingInt32(session_options.intra_op_param.thread_pool_size, "thread_pool_size"), TraceLoggingBoolean(session_options.intra_op_param.auto_set_affinity, "auto_set_affinity"), @@ -515,7 +515,7 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingWrite( telemetry_provider_handle, "SessionOptions_ConfigEntry", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(config_pair.first.c_str(), "Key"), TraceLoggingString(config_pair.second.c_str(), "Value")); diff --git a/onnxruntime/core/session/provider_registration.cc b/onnxruntime/core/session/provider_registration.cc index d4f5cd02edbd4..73c646f1186ef 100644 --- a/onnxruntime/core/session/provider_registration.cc +++ b/onnxruntime/core/session/provider_registration.cc @@ -77,7 +77,7 @@ ORT_API_STATUS_IMPL(OrtApis::SessionOptionsAppendExecutionProvider, TraceLoggingWrite( telemetry_provider_handle, "ProviderOptionsAppendExecutionProvider", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TLKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(provider_name, "ProviderName"), TraceLoggingString(config_pair.first.c_str(), "Key"), From 7e387c65089d05ec68455c1db04c5453dbba1cca Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Mon, 8 Jan 2024 19:43:36 -0800 Subject: [PATCH 22/22] Rename ORTTraceLoggingKeyword and more lint NITs --- include/onnxruntime/core/common/logging/logging.h | 6 +++--- onnxruntime/core/common/logging/logging.cc | 3 ++- onnxruntime/core/framework/execution_providers.h | 2 +- .../core/platform/windows/logging/etw_sink.cc | 14 +++++++------- onnxruntime/core/platform/windows/telemetry.cc | 2 +- .../providers/qnn/builder/qnn_backend_manager.cc | 4 ++-- .../core/providers/qnn/qnn_execution_provider.cc | 2 +- onnxruntime/core/session/inference_session.cc | 6 +++--- onnxruntime/core/session/provider_registration.cc | 2 +- 9 files changed, 21 insertions(+), 20 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index e8d888f31665c..2b9912ea77389 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -76,11 +76,11 @@ struct Category { }; /// -/// TraceLogging keywords for categories of dynamic logging enablement +/// ORT TraceLogging keywords for categories of dynamic logging enablement /// -enum class TraceLoggingKeyword : uint64_t { +enum class ORTTraceLoggingKeyword : uint64_t { Session = 0x1, // ORT Session TraceLoggingWrite - Logs = 0x2, // LOGS() Macro ORT logs. Pair with an appropiate level depending on detail required + Logs = 0x2, // LOGS() Macro ORT logs. Pair with an appropriate level depending on detail required Reserved1 = 0x4, // Reserved if we want to add some specific sub-categories instead of just LOGS() or other uses Reserved2 = 0x8, Reserved3 = 0x10, diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index c7ca157c3c3a7..eac9a7fa08081 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -268,7 +268,8 @@ std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogge Severity OverrideLevelWithEtw(Severity originalSeverity) { #ifdef _WIN32 auto& manager = logging::EtwRegistrationManager::Instance(); - if (manager.IsEnabled() && (manager.Keyword() & static_cast(onnxruntime::logging::TraceLoggingKeyword::Logs)) != 0) { + if (manager.IsEnabled() && + (manager.Keyword() & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0) { return manager.MapLevelToSeverity(); } #endif // _WIN32 diff --git a/onnxruntime/core/framework/execution_providers.h b/onnxruntime/core/framework/execution_providers.h index 500055ea903d5..61147e4367876 100644 --- a/onnxruntime/core/framework/execution_providers.h +++ b/onnxruntime/core/framework/execution_providers.h @@ -48,7 +48,7 @@ class ExecutionProviders { TraceLoggingWrite( telemetry_provider_handle, "ProviderOptions", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(provider_id.c_str(), "ProviderId"), TraceLoggingString(config_pair.first.c_str(), "Key"), diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.cc b/onnxruntime/core/platform/windows/logging/etw_sink.cc index 9b4cbd1628a55..5fb7f7a65161d 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.cc +++ b/onnxruntime/core/platform/windows/logging/etw_sink.cc @@ -178,13 +178,13 @@ void EtwSink::SendImpl(const Timestamp& timestamp, const std::string& logger_id, // TraceLoggingWrite requires (painfully) a compile time constant for the TraceLoggingLevel, // forcing us to use an ugly macro for the call. #define ETW_EVENT_NAME "ONNXRuntimeLogEvent" -#define TRACE_LOG_WRITE(level) \ - TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ - TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Logs)), \ - TraceLoggingLevel(level), \ - TraceLoggingString(logger_id.c_str(), "logger"), \ - TraceLoggingString(message.Category(), "category"), \ - TraceLoggingString(message.Location().ToString().c_str(), "location"), \ +#define TRACE_LOG_WRITE(level) \ + TraceLoggingWrite(etw_provider_handle, ETW_EVENT_NAME, \ + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)), \ + TraceLoggingLevel(level), \ + TraceLoggingString(logger_id.c_str(), "logger"), \ + TraceLoggingString(message.Category(), "category"), \ + TraceLoggingString(message.Location().ToString().c_str(), "location"), \ TraceLoggingString(message.Message().c_str(), "message")) const auto severity{message.Severity()}; diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index a70b24d50e943..a9849873fd060 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -244,7 +244,7 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage), TraceLoggingKeyword(MICROSOFT_KEYWORD_MEASURES), - TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), // Telemetry info TraceLoggingUInt8(0, "schemaVersion"), diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index f7c429a91c69c..ca6a2238e520d 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -853,7 +853,7 @@ Status QnnBackendManager::ExtractBackendProfilingInfo() { auto& provider = env.GetTelemetryProvider(); if (provider.IsEnabled()) { auto keyword = provider.Keyword(); - if ((keyword & static_cast(onnxruntime::logging::TraceLoggingKeyword::Profiling)) != 0) { + if ((keyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Profiling)) != 0) { tracelogging_provider_ep_enabled = true; } } @@ -1033,7 +1033,7 @@ void QnnBackendManager::LogQnnProfileEventAsTraceLogging( TraceLoggingWrite( telemetry_provider_handle, "QNNProfilingEvent", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Profiling)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Profiling)), TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), TraceLoggingValue(timestamp, "Timestamp"), TraceLoggingString(message.c_str(), "Message"), diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index ef612d22f6b09..e5856e85e19e8 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -152,7 +152,7 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio if (provider.IsEnabled()) { auto level = provider.Level(); auto keyword = provider.Keyword(); - if ((keyword & static_cast(onnxruntime::logging::TraceLoggingKeyword::Profiling)) != 0) { + if ((keyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Profiling)) != 0) { if (level != 0) { if (level == 5) { LOGS_DEFAULT(INFO) << "Overriding profiling to basic based on ETW level: " << static_cast(level); diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index b4671ddd0713b..93877c8dd66bd 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -479,7 +479,7 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options #ifdef _WIN32 TraceLoggingWrite(telemetry_provider_handle, "SessionOptions", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingUInt8(static_cast(session_options.execution_mode), "execution_mode"), TraceLoggingUInt8(static_cast(session_options.execution_order), "execution_order"), @@ -501,7 +501,7 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingWrite( telemetry_provider_handle, "SessionOptions_IntraOrtThreadPoolParams", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingInt32(session_options.intra_op_param.thread_pool_size, "thread_pool_size"), TraceLoggingBoolean(session_options.intra_op_param.auto_set_affinity, "auto_set_affinity"), @@ -515,7 +515,7 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingWrite( telemetry_provider_handle, "SessionOptions_ConfigEntry", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(config_pair.first.c_str(), "Key"), TraceLoggingString(config_pair.second.c_str(), "Value")); diff --git a/onnxruntime/core/session/provider_registration.cc b/onnxruntime/core/session/provider_registration.cc index 73c646f1186ef..b012406bd026a 100644 --- a/onnxruntime/core/session/provider_registration.cc +++ b/onnxruntime/core/session/provider_registration.cc @@ -77,7 +77,7 @@ ORT_API_STATUS_IMPL(OrtApis::SessionOptionsAppendExecutionProvider, TraceLoggingWrite( telemetry_provider_handle, "ProviderOptionsAppendExecutionProvider", - TraceLoggingKeyword(static_cast(onnxruntime::logging::TraceLoggingKeyword::Session)), + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Session)), TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(provider_name, "ProviderName"), TraceLoggingString(config_pair.first.c_str(), "Key"),