From 4d1243b4b4dd5ce9475a690cb270e7435f3e970b Mon Sep 17 00:00:00 2001 From: ivberg Date: Thu, 11 Jan 2024 12:43:27 -0800 Subject: [PATCH] ORT ETW dynamic logging that improves ORT diagnosability & performance (#18882) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ### Description This PR has several combined ORT ETW changes that improve ORT log diagnosability & performance.  - The existing log behavior in the ORT API and Severity behavior remain the same as compiled by the dev using the ORT API - The PR keeps the existing design which has 2 TraceLogging providers defined (although both were not used before this PR) - Keeps great inference (inf) and session load performance even with dynamic logging enabled (see below) - On Windows, when ONNXRuntimeTraceLoggingProvider is enabled, then ORT will dynamically _add_ a new sink reflecting the severity level provided by ETW dynamically. E.G Critical - Verbose per the need at runtime - This allows previous printf style LOGS() statements both for CPU and NPU cases to flow to ETW via a local trace (if enabled) - This DOES NOT add any new Telemetry which can optionally be sent to Microsoft. - Telemetry are ETW events marked with the Measure keyword that _can_ be sampled if a box opts-in - Existing Microsoft.ML.ONNXRuntime events have appropriate keywords and levels added if they were missing - If Execution Providers (EPs) can provide more detailed insight into their HW or component, then this PR allows for those to be dynamically logged instead of just at compile time - In this PR, the QNN EP for QC NPUs can have basic or detailed profiling enabled to give some insight into how the NPU is performing - When the Microsoft.ML.ONNXRuntime ETW provider is enabled with the Profiling keyword and level 5 then QC QNN basic profiling info is output to ETW ### Motivation and Context - This make ORT logging and diagnosability more performant (on Windows) and available in a wider variety of runtime environments. - The performance difference for inf times was ~300x+ drastically better/faster when these logs were output to ETW vs just stdout (Verbose Severity) - This style of ETW dynamic tracing is the widely used standard for Windows components, and even by some 3rd party software since the ETW API is open and part of the Windows API - These ETW based logs can be seamlessly combined with other ETW logs such as an AI component/feature using ORT, OS CPU profiling, scheduling, and more - Before the PR, ORT logging is largely printf style and output to a sink (usually stdout) only if compiled with a certain log Severity. When enabled the previous logging (to stdout) would vastly slow down inference times. Once compiled for release the internal ORT logs were not accessible by anyone except the AI model developer in their dev inner loop. That means logs could not be enabled on a lab machine, or on a production system where the runtime behavior or performance might be different for various reasons on a wide variety of HW. - This change was tested with performance in mind and tested with a mobilenet small AI model with onnxruntime_perf_test - CPU: There was no statistical difference for inf times with the baseline (main) or this PR whether ETW was enabled or not (both ORT providers all keywords level 5). - NPU (QNN on SP9 or Dev Kit 2023 QC SQ3): There was no statistical difference for inf times with this PR whether ETW (both ORT providers all keywords) were enabled or not for Level 5 (Verbose). This is even with QNN Basic profiling turned on and outputting NPU stats to ETW - As expected and designed, there was perf slowdown when Max Level 255 is enabled which translates to QNN Detailed profiling. This mirrors the expected slowdown in the NPU when individual model operations are monitored & recorded as well. This perf is similar to the QNN SDK Detailed profiling performance separate from this PR. This is designed to be above level 5 (verbose) as that is commonly the max level used in many trace profiles and won't affect inf performance. - Other OSes such as Linux & Android are left untouched for now. - Out of scope for this PR but TraceLogging is available for Linux with LTTng tracing. So in the future, this optional tracing could also be made available on other OSes where a TraceLogging API is available --- .../onnxruntime/core/common/logging/logging.h | 27 +++ onnxruntime/core/common/logging/logging.cc | 33 ++++ .../common/logging/sinks/composite_sink.h | 23 ++- .../core/framework/execution_providers.h | 3 + .../core/framework/sequential_executor.cc | 6 +- .../framework/stream_execution_context.cc | 2 +- onnxruntime/core/platform/telemetry.cc | 15 ++ onnxruntime/core/platform/telemetry.h | 8 + .../core/platform/windows/logging/etw_sink.cc | 128 +++++++++---- .../core/platform/windows/logging/etw_sink.h | 60 ++++++ .../core/platform/windows/telemetry.cc | 53 +++++- onnxruntime/core/platform/windows/telemetry.h | 26 +++ .../qnn/builder/qnn_backend_manager.cc | 171 +++++++++++++----- .../qnn/builder/qnn_backend_manager.h | 28 ++- .../providers/qnn/qnn_execution_provider.cc | 32 +++- onnxruntime/core/session/inference_session.cc | 26 ++- onnxruntime/core/session/ort_env.cc | 28 +-- .../core/session/provider_registration.cc | 4 + onnxruntime/test/common/logging/sinks_test.cc | 2 +- .../logging/HowToValidateEtwSinkOutput.md | 31 +++- .../platform/windows/logging/etw_sink_test.cc | 4 +- ort.wprp | 4 +- 22 files changed, 591 insertions(+), 123 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index bea3fa1d09cc2..2b9912ea77389 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -75,6 +75,21 @@ struct Category { // TODO: What other high level categories are meaningful? Model? Optimizer? Execution? }; +/// +/// ORT TraceLogging keywords for categories of dynamic logging enablement +/// +enum class ORTTraceLoggingKeyword : uint64_t { + Session = 0x1, // ORT Session TraceLoggingWrite + 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, + Reserved4 = 0x20, + Reserved5 = 0x40, + Reserved6 = 0x80, + Profiling = 0x100 // Enables profiling. At higher levels >5 can impact inference performance +}; + class ISink; class Logger; class Capture; @@ -333,5 +348,17 @@ unsigned int GetThreadId(); */ 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); + +/** + 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); + } // namespace logging } // namespace onnxruntime diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 6c6e2f48557ef..eac9a7fa08081 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,36 @@ 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 + (void)originalSeverity; + (void)etwSeverity; + return existingLogger; +#endif // _WIN32 +} + +Severity OverrideLevelWithEtw(Severity originalSeverity) { +#ifdef _WIN32 + auto& manager = logging::EtwRegistrationManager::Instance(); + if (manager.IsEnabled() && + (manager.Keyword() & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0) { + return manager.MapLevelToSeverity(); + } +#endif // _WIN32 + return originalSeverity; +} + } // 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..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" @@ -27,20 +29,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 and min severity for that sink + /// + /// 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/framework/execution_providers.h b/onnxruntime/core/framework/execution_providers.h index d97953fd9d5ea..61147e4367876 100644 --- a/onnxruntime/core/framework/execution_providers.h +++ b/onnxruntime/core/framework/execution_providers.h @@ -13,6 +13,7 @@ #include "core/graph/graph_viewer.h" #include "core/common/logging/logging.h" #ifdef _WIN32 +#include #include "core/platform/tracing.h" #endif @@ -47,6 +48,8 @@ class ExecutionProviders { TraceLoggingWrite( telemetry_provider_handle, "ProviderOptions", + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::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/framework/sequential_executor.cc b/onnxruntime/core/framework/sequential_executor.cc index ba68bc1d7d834..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(); - LOGS(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); - LOGS(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(); - LOGS(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 4ff5ee5db865d..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()); - LOGS(*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 a99261d1d1caa..dc3b011cc7968 100644 --- a/onnxruntime/core/platform/telemetry.cc +++ b/onnxruntime/core/platform/telemetry.cc @@ -12,6 +12,21 @@ 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 +// The Level defined as uchar is coming from the ETW Enable callback in TraceLoggingRegisterEx. +unsigned char Telemetry::Level() const { + return 0; +} + +// Get the current keyword +uint64_t 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..7b61de9d54073 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 uint64_t 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 396695e6c570c..5fb7f7a65161d 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.cc +++ b/onnxruntime/core/platform/windows/logging/etw_sink.cc @@ -58,42 +58,107 @@ 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)); - } +EtwRegistrationManager& EtwRegistrationManager::Instance() { + static EtwRegistrationManager instance; + instance.LazyInitialize(); + return instance; +} - // return an instance that is just used to unregister as the program exits - static EtwRegistrationManager instance(etw_status); - 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 { - return etw_status_; +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; } +} + +ULONGLONG EtwRegistrationManager::Keyword() const { + std::lock_guard lock(provider_change_mutex_); + return keyword_; +} - ~EtwRegistrationManager() { - ::TraceLoggingUnregister(etw_provider_handle); +HRESULT EtwRegistrationManager::Status() const { + return etw_status_; +} + +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() { +} - EtwRegistrationManager(const HRESULT status) noexcept : etw_status_{status} {} - const HRESULT etw_status_; -}; +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_)); + } + } + } +} + +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 +166,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; } @@ -114,11 +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, 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/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index 1e4f49a619302..143c3fcfdfc52 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,9 +20,11 @@ #include #include #include +#include #include "core/common/logging/capture.h" #include "core/common/logging/isink.h" +#include "core/platform/ort_mutex.h" namespace onnxruntime { namespace logging { @@ -41,6 +45,62 @@ 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 + uint64_t Keyword() const; + + // Get the ETW registration status + HRESULT Status() const; + + void RegisterInternalCallback(const EtwInternalCallback& callback); + + private: + EtwRegistrationManager(); + ~EtwRegistrationManager(); + void LazyInitialize(); + + 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); + + 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 } // namespace onnxruntime diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index ec49c2edc2125..a9849873fd060 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 // 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 @@ -55,15 +57,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; +UINT64 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 +85,44 @@ 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_; +} + +UINT64 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; } @@ -110,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"), @@ -126,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 { @@ -199,6 +244,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::ORTTraceLoggingKeyword::Session)), + TraceLoggingLevel(WINEVENT_LEVEL_INFO), // Telemetry info TraceLoggingUInt8(0, "schemaVersion"), TraceLoggingUInt32(session_id, "sessionId"), @@ -227,6 +274,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"), @@ -243,6 +291,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"), diff --git a/onnxruntime/core/platform/windows/telemetry.h b/onnxruntime/core/platform/windows/telemetry.h index 08e48214c85b3..c3798943d491d 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 + UINT64 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/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index 38d74909db86b..ca6a2238e520d 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -18,6 +18,11 @@ #include "core/common/logging/capture.h" #include "core/providers/qnn/builder/onnx_ctx_model_helper.h" +#ifdef _WIN32 +#include +#include "core/platform/tracing.h" +#endif + // Flag to determine if Backend should do node validation for each opNode added #define DO_GRAPH_NODE_VALIDATIONS 1 @@ -843,28 +848,46 @@ 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::ORTTraceLoggingKeyword::Profiling)) != 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_, VERBOSE) << "Wrote QNN profiling events (" << num_events << ") to qnn-profiling-data.csv"; + } else { + LOGS(*logger_, VERBOSE) << "Wrote QNN profiling events (" << num_events << ") to ETW"; + } } return Status::OK(); @@ -873,7 +896,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 +908,14 @@ 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_, VERBOSE) << "Wrote QNN profiling sub events (" << num_sub_events << ")"; } return Status::OK(); @@ -899,18 +925,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 +947,32 @@ 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"; +#ifndef _WIN32 + tracelogging_provider_ep_enabled = false; +#endif + + if (!tracelogging_provider_ep_enabled) { + outfile << "UNKNOWN" + << "," + << message << "," + << event_data.value << "," + << unit << "," + << "BACKEND" + << "," + << eventLevel << "," + << (event_data.identifier ? event_data.identifier : "NULL") << "\n"; + } else { +#ifdef _WIN32 + LogQnnProfileEventAsTraceLogging( + (uint64_t)0, + message, + std::to_string(event_data.value), + unit, + "BACKEND", + eventLevel, + (event_data.identifier ? event_data.identifier : "NULL")); +#endif + } return Status::OK(); } @@ -935,7 +980,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 +990,61 @@ 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"; +#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 << "," + << message << "," + << ExtractQnnScalarValue(event_data_extended.v1.value) << "," + << unit << "," + << "BACKEND" + << "," + << eventLevel << "," + << (event_data_extended.v1.identifier ? event_data_extended.v1.identifier : "NULL") << "\n"; + } + } else { +#ifdef _WIN32 + 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")); +#endif } return Status::OK(); } +#ifdef _WIN32 +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::ORTTraceLoggingKeyword::Profiling)), + TraceLoggingLevel(WINEVENT_LEVEL_VERBOSE), + 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")); +} +#endif + 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..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); - 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 +183,25 @@ 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); +#ifdef _WIN32 + 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); +#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 c72012fd4a19b..e5856e85e19e8 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" @@ -28,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") { @@ -146,9 +147,30 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio static const std::string PROFILING_LEVEL = "profiling_level"; qnn::ProfilingLevel profiling_level = qnn::ProfilingLevel::OFF; - 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); + 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::ORTTraceLoggingKeyword::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); + } else { + LOGS_DEFAULT(INFO) << "Overriding profiling to detailed based on ETW level: " << static_cast(level); + 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); + } } 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..93877c8dd66bd 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 { @@ -322,11 +328,17 @@ logging::Severity GetSeverity(const SessionOptions& session_options) { 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), - GetSeverity(session_options), + sink = std::make_unique(session_options.user_logging_function, + 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), + std::min(sessionSeverity, etwOverrideSeverity), false, logging::LoggingManager::InstanceType::Temporal, &session_options.session_logid); @@ -467,6 +479,8 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options #ifdef _WIN32 TraceLoggingWrite(telemetry_provider_handle, "SessionOptions", + 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"), TraceLoggingBoolean(session_options.enable_profiling, "enable_profiling"), @@ -487,6 +501,8 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingWrite( telemetry_provider_handle, "SessionOptions_IntraOrtThreadPoolParams", + 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"), TraceLoggingBoolean(session_options.intra_op_param.allow_spinning, "allow_spinning"), @@ -499,6 +515,8 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingWrite( telemetry_provider_handle, "SessionOptions_ConfigEntry", + 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/ort_env.cc b/onnxruntime/core/session/ort_env.cc index e3957baa990f8..331f1db26a029 100644 --- a/onnxruntime/core/session/ort_env.cc +++ b/onnxruntime/core/session/ort_env.cc @@ -39,23 +39,23 @@ 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(); } + 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), + std::min(static_cast(lm_info.default_warning_level), etwOverrideSeverity), + false, + LoggingManager::InstanceType::Default, + &name); + std::unique_ptr env; if (!tp_options) { status = onnxruntime::Environment::Create(std::move(lmgr), env); diff --git a/onnxruntime/core/session/provider_registration.cc b/onnxruntime/core/session/provider_registration.cc index 2e9af9f1f9bb2..b012406bd026a 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" @@ -13,6 +14,7 @@ #include "core/providers/openvino/openvino_provider_factory_creator.h" #ifdef _WIN32 +#include #include "core/platform/tracing.h" #endif @@ -75,6 +77,8 @@ ORT_API_STATUS_IMPL(OrtApis::SessionOptionsAppendExecutionProvider, TraceLoggingWrite( telemetry_provider_handle, "ProviderOptionsAppendExecutionProvider", + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Session)), + TraceLoggingLevel(WINEVENT_LEVEL_INFO), TraceLoggingString(provider_name, "ProviderName"), TraceLoggingString(config_pair.first.c_str(), "Key"), TraceLoggingString(config_pair.second.c_str(), "Value")); 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/HowToValidateEtwSinkOutput.md b/onnxruntime/test/platform/windows/logging/HowToValidateEtwSinkOutput.md index 2f8d06d66d576..59fe946b929f2 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 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) +- 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 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, 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" />