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" />