From f7efc747af58f6952064ad4caec8e6b588da8742 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Sat, 27 Apr 2024 00:00:50 -0700 Subject: [PATCH 01/12] Initial working version non-cleaned up and with missing functionality --- .../onnxruntime/core/common/logging/logging.h | 40 ++++++- onnxruntime/core/common/logging/logging.cc | 111 +++++++++++++++++- .../qnn/builder/qnn_backend_manager.cc | 83 ++++++++++++- .../qnn/builder/qnn_backend_manager.h | 2 + .../providers/qnn/qnn_execution_provider.cc | 36 ++++++ onnxruntime/core/session/inference_session.cc | 44 ++++++- onnxruntime/core/session/ort_env.cc | 2 +- 7 files changed, 302 insertions(+), 16 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index f62053a5e44ab..9fc903232c1ac 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -14,10 +14,9 @@ #include "core/common/common.h" #include "core/common/profiler_common.h" #include "core/common/logging/capture.h" -#include "core/common/logging/severity.h" - #include "core/common/logging/macros.h" - +#include "core/common/logging/severity.h" +#include "core/platform/ort_mutex.h" #include "date/date.h" /* @@ -167,6 +166,34 @@ class LoggingManager final { */ static bool HasDefaultLogger() { return nullptr != s_default_logger_; } + /** + Gets the default instance of the LoggingManager. + */ + static LoggingManager* GetDefaultInstance(); + +#ifdef _WIN32 + /** + Returns the current sink + */ + // std::shared_ptr GetCurrentSink() const; + + /** + Replace the current sink with a new one + */ + void UpdateSink(std::unique_ptr new_sink); + + /** + Removes the ETW Sink if one is present + */ + void RemoveEtwSink(); + + /** + Adds an ETW Sink to the current sink creating a CompositeSink if necessary + @param etwSeverity The severity level for the ETW Sink + */ + void AddEtwSink(logging::Severity etwSeverity); +#endif + /** Change the minimum severity level for log messages to be output by the default logger. @param severity The severity. @@ -214,7 +241,10 @@ class LoggingManager final { void CreateDefaultLogger(const std::string& logger_id); std::unique_ptr sink_; - const Severity default_min_severity_; +#ifdef _WIN32 + mutable OrtMutex sink_mutex_; +#endif + Severity default_min_severity_; const bool default_filter_user_data_; const int default_max_vlog_level_; bool owns_default_logger_; @@ -362,7 +392,7 @@ unsigned int GetProcessId(); /** If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then adds to the existing logger. */ -std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, +std::unique_ptr EnhanceSinkWithEtw(std::unique_ptr existingSink, logging::Severity originalSeverity, logging::Severity etwSeverity); /** diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index eac9a7fa08081..344c795b8c229 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -22,10 +22,10 @@ #include #endif #endif -#include "core/platform/ort_mutex.h" #if __FreeBSD__ #include // Use thr_self() syscall under FreeBSD to get thread id +#include "logging.h" #endif namespace onnxruntime { @@ -52,6 +52,10 @@ static std::atomic& DefaultLoggerManagerInstance() noexcept { return default_instance; } +LoggingManager* LoggingManager::GetDefaultInstance() { + return static_cast(DefaultLoggerManagerInstance().load()); +} + // GSL_SUPRESS(i.22) is broken. Ignore the warnings for the static local variables that are trivial // and should not have any destruction order issues via pragmas instead. // https://developercommunity.visualstudio.com/content/problem/249706/gslsuppress-does-not-work-for-i22-c-core-guideline.html @@ -66,6 +70,7 @@ static OrtMutex& DefaultLoggerMutex() noexcept { } Logger* LoggingManager::s_default_logger_ = nullptr; +OrtMutex sink_mutex_; #ifdef _MSC_VER #pragma warning(pop) @@ -155,11 +160,33 @@ std::unique_ptr LoggingManager::CreateLogger(const std::string& logger_i return logger; } +#ifdef _WIN32 +// std::shared_ptr LoggingManager::GetCurrentSink() const { +// std::lock_guard guard(sink_mutex_); +// return sink_; +// } + +void LoggingManager::UpdateSink(std::unique_ptr new_sink) { + if (!new_sink) { + throw std::invalid_argument("new_sink must not be nullptr."); + } + + std::lock_guard guard(sink_mutex_); + sink_ = std::move(new_sink); +} +#endif + void LoggingManager::Log(const std::string& logger_id, const Capture& message) const { +// #ifdef _WIN32 +// std::lock_guard guard(sink_mutex_); +// #endif sink_->Send(GetTimestamp(), logger_id, message); } void LoggingManager::SendProfileEvent(profiling::EventRecord& eventRecord) const { +// #ifdef _WIN32 +// std::lock_guard guard(sink_mutex_); +// #endif sink_->SendProfileEvent(eventRecord); } @@ -245,17 +272,17 @@ unsigned int GetProcessId() { #endif } -std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, +std::unique_ptr EnhanceSinkWithEtw(std::unique_ptr existingSink, 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::move(existingSink), originalSeverity); compositeSink->AddSink(std::make_unique(), etwSeverity); return compositeSink; } else { - return existingLogger; + return existingSink; } #else // On non-Windows platforms, just return the existing logger @@ -276,5 +303,81 @@ Severity OverrideLevelWithEtw(Severity originalSeverity) { return originalSeverity; } +#ifdef _WIN32 +void LoggingManager::AddEtwSink(logging::Severity etwSeverity) { + std::lock_guard guard(sink_mutex_); + + // Check if the EtwRegistrationManager is enabled + auto& manager = EtwRegistrationManager::Instance(); + if (!manager.IsEnabled()) { + return; // ETW not enabled, no operation needed + } + + CompositeSink* current_composite = dynamic_cast(sink_.get()); + if (!current_composite) { + // Current sink is not a composite, create a new composite sink and add the current sink to it + auto new_composite = std::make_unique(); + new_composite->AddSink(std::move(sink_), default_min_severity_); // Move the current sink into the new composite + sink_ = std::move(new_composite); // Now sink_ is pointing to the new composite + current_composite = static_cast(sink_.get()); // Update pointer to the new composite sink + } + + // Adjust the default minimum severity level to accommodate ETW logging needs + default_min_severity_ = std::min(default_min_severity_, etwSeverity); + if (s_default_logger_ != nullptr) { + s_default_logger_->SetSeverity(default_min_severity_); + } + + // Check if an EtwSink already exists in the current composite + const auto& sinks = current_composite->GetSinks(); + if (std::any_of(sinks.begin(), sinks.end(), [](const auto& pair) { + return dynamic_cast(pair.first.get()) != nullptr; + })) { + return; // EtwSink already exists, do not add another + } + + // Add a new EtwSink + current_composite->AddSink(std::make_unique(), etwSeverity); + +} + +void LoggingManager::RemoveEtwSink() { + std::lock_guard guard(sink_mutex_); + auto composite_sink = dynamic_cast(sink_.get()); + + if (composite_sink) { + const auto& sinks_with_severity = composite_sink->GetSinks(); + std::unique_ptr remaining_sink; + + Severity newSeverity = Severity::kFATAL; + + for (const auto& sink_pair : sinks_with_severity) { + if (dynamic_cast(sink_pair.first.get()) == nullptr) { + if (remaining_sink) { + // If more than one non-EtwSink is found, we leave the CompositeSink intact + return; + } + newSeverity = std::min(newSeverity, sink_pair.second); + remaining_sink = std::move(const_cast&>(sink_pair.first)); + } + } + + // If only one non-EtwSink remains, replace the CompositeSink with this sink + if (remaining_sink) { + sink_ = std::move(remaining_sink); + + } else { + // Handle the case where all sinks were EtwSinks + // sink_ = std::make_unique(); // Assuming NullSink is a basic ISink that does nothing + } + + default_min_severity_ = newSeverity; + if (s_default_logger_ != nullptr) { + s_default_logger_->SetSeverity(default_min_severity_); + } + } +} +#endif + } // namespace logging } // 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 f322a27da22ff..26b9733b0e4a0 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -234,13 +234,30 @@ void QnnLogging(const char* format, QnnLog_Level_t level, uint64_t timestamp, va_list argument_parameter) { - ORT_UNUSED_PARAMETER(level); ORT_UNUSED_PARAMETER(timestamp); // Always output Qnn log as Ort verbose log const auto& logger = ::onnxruntime::logging::LoggingManager::DefaultLogger(); - const auto severity = ::onnxruntime::logging::Severity::kVERBOSE; const auto data_type = ::onnxruntime::logging::DataType::SYSTEM; + + ::onnxruntime::logging::Severity severity; + switch (level) { + case QNN_LOG_LEVEL_ERROR: + severity = ::onnxruntime::logging::Severity::kERROR; + break; + case QNN_LOG_LEVEL_WARN: + severity = ::onnxruntime::logging::Severity::kWARNING; + break; + case QNN_LOG_LEVEL_INFO: + severity = ::onnxruntime::logging::Severity::kINFO; + break; + case QNN_LOG_LEVEL_VERBOSE: + case QNN_LOG_LEVEL_DEBUG: // Treat DEBUG as VERBOSE in ORT + default: + severity = ::onnxruntime::logging::Severity::kVERBOSE; + break; + } + if (logger.OutputIsEnabled(severity, data_type)) { ::onnxruntime::logging::Capture(logger, severity, @@ -273,11 +290,69 @@ void QnnBackendManager::InitializeQnnLog() { } LOGS(*logger_, VERBOSE) << "Set Qnn log level: " << qnn_log_level; - if (QNN_SUCCESS != qnn_interface_.logCreate(QnnLogging, qnn_log_level, &log_handle_)) { - LOGS(*logger_, WARNING) << "Unable to initialize logging in the QNN backend."; + Qnn_ErrorHandle_t result = qnn_interface_.logCreate(QnnLogging, qnn_log_level, &log_handle_); + + if (result != QNN_SUCCESS) { + switch (result) { + case QNN_COMMON_ERROR_NOT_SUPPORTED: + LOGS(*logger_, ERROR) << "Logging not supported in the QNN backend."; + break; + case QNN_LOG_ERROR_INVALID_ARGUMENT: + LOGS(*logger_, ERROR) << "Invalid argument provided to QnnLog_create."; + break; + case QNN_LOG_ERROR_MEM_ALLOC: + LOGS(*logger_, ERROR) << "Memory allocation error during QNN logging initialization."; + break; + case QNN_LOG_ERROR_INITIALIZATION: + LOGS(*logger_, ERROR) << "Initialization of logging failed in the QNN backend."; + break; + default: + LOGS(*logger_, WARNING) << "Unknown error occurred while initializing logging in the QNN backend."; + break; + } } } +void QnnBackendManager::UpdateQnnLogLevel(logging::Severity ort_log_level) { + + if (nullptr == log_handle_) { + LOGS(*logger_, ERROR) << "Unable to update QNN Log Level. Invalid QNN log handle."; + return; + } + + QnnLog_Level_t qnn_log_level = QNN_LOG_LEVEL_ERROR; + // Map ORT log severity to Qnn log level + switch (ort_log_level) { + case logging::Severity::kVERBOSE: + qnn_log_level = QNN_LOG_LEVEL_DEBUG; + break; + case logging::Severity::kINFO: + qnn_log_level = QNN_LOG_LEVEL_INFO; + break; + case logging::Severity::kWARNING: + qnn_log_level = QNN_LOG_LEVEL_WARN; + break; + case logging::Severity::kERROR: + case logging::Severity::kFATAL: + default: + break; + } + + LOGS(*logger_, INFO) << "Updating Qnn log level to: " << qnn_log_level; + + // Use the QnnLog_setLogLevel API to set the new log level + Qnn_ErrorHandle_t result = qnn_interface_.logSetLogLevel(log_handle_, qnn_log_level); + if (QNN_SUCCESS != result) { + if (result == QNN_LOG_ERROR_INVALID_ARGUMENT) { + LOGS(*logger_, ERROR) << "Invalid log level argument provided to QnnLog_setLogLevel."; + } else if (result == QNN_LOG_ERROR_INVALID_HANDLE) { + LOGS(*logger_, ERROR) << "Invalid log handle provided to QnnLog_setLogLevel."; + } else { + LOGS(*logger_, ERROR) << "Failed to set log level in Qnn backend."; + } + } +} + Status QnnBackendManager::InitializeBackend() { if (true == backend_initialized_) { LOGS_DEFAULT(INFO) << "Backend initialized already."; diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h index 673e3c2f33d64..131b436bd5920 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h @@ -117,6 +117,8 @@ class QnnBackendManager { void InitializeQnnLog(); + void UpdateQnnLogLevel(logging::Severity ort_log_level); + // Terminate logging in the backend Status TerminateQnnLog() { if (logger_ == nullptr) { diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index 235ea45cd4dde..d91584ba6947b 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -23,6 +23,11 @@ #include "core/providers/qnn/builder/onnx_ctx_model_helper.h" #include "core/framework/run_options.h" +#ifdef _WIN32 +#include +#include "core/platform/windows/logging/etw_sink.h" +#endif + namespace onnxruntime { constexpr const char* QNN = "QNN"; @@ -220,6 +225,37 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio } } +#ifdef _WIN32 + auto& etwRegistrationManager = logging::EtwRegistrationManager::Instance(); + // Register callback for ETW capture state (rundown) + etwRegistrationManager.RegisterInternalCallback( + [&etwRegistrationManager, this]( + LPCGUID SourceId, + ULONG IsEnabled, + UCHAR Level, + ULONGLONG MatchAnyKeyword, + ULONGLONG MatchAllKeyword, + PEVENT_FILTER_DESCRIPTOR FilterData, + PVOID CallbackContext) { + (void)SourceId; + (void)Level; + (void)MatchAnyKeyword; + (void)MatchAllKeyword; + (void)FilterData; + (void)CallbackContext; + + // Check if this callback is for enabling + if (((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0) && + IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { + auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity(); + qnn_backend_manager_->UpdateQnnLogLevel(ortETWSeverity); + } + + // We can't just set to whatever when ETW is disabled. TODO - We need to remember/restore the original value + // (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) + }); +#endif + // In case ETW gets disabled later auto profiling_level_pos = provider_options_map.find(PROFILING_LEVEL); if (profiling_level_pos != provider_options_map.end()) { diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index c1cd21570a6a4..59fd1a14a7be4 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -345,7 +345,9 @@ void InferenceSession::SetLoggingManager(const SessionOptions& session_options, session_options.user_logging_param); auto sessionSeverity = GetSeverity(session_options); auto etwOverrideSeverity = logging::OverrideLevelWithEtw(sessionSeverity); - sink = EnhanceLoggerWithEtw(std::move(sink), sessionSeverity, etwOverrideSeverity); +#ifdef _WIN32 + sink = EnhanceSinkWithEtw(std::move(sink), sessionSeverity, etwOverrideSeverity); +#endif user_logging_manager_ = std::make_unique(std::move(sink), std::min(sessionSeverity, etwOverrideSeverity), @@ -369,7 +371,7 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, std::lock_guard lock(active_sessions_mutex_); active_sessions_[global_session_id_++] = this; - // Register callback for ETW capture state (rundown) + // Register callback for ETW capture state (rundown) for Microsoft.ML.ONNXRuntime provider WindowsTelemetry::RegisterInternalCallback( [this]( LPCGUID SourceId, @@ -392,6 +394,44 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, LogAllSessions(); } }); + + // Register callback for ETW start / stop so that LOGS tracing can be adjusted dynamically after session start + auto& etwRegistrationManager = logging::EtwRegistrationManager::Instance(); + // Register callback for ETW capture state (rundown) + etwRegistrationManager.RegisterInternalCallback( + [&etwRegistrationManager, this]( + LPCGUID SourceId, + ULONG IsEnabled, + UCHAR Level, + ULONGLONG MatchAnyKeyword, + ULONGLONG MatchAllKeyword, + PEVENT_FILTER_DESCRIPTOR FilterData, + PVOID CallbackContext) { + (void)SourceId; + (void)Level; + (void)MatchAnyKeyword; + (void)MatchAllKeyword; + (void)FilterData; + (void)CallbackContext; + + if (logging_manager_ != nullptr) { + + auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity(); + + if ((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0 && + IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { + LOGS(*session_logger_, VERBOSE) << "Adding ETW Sink to logger with severity level: " << (ULONG) ortETWSeverity; + logging_manager_->AddEtwSink(ortETWSeverity); + onnxruntime::logging::LoggingManager::GetDefaultInstance()->AddEtwSink(ortETWSeverity); + LOGS(*session_logger_, INFO) << "Done Adding ETW Sink to logger with severity level: " << (ULONG) ortETWSeverity; + } + if (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) { + LOGS(*session_logger_, INFO) << "Removing ETW Sink from logger"; + logging_manager_->RemoveEtwSink(); + LOGS(*session_logger_, VERBOSE) << "Done Removing ETW Sink from logger"; + } + } + }); #endif SetLoggingManager(session_options, session_env); diff --git a/onnxruntime/core/session/ort_env.cc b/onnxruntime/core/session/ort_env.cc index 331f1db26a029..6df013f523b07 100644 --- a/onnxruntime/core/session/ort_env.cc +++ b/onnxruntime/core/session/ort_env.cc @@ -48,7 +48,7 @@ OrtEnv* OrtEnv::GetInstance(const OrtEnv::LoggingManagerConstructionInfo& lm_inf sink = MakePlatformDefaultLogSink(); } auto etwOverrideSeverity = logging::OverrideLevelWithEtw(static_cast(lm_info.default_warning_level)); - sink = EnhanceLoggerWithEtw(std::move(sink), static_cast(lm_info.default_warning_level), + sink = EnhanceSinkWithEtw(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), From 9df03cc3020a333fe29054bf09ac9afd6f9fd803 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Sat, 27 Apr 2024 11:29:02 -0700 Subject: [PATCH 02/12] Reset QNN Log level when provider is disabled. Add captureStateOnSave to WPR profile. +Code cleanup and formatting --- .../onnxruntime/core/common/logging/logging.h | 12 +- onnxruntime/core/common/logging/logging.cc | 137 +++++++---------- .../qnn/builder/qnn_backend_manager.cc | 141 ++++++++---------- .../qnn/builder/qnn_backend_manager.h | 3 + .../providers/qnn/qnn_execution_provider.cc | 56 +++---- onnxruntime/core/session/inference_session.cc | 71 +++++---- onnxruntime/core/session/ort_env.cc | 2 +- ort.wprp | 11 +- 8 files changed, 196 insertions(+), 237 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index 9fc903232c1ac..c07a4e14a6bd3 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -172,16 +172,6 @@ class LoggingManager final { static LoggingManager* GetDefaultInstance(); #ifdef _WIN32 - /** - Returns the current sink - */ - // std::shared_ptr GetCurrentSink() const; - - /** - Replace the current sink with a new one - */ - void UpdateSink(std::unique_ptr new_sink); - /** Removes the ETW Sink if one is present */ @@ -393,7 +383,7 @@ unsigned int GetProcessId(); If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then adds to the existing logger. */ std::unique_ptr EnhanceSinkWithEtw(std::unique_ptr existingSink, logging::Severity originalSeverity, - logging::Severity etwSeverity); + logging::Severity etwSeverity); /** If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then can override the logging level. diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 344c795b8c229..014316e46d3c9 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -160,33 +160,11 @@ std::unique_ptr LoggingManager::CreateLogger(const std::string& logger_i return logger; } -#ifdef _WIN32 -// std::shared_ptr LoggingManager::GetCurrentSink() const { -// std::lock_guard guard(sink_mutex_); -// return sink_; -// } - -void LoggingManager::UpdateSink(std::unique_ptr new_sink) { - if (!new_sink) { - throw std::invalid_argument("new_sink must not be nullptr."); - } - - std::lock_guard guard(sink_mutex_); - sink_ = std::move(new_sink); -} -#endif - void LoggingManager::Log(const std::string& logger_id, const Capture& message) const { -// #ifdef _WIN32 -// std::lock_guard guard(sink_mutex_); -// #endif sink_->Send(GetTimestamp(), logger_id, message); } void LoggingManager::SendProfileEvent(profiling::EventRecord& eventRecord) const { -// #ifdef _WIN32 -// std::lock_guard guard(sink_mutex_); -// #endif sink_->SendProfileEvent(eventRecord); } @@ -273,7 +251,7 @@ unsigned int GetProcessId() { } std::unique_ptr EnhanceSinkWithEtw(std::unique_ptr existingSink, logging::Severity originalSeverity, - logging::Severity etwSeverity) { + logging::Severity etwSeverity) { #ifdef _WIN32 auto& manager = EtwRegistrationManager::Instance(); if (manager.IsEnabled()) { @@ -305,77 +283,76 @@ Severity OverrideLevelWithEtw(Severity originalSeverity) { #ifdef _WIN32 void LoggingManager::AddEtwSink(logging::Severity etwSeverity) { - std::lock_guard guard(sink_mutex_); + std::lock_guard guard(sink_mutex_); - // Check if the EtwRegistrationManager is enabled - auto& manager = EtwRegistrationManager::Instance(); - if (!manager.IsEnabled()) { - return; // ETW not enabled, no operation needed - } + // Check if the EtwRegistrationManager is enabled + auto& manager = EtwRegistrationManager::Instance(); + if (!manager.IsEnabled()) { + return; // ETW not enabled, no operation needed + } - CompositeSink* current_composite = dynamic_cast(sink_.get()); - if (!current_composite) { - // Current sink is not a composite, create a new composite sink and add the current sink to it - auto new_composite = std::make_unique(); - new_composite->AddSink(std::move(sink_), default_min_severity_); // Move the current sink into the new composite - sink_ = std::move(new_composite); // Now sink_ is pointing to the new composite - current_composite = static_cast(sink_.get()); // Update pointer to the new composite sink - } + CompositeSink* current_composite = dynamic_cast(sink_.get()); + if (!current_composite) { + // Current sink is not a composite, create a new composite sink and add the current sink to it + auto new_composite = std::make_unique(); + new_composite->AddSink(std::move(sink_), default_min_severity_); // Move the current sink into the new composite + sink_ = std::move(new_composite); // Now sink_ is pointing to the new composite + current_composite = static_cast(sink_.get()); // Update pointer to the new composite sink + } - // Adjust the default minimum severity level to accommodate ETW logging needs - default_min_severity_ = std::min(default_min_severity_, etwSeverity); - if (s_default_logger_ != nullptr) { - s_default_logger_->SetSeverity(default_min_severity_); - } + // Adjust the default minimum severity level to accommodate ETW logging needs + default_min_severity_ = std::min(default_min_severity_, etwSeverity); + if (s_default_logger_ != nullptr) { + s_default_logger_->SetSeverity(default_min_severity_); + } - // Check if an EtwSink already exists in the current composite - const auto& sinks = current_composite->GetSinks(); - if (std::any_of(sinks.begin(), sinks.end(), [](const auto& pair) { + // Check if an EtwSink already exists in the current composite + const auto& sinks = current_composite->GetSinks(); + if (std::any_of(sinks.begin(), sinks.end(), [](const auto& pair) { return dynamic_cast(pair.first.get()) != nullptr; - })) { - return; // EtwSink already exists, do not add another - } - - // Add a new EtwSink - current_composite->AddSink(std::make_unique(), etwSeverity); + })) { + return; // EtwSink already exists, do not add another + } + // Add a new EtwSink + current_composite->AddSink(std::make_unique(), etwSeverity); } void LoggingManager::RemoveEtwSink() { - std::lock_guard guard(sink_mutex_); - auto composite_sink = dynamic_cast(sink_.get()); - - if (composite_sink) { - const auto& sinks_with_severity = composite_sink->GetSinks(); - std::unique_ptr remaining_sink; - - Severity newSeverity = Severity::kFATAL; - - for (const auto& sink_pair : sinks_with_severity) { - if (dynamic_cast(sink_pair.first.get()) == nullptr) { - if (remaining_sink) { - // If more than one non-EtwSink is found, we leave the CompositeSink intact - return; - } - newSeverity = std::min(newSeverity, sink_pair.second); - remaining_sink = std::move(const_cast&>(sink_pair.first)); - } - } + std::lock_guard guard(sink_mutex_); + auto composite_sink = dynamic_cast(sink_.get()); - // If only one non-EtwSink remains, replace the CompositeSink with this sink - if (remaining_sink) { - sink_ = std::move(remaining_sink); + if (composite_sink) { + const auto& sinks_with_severity = composite_sink->GetSinks(); + std::unique_ptr remaining_sink; - } else { - // Handle the case where all sinks were EtwSinks - // sink_ = std::make_unique(); // Assuming NullSink is a basic ISink that does nothing - } + Severity newSeverity = Severity::kFATAL; - default_min_severity_ = newSeverity; - if (s_default_logger_ != nullptr) { - s_default_logger_->SetSeverity(default_min_severity_); + for (const auto& sink_pair : sinks_with_severity) { + if (dynamic_cast(sink_pair.first.get()) == nullptr) { + if (remaining_sink) { + // If more than one non-EtwSink is found, we leave the CompositeSink intact + return; } + newSeverity = std::min(newSeverity, sink_pair.second); + remaining_sink = std::move(const_cast&>(sink_pair.first)); + } } + + // If only one non-EtwSink remains, replace the CompositeSink with this sink + if (remaining_sink) { + sink_ = std::move(remaining_sink); + + } else { + // Handle the case where all sinks were EtwSinks + // sink_ = std::make_unique(); // Assuming NullSink is a basic ISink that does nothing + } + + default_min_severity_ = newSeverity; + if (s_default_logger_ != nullptr) { + s_default_logger_->SetSeverity(default_min_severity_); + } + } } #endif diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index 26b9733b0e4a0..a04b9272e80ed 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -236,26 +236,25 @@ void QnnLogging(const char* format, va_list argument_parameter) { ORT_UNUSED_PARAMETER(timestamp); - // Always output Qnn log as Ort verbose log const auto& logger = ::onnxruntime::logging::LoggingManager::DefaultLogger(); const auto data_type = ::onnxruntime::logging::DataType::SYSTEM; ::onnxruntime::logging::Severity severity; switch (level) { - case QNN_LOG_LEVEL_ERROR: - severity = ::onnxruntime::logging::Severity::kERROR; - break; - case QNN_LOG_LEVEL_WARN: - severity = ::onnxruntime::logging::Severity::kWARNING; - break; - case QNN_LOG_LEVEL_INFO: - severity = ::onnxruntime::logging::Severity::kINFO; - break; - case QNN_LOG_LEVEL_VERBOSE: - case QNN_LOG_LEVEL_DEBUG: // Treat DEBUG as VERBOSE in ORT - default: - severity = ::onnxruntime::logging::Severity::kVERBOSE; - break; + case QNN_LOG_LEVEL_ERROR: + severity = ::onnxruntime::logging::Severity::kERROR; + break; + case QNN_LOG_LEVEL_WARN: + severity = ::onnxruntime::logging::Severity::kWARNING; + break; + case QNN_LOG_LEVEL_INFO: + severity = ::onnxruntime::logging::Severity::kINFO; + break; + case QNN_LOG_LEVEL_VERBOSE: + case QNN_LOG_LEVEL_DEBUG: // Treat DEBUG as VERBOSE in ORT + default: + severity = ::onnxruntime::logging::Severity::kVERBOSE; + break; } if (logger.OutputIsEnabled(severity, data_type)) { @@ -270,87 +269,75 @@ void QnnLogging(const char* format, void QnnBackendManager::InitializeQnnLog() { // Set Qnn log level align with Ort log level - QnnLog_Level_t qnn_log_level = QNN_LOG_LEVEL_WARN; auto ort_log_level = logger_->GetSeverity(); + QnnLog_Level_t qnn_log_level = MapOrtSeverityToQNNLogLevel(ort_log_level); + LOGS(*logger_, VERBOSE) << "Set Qnn log level: " << qnn_log_level; + + Qnn_ErrorHandle_t result = qnn_interface_.logCreate(QnnLogging, qnn_log_level, &log_handle_); + + if (result != QNN_SUCCESS) { + switch (result) { + case QNN_COMMON_ERROR_NOT_SUPPORTED: + LOGS(*logger_, ERROR) << "Logging not supported in the QNN backend."; + break; + case QNN_LOG_ERROR_INVALID_ARGUMENT: + LOGS(*logger_, ERROR) << "Invalid argument provided to QnnLog_create."; + break; + case QNN_LOG_ERROR_MEM_ALLOC: + LOGS(*logger_, ERROR) << "Memory allocation error during QNN logging initialization."; + break; + case QNN_LOG_ERROR_INITIALIZATION: + LOGS(*logger_, ERROR) << "Initialization of logging failed in the QNN backend."; + break; + default: + LOGS(*logger_, WARNING) << "Unknown error occurred while initializing logging in the QNN backend."; + break; + } + } +} + +QnnLog_Level_t QnnBackendManager::MapOrtSeverityToQNNLogLevel(logging::Severity ort_log_level) { + // Map ORT log severity to Qnn log level switch (ort_log_level) { case logging::Severity::kVERBOSE: - qnn_log_level = QNN_LOG_LEVEL_DEBUG; - break; + return QNN_LOG_LEVEL_DEBUG; case logging::Severity::kINFO: - qnn_log_level = QNN_LOG_LEVEL_INFO; - break; + return QNN_LOG_LEVEL_INFO; case logging::Severity::kWARNING: - qnn_log_level = QNN_LOG_LEVEL_WARN; - break; + return QNN_LOG_LEVEL_WARN; case logging::Severity::kERROR: - qnn_log_level = QNN_LOG_LEVEL_ERROR; - break; + case logging::Severity::kFATAL: default: - break; + return QNN_LOG_LEVEL_ERROR; } - LOGS(*logger_, VERBOSE) << "Set Qnn log level: " << qnn_log_level; - - Qnn_ErrorHandle_t result = qnn_interface_.logCreate(QnnLogging, qnn_log_level, &log_handle_); +} - if (result != QNN_SUCCESS) { - switch (result) { - case QNN_COMMON_ERROR_NOT_SUPPORTED: - LOGS(*logger_, ERROR) << "Logging not supported in the QNN backend."; - break; - case QNN_LOG_ERROR_INVALID_ARGUMENT: - LOGS(*logger_, ERROR) << "Invalid argument provided to QnnLog_create."; - break; - case QNN_LOG_ERROR_MEM_ALLOC: - LOGS(*logger_, ERROR) << "Memory allocation error during QNN logging initialization."; - break; - case QNN_LOG_ERROR_INITIALIZATION: - LOGS(*logger_, ERROR) << "Initialization of logging failed in the QNN backend."; - break; - default: - LOGS(*logger_, WARNING) << "Unknown error occurred while initializing logging in the QNN backend."; - break; - } - } +void QnnBackendManager::ResetQnnLogLevel() { + auto ort_log_level = logger_->GetSeverity(); + LOGS(*logger_, INFO) << "Reset Qnn log level to ORT Logger level: " << (UINT) ort_log_level; + UpdateQnnLogLevel(ort_log_level); } void QnnBackendManager::UpdateQnnLogLevel(logging::Severity ort_log_level) { - if (nullptr == log_handle_) { LOGS(*logger_, ERROR) << "Unable to update QNN Log Level. Invalid QNN log handle."; return; } + QnnLog_Level_t qnn_log_level = MapOrtSeverityToQNNLogLevel(ort_log_level); - QnnLog_Level_t qnn_log_level = QNN_LOG_LEVEL_ERROR; - // Map ORT log severity to Qnn log level - switch (ort_log_level) { - case logging::Severity::kVERBOSE: - qnn_log_level = QNN_LOG_LEVEL_DEBUG; - break; - case logging::Severity::kINFO: - qnn_log_level = QNN_LOG_LEVEL_INFO; - break; - case logging::Severity::kWARNING: - qnn_log_level = QNN_LOG_LEVEL_WARN; - break; - case logging::Severity::kERROR: - case logging::Severity::kFATAL: - default: - break; - } - - LOGS(*logger_, INFO) << "Updating Qnn log level to: " << qnn_log_level; + LOGS(*logger_, INFO) << "Updating Qnn log level to: " << qnn_log_level; - // Use the QnnLog_setLogLevel API to set the new log level - Qnn_ErrorHandle_t result = qnn_interface_.logSetLogLevel(log_handle_, qnn_log_level); - if (QNN_SUCCESS != result) { - if (result == QNN_LOG_ERROR_INVALID_ARGUMENT) { - LOGS(*logger_, ERROR) << "Invalid log level argument provided to QnnLog_setLogLevel."; - } else if (result == QNN_LOG_ERROR_INVALID_HANDLE) { - LOGS(*logger_, ERROR) << "Invalid log handle provided to QnnLog_setLogLevel."; - } else { - LOGS(*logger_, ERROR) << "Failed to set log level in Qnn backend."; - } + // Use the QnnLog_setLogLevel API to set the new log level + Qnn_ErrorHandle_t result = qnn_interface_.logSetLogLevel(log_handle_, qnn_log_level); + if (QNN_SUCCESS != result) { + if (result == QNN_LOG_ERROR_INVALID_ARGUMENT) { + LOGS(*logger_, ERROR) << "Invalid log level argument provided to QnnLog_setLogLevel."; + } else if (result == QNN_LOG_ERROR_INVALID_HANDLE) { + LOGS(*logger_, ERROR) << "Invalid log handle provided to QnnLog_setLogLevel."; + } else { + LOGS(*logger_, ERROR) << "Failed to set log level in Qnn backend."; } + } } Status QnnBackendManager::InitializeBackend() { diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h index 131b436bd5920..594c591f42375 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h @@ -119,6 +119,8 @@ class QnnBackendManager { void UpdateQnnLogLevel(logging::Severity ort_log_level); + void ResetQnnLogLevel(); + // Terminate logging in the backend Status TerminateQnnLog() { if (logger_ == nullptr) { @@ -208,6 +210,7 @@ class QnnBackendManager { 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); + QnnLog_Level_t MapOrtSeverityToQNNLogLevel(logging::Severity ort_log_level); #ifdef _WIN32 void LogQnnProfileEventAsTraceLogging( uint64_t timestamp, diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index d91584ba6947b..cec1823153940 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -226,34 +226,34 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio } #ifdef _WIN32 - auto& etwRegistrationManager = logging::EtwRegistrationManager::Instance(); - // Register callback for ETW capture state (rundown) - etwRegistrationManager.RegisterInternalCallback( - [&etwRegistrationManager, this]( - LPCGUID SourceId, - ULONG IsEnabled, - UCHAR Level, - ULONGLONG MatchAnyKeyword, - ULONGLONG MatchAllKeyword, - PEVENT_FILTER_DESCRIPTOR FilterData, - PVOID CallbackContext) { - (void)SourceId; - (void)Level; - (void)MatchAnyKeyword; - (void)MatchAllKeyword; - (void)FilterData; - (void)CallbackContext; - - // Check if this callback is for enabling - if (((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0) && - IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { - auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity(); - qnn_backend_manager_->UpdateQnnLogLevel(ortETWSeverity); - } - - // We can't just set to whatever when ETW is disabled. TODO - We need to remember/restore the original value - // (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) - }); + auto& etwRegistrationManager = logging::EtwRegistrationManager::Instance(); + // Register callback for ETW capture state (rundown) + etwRegistrationManager.RegisterInternalCallback( + [&etwRegistrationManager, this]( + LPCGUID SourceId, + ULONG IsEnabled, + UCHAR Level, + ULONGLONG MatchAnyKeyword, + ULONGLONG MatchAllKeyword, + PEVENT_FILTER_DESCRIPTOR FilterData, + PVOID CallbackContext) { + (void)SourceId; + (void)Level; + (void)MatchAnyKeyword; + (void)MatchAllKeyword; + (void)FilterData; + (void)CallbackContext; + + if (((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0) && + IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { + auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity(); + qnn_backend_manager_->UpdateQnnLogLevel(ortETWSeverity); + } + + if (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) { + qnn_backend_manager_->ResetQnnLogLevel(); + } + }); #endif // In case ETW gets disabled later diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 59fd1a14a7be4..a194bf7302c10 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -395,43 +395,42 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, } }); - // Register callback for ETW start / stop so that LOGS tracing can be adjusted dynamically after session start - auto& etwRegistrationManager = logging::EtwRegistrationManager::Instance(); - // Register callback for ETW capture state (rundown) - etwRegistrationManager.RegisterInternalCallback( - [&etwRegistrationManager, this]( - LPCGUID SourceId, - ULONG IsEnabled, - UCHAR Level, - ULONGLONG MatchAnyKeyword, - ULONGLONG MatchAllKeyword, - PEVENT_FILTER_DESCRIPTOR FilterData, - PVOID CallbackContext) { - (void)SourceId; - (void)Level; - (void)MatchAnyKeyword; - (void)MatchAllKeyword; - (void)FilterData; - (void)CallbackContext; - - if (logging_manager_ != nullptr) { - - auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity(); - - if ((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0 && - IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { - LOGS(*session_logger_, VERBOSE) << "Adding ETW Sink to logger with severity level: " << (ULONG) ortETWSeverity; - logging_manager_->AddEtwSink(ortETWSeverity); - onnxruntime::logging::LoggingManager::GetDefaultInstance()->AddEtwSink(ortETWSeverity); - LOGS(*session_logger_, INFO) << "Done Adding ETW Sink to logger with severity level: " << (ULONG) ortETWSeverity; - } - if (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) { - LOGS(*session_logger_, INFO) << "Removing ETW Sink from logger"; - logging_manager_->RemoveEtwSink(); - LOGS(*session_logger_, VERBOSE) << "Done Removing ETW Sink from logger"; - } + // Register callback for ETW start / stop so that LOGS tracing can be adjusted dynamically after session start + auto& etwRegistrationManager = logging::EtwRegistrationManager::Instance(); + // Register callback for ETW capture state (rundown) + etwRegistrationManager.RegisterInternalCallback( + [&etwRegistrationManager, this]( + LPCGUID SourceId, + ULONG IsEnabled, + UCHAR Level, + ULONGLONG MatchAnyKeyword, + ULONGLONG MatchAllKeyword, + PEVENT_FILTER_DESCRIPTOR FilterData, + PVOID CallbackContext) { + (void)SourceId; + (void)Level; + (void)MatchAnyKeyword; + (void)MatchAllKeyword; + (void)FilterData; + (void)CallbackContext; + + if (logging_manager_ != nullptr) { + auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity(); + + if ((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0 && + IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { + LOGS(*session_logger_, VERBOSE) << "Adding ETW Sink to logger with severity level: " << (ULONG)ortETWSeverity; + logging_manager_->AddEtwSink(ortETWSeverity); + onnxruntime::logging::LoggingManager::GetDefaultInstance()->AddEtwSink(ortETWSeverity); + LOGS(*session_logger_, INFO) << "Done Adding ETW Sink to logger with severity level: " << (ULONG)ortETWSeverity; + } + if (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) { + LOGS(*session_logger_, INFO) << "Removing ETW Sink from logger"; + logging_manager_->RemoveEtwSink(); + LOGS(*session_logger_, VERBOSE) << "Done Removing ETW Sink from logger"; } - }); + } + }); #endif SetLoggingManager(session_options, session_env); diff --git a/onnxruntime/core/session/ort_env.cc b/onnxruntime/core/session/ort_env.cc index 6df013f523b07..3c178fd1e91d3 100644 --- a/onnxruntime/core/session/ort_env.cc +++ b/onnxruntime/core/session/ort_env.cc @@ -49,7 +49,7 @@ OrtEnv* OrtEnv::GetInstance(const OrtEnv::LoggingManagerConstructionInfo& lm_inf } auto etwOverrideSeverity = logging::OverrideLevelWithEtw(static_cast(lm_info.default_warning_level)); sink = EnhanceSinkWithEtw(std::move(sink), static_cast(lm_info.default_warning_level), - etwOverrideSeverity); + etwOverrideSeverity); lmgr = std::make_unique(std::move(sink), std::min(static_cast(lm_info.default_warning_level), etwOverrideSeverity), false, diff --git a/ort.wprp b/ort.wprp index b82ec5882c60d..5dd2332cb1f9f 100644 --- a/ort.wprp +++ b/ort.wprp @@ -1,5 +1,5 @@  - @@ -12,8 +12,11 @@ - + + + + + @@ -48,4 +51,4 @@ DetailLevel="Light" /> - \ No newline at end of file + From b0220f406bba27c86d0912e0ca9ce60506722c4d Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Sat, 27 Apr 2024 13:36:31 -0700 Subject: [PATCH 03/12] Log SessionCreation_CaptureState upon ETW captureState --- onnxruntime/core/platform/telemetry.cc | 3 +- onnxruntime/core/platform/telemetry.h | 2 +- .../core/platform/windows/telemetry.cc | 69 +++++++++++++------ onnxruntime/core/platform/windows/telemetry.h | 2 +- onnxruntime/core/session/inference_session.cc | 16 ++++- 5 files changed, 64 insertions(+), 28 deletions(-) diff --git a/onnxruntime/core/platform/telemetry.cc b/onnxruntime/core/platform/telemetry.cc index dc3b011cc7968..206774c896ff5 100644 --- a/onnxruntime/core/platform/telemetry.cc +++ b/onnxruntime/core/platform/telemetry.cc @@ -55,7 +55,7 @@ void Telemetry::LogSessionCreation(uint32_t session_id, int64_t ir_version, cons const std::string& model_graph_name, const std::unordered_map& model_metadata, const std::string& loadedFrom, const std::vector& execution_provider_ids, - bool use_fp16) const { + bool use_fp16, bool captureState) const { ORT_UNUSED_PARAMETER(session_id); ORT_UNUSED_PARAMETER(ir_version); ORT_UNUSED_PARAMETER(model_producer_name); @@ -67,6 +67,7 @@ void Telemetry::LogSessionCreation(uint32_t session_id, int64_t ir_version, cons ORT_UNUSED_PARAMETER(loadedFrom); ORT_UNUSED_PARAMETER(execution_provider_ids); ORT_UNUSED_PARAMETER(use_fp16); + ORT_UNUSED_PARAMETER(captureState); } void Telemetry::LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file, diff --git a/onnxruntime/core/platform/telemetry.h b/onnxruntime/core/platform/telemetry.h index 7b61de9d54073..bc261fddcd56e 100644 --- a/onnxruntime/core/platform/telemetry.h +++ b/onnxruntime/core/platform/telemetry.h @@ -60,7 +60,7 @@ class Telemetry { const std::string& model_graph_name, const std::unordered_map& model_metadata, const std::string& loadedFrom, const std::vector& execution_provider_ids, - bool use_fp16) const; + bool use_fp16, bool captureState) const; virtual void LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file, const char* function, uint32_t line) const; diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index 654281d526e4d..f3063219c7875 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -210,7 +210,7 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio const std::string& model_graph_name, const std::unordered_map& model_metadata, const std::string& loaded_from, const std::vector& execution_provider_ids, - bool use_fp16) const { + bool use_fp16, bool captureState) const { if (global_register_count_ == 0 || enabled_ == false) return; @@ -253,27 +253,52 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio execution_provider_string += i; } - TraceLoggingWrite(telemetry_provider_handle, - "SessionCreation", - 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"), - TraceLoggingInt64(ir_version, "irVersion"), - TraceLoggingUInt32(projection_, "OrtProgrammingProjection"), - TraceLoggingString(model_producer_name.c_str(), "modelProducerName"), - TraceLoggingString(model_producer_version.c_str(), "modelProducerVersion"), - TraceLoggingString(model_domain.c_str(), "modelDomain"), - TraceLoggingBool(use_fp16, "usefp16"), - TraceLoggingString(domain_to_verison_string.c_str(), "domainToVersionMap"), - TraceLoggingString(model_graph_name.c_str(), "modelGraphName"), - TraceLoggingString(model_metadata_string.c_str(), "modelMetaData"), - TraceLoggingString(loaded_from.c_str(), "loadedFrom"), - TraceLoggingString(execution_provider_string.c_str(), "executionProviderIds")); + // Difference is MeasureEvent & isCaptureState, but keep in sync otherwise + if (!captureState) { + TraceLoggingWrite(telemetry_provider_handle, + "SessionCreation", + 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"), + TraceLoggingInt64(ir_version, "irVersion"), + TraceLoggingUInt32(projection_, "OrtProgrammingProjection"), + TraceLoggingString(model_producer_name.c_str(), "modelProducerName"), + TraceLoggingString(model_producer_version.c_str(), "modelProducerVersion"), + TraceLoggingString(model_domain.c_str(), "modelDomain"), + TraceLoggingBool(use_fp16, "usefp16"), + TraceLoggingString(domain_to_verison_string.c_str(), "domainToVersionMap"), + TraceLoggingString(model_graph_name.c_str(), "modelGraphName"), + TraceLoggingString(model_metadata_string.c_str(), "modelMetaData"), + TraceLoggingString(loaded_from.c_str(), "loadedFrom"), + TraceLoggingString(execution_provider_string.c_str(), "executionProviderIds")); + } else { + TraceLoggingWrite(telemetry_provider_handle, + "SessionCreation_CaptureState", + TraceLoggingBool(true, "UTCReplace_AppSessionGuid"), + TelemetryPrivacyDataTag(PDT_ProductAndServiceUsage), + // Not a measure event + TraceLoggingKeyword(static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Session)), + TraceLoggingLevel(WINEVENT_LEVEL_INFO), + // Telemetry info + TraceLoggingUInt8(0, "schemaVersion"), + TraceLoggingUInt32(session_id, "sessionId"), + TraceLoggingInt64(ir_version, "irVersion"), + TraceLoggingUInt32(projection_, "OrtProgrammingProjection"), + TraceLoggingString(model_producer_name.c_str(), "modelProducerName"), + TraceLoggingString(model_producer_version.c_str(), "modelProducerVersion"), + TraceLoggingString(model_domain.c_str(), "modelDomain"), + TraceLoggingBool(use_fp16, "usefp16"), + TraceLoggingString(domain_to_verison_string.c_str(), "domainToVersionMap"), + TraceLoggingString(model_graph_name.c_str(), "modelGraphName"), + TraceLoggingString(model_metadata_string.c_str(), "modelMetaData"), + TraceLoggingString(loaded_from.c_str(), "loadedFrom"), + TraceLoggingString(execution_provider_string.c_str(), "executionProviderIds")); + } } void WindowsTelemetry::LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file, diff --git a/onnxruntime/core/platform/windows/telemetry.h b/onnxruntime/core/platform/windows/telemetry.h index cdb186e9ed703..27cd20c2d21d1 100644 --- a/onnxruntime/core/platform/windows/telemetry.h +++ b/onnxruntime/core/platform/windows/telemetry.h @@ -51,7 +51,7 @@ class WindowsTelemetry : public Telemetry { const std::string& model_graph_name, const std::unordered_map& model_metadata, const std::string& loadedFrom, const std::vector& execution_provider_ids, - bool use_fp16) const override; + bool use_fp16, bool captureState) const override; void LogRuntimeError(uint32_t session_id, const common::Status& status, const char* file, const char* function, uint32_t line) const override; diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index a194bf7302c10..880b4fccbedfa 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -567,7 +567,7 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, } void InferenceSession::TraceSessionOptions(const SessionOptions& session_options, bool captureState) { - (void)captureState; // Otherwise Linux build error + ORT_UNUSED_PARAMETER(captureState); // Otherwise Linux build error LOGS(*session_logger_, INFO) << session_options; @@ -2066,8 +2066,8 @@ common::Status InferenceSession::Initialize() { bool model_has_fp16_inputs = ModelHasFP16Inputs(graph); env.GetTelemetryProvider().LogSessionCreation( session_id_, model_->IrVersion(), model_->ProducerName(), model_->ProducerVersion(), model_->Domain(), - model_->MainGraph().DomainToVersionMap(), model_->MainGraph().Name(), model_->MetaData(), - telemetry_.event_name_, execution_providers_.GetIds(), model_has_fp16_inputs); + graph.DomainToVersionMap(), graph.Name(), model_->MetaData(), + telemetry_.event_name_, execution_providers_.GetIds(), model_has_fp16_inputs, false); LOGS(*session_logger_, INFO) << "Session successfully initialized."; } @@ -3208,9 +3208,19 @@ IOBinding* SessionIOBinding::Get() { #ifdef _WIN32 void InferenceSession::LogAllSessions() { + const Env& env = Env::Default(); + std::lock_guard lock(active_sessions_mutex_); for (const auto& session_pair : active_sessions_) { InferenceSession* session = session_pair.second; + + onnxruntime::Graph& graph = model_->MainGraph(); + bool model_has_fp16_inputs = ModelHasFP16Inputs(graph); + env.GetTelemetryProvider().LogSessionCreation( + session_id_, model_->IrVersion(), model_->ProducerName(), model_->ProducerVersion(), model_->Domain(), + graph.DomainToVersionMap(), graph.Name(), model_->MetaData(), + telemetry_.event_name_, execution_providers_.GetIds(), model_has_fp16_inputs, true); + TraceSessionOptions(session->session_options_, true); } } From 5905c06b5f3c3b1bbe7d98f6e0c556bb8d14297e Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Sat, 27 Apr 2024 13:41:29 -0700 Subject: [PATCH 04/12] LintRunner --- .../core/providers/qnn/builder/qnn_backend_manager.cc | 2 +- onnxruntime/core/providers/qnn/qnn_execution_provider.cc | 9 +++++---- onnxruntime/core/session/inference_session.cc | 2 +- 3 files changed, 7 insertions(+), 6 deletions(-) diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index a04b9272e80ed..84368afb86a9b 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -314,7 +314,7 @@ QnnLog_Level_t QnnBackendManager::MapOrtSeverityToQNNLogLevel(logging::Severity void QnnBackendManager::ResetQnnLogLevel() { auto ort_log_level = logger_->GetSeverity(); - LOGS(*logger_, INFO) << "Reset Qnn log level to ORT Logger level: " << (UINT) ort_log_level; + LOGS(*logger_, INFO) << "Reset Qnn log level to ORT Logger level: " << (UINT)ort_log_level; UpdateQnnLogLevel(ort_log_level); } diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index cec1823153940..fc737b566cd4d 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -244,10 +244,11 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio (void)FilterData; (void)CallbackContext; - if (((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0) && - IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { - auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity(); - qnn_backend_manager_->UpdateQnnLogLevel(ortETWSeverity); + if (IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { + if ((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0) { + auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity(); + qnn_backend_manager_->UpdateQnnLogLevel(ortETWSeverity); + } } if (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) { diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 880b4fccbedfa..f801929557d51 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -567,7 +567,7 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, } void InferenceSession::TraceSessionOptions(const SessionOptions& session_options, bool captureState) { - ORT_UNUSED_PARAMETER(captureState); // Otherwise Linux build error + ORT_UNUSED_PARAMETER(captureState); // Otherwise Linux build error LOGS(*session_logger_, INFO) << session_options; From 7fbe542c9a24d28c76a4cd143ef1e8048b1ecf78 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Wed, 1 May 2024 16:21:00 -0700 Subject: [PATCH 05/12] Refactor code to support also setting dynamically the QNN Profiling level via ETW. However, this is commented out / disabled for now due to 3rd party QNN crash seen in QNN 2.19.2 (qnn-sdk-v2.19.2.24021) --- .../qnn/builder/qnn_backend_manager.cc | 37 +++++++++---- .../qnn/builder/qnn_backend_manager.h | 10 ++-- .../providers/qnn/qnn_execution_provider.cc | 52 ++++++++++++------- .../providers/qnn/qnn_execution_provider.h | 2 + 4 files changed, 68 insertions(+), 33 deletions(-) diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index 84368afb86a9b..b6bc34964c8bd 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -267,7 +267,7 @@ void QnnLogging(const char* format, } } -void QnnBackendManager::InitializeQnnLog() { +Status QnnBackendManager::InitializeQnnLog() { // Set Qnn log level align with Ort log level auto ort_log_level = logger_->GetSeverity(); QnnLog_Level_t qnn_log_level = MapOrtSeverityToQNNLogLevel(ort_log_level); @@ -294,6 +294,9 @@ void QnnBackendManager::InitializeQnnLog() { break; } } + + ORT_RETURN_IF(QNN_BACKEND_NO_ERROR != result, "Failed to initialize logging in the QNN backend"); + return Status::OK(); } QnnLog_Level_t QnnBackendManager::MapOrtSeverityToQNNLogLevel(logging::Severity ort_log_level) { @@ -312,17 +315,14 @@ QnnLog_Level_t QnnBackendManager::MapOrtSeverityToQNNLogLevel(logging::Severity } } -void QnnBackendManager::ResetQnnLogLevel() { +Status QnnBackendManager::ResetQnnLogLevel() { auto ort_log_level = logger_->GetSeverity(); LOGS(*logger_, INFO) << "Reset Qnn log level to ORT Logger level: " << (UINT)ort_log_level; - UpdateQnnLogLevel(ort_log_level); + return UpdateQnnLogLevel(ort_log_level); } -void QnnBackendManager::UpdateQnnLogLevel(logging::Severity ort_log_level) { - if (nullptr == log_handle_) { - LOGS(*logger_, ERROR) << "Unable to update QNN Log Level. Invalid QNN log handle."; - return; - } +Status QnnBackendManager::UpdateQnnLogLevel(logging::Severity ort_log_level) { + ORT_RETURN_IF(nullptr == log_handle_, "Unable to update QNN Log Level. Invalid QNN log handle."); QnnLog_Level_t qnn_log_level = MapOrtSeverityToQNNLogLevel(ort_log_level); LOGS(*logger_, INFO) << "Updating Qnn log level to: " << qnn_log_level; @@ -334,10 +334,10 @@ void QnnBackendManager::UpdateQnnLogLevel(logging::Severity ort_log_level) { LOGS(*logger_, ERROR) << "Invalid log level argument provided to QnnLog_setLogLevel."; } else if (result == QNN_LOG_ERROR_INVALID_HANDLE) { LOGS(*logger_, ERROR) << "Invalid log handle provided to QnnLog_setLogLevel."; - } else { - LOGS(*logger_, ERROR) << "Failed to set log level in Qnn backend."; } } + ORT_RETURN_IF(QNN_BACKEND_NO_ERROR != result, "Failed to set log level in Qnn backend"); + return Status::OK(); } Status QnnBackendManager::InitializeBackend() { @@ -484,6 +484,23 @@ Status QnnBackendManager::ReleaseProfilehandle() { return Status::OK(); } +Status QnnBackendManager::SetProfilingLevelETW(ProfilingLevel profiling_level_etw_param) { + if (profiling_level_etw_ != profiling_level_etw_param) { + profiling_level_etw_ = profiling_level_etw_param; + + auto result = ReleaseProfilehandle(); + if (Status::OK() != result) { + ORT_THROW("Failed to ReleaseProfilehandle for previous QNN profiling"); + } + + result = InitializeProfiling(); + if (Status::OK() != result) { + ORT_THROW("Failed to Re-InitializeProfiling for QNN ETW profiling"); + } + } + return Status::OK(); +} + Status SetQnnContextConfig(ContextPriority context_priority, QnnContext_Config_t& qnn_context_config) { qnn_context_config.option = QNN_CONTEXT_CONFIG_OPTION_PRIORITY; switch (context_priority) { diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h index 594c591f42375..18e4d7bdc905b 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h @@ -111,15 +111,15 @@ class QnnBackendManager { void SetLogger(const logging::Logger* logger) { if (logger_ == nullptr) { logger_ = logger; - InitializeQnnLog(); + (void)InitializeQnnLog(); } } - void InitializeQnnLog(); + Status InitializeQnnLog(); - void UpdateQnnLogLevel(logging::Severity ort_log_level); + Status UpdateQnnLogLevel(logging::Severity ort_log_level); - void ResetQnnLogLevel(); + Status ResetQnnLogLevel(); // Terminate logging in the backend Status TerminateQnnLog() { @@ -146,6 +146,8 @@ class QnnBackendManager { std::ofstream& outfile, bool backendSupportsExtendedEventData, bool tracelogging_provider_ep_enabled); + Status SetProfilingLevelETW(ProfilingLevel profiling_level_etw_param); + void SetQnnBackendType(uint32_t backend_id); QnnBackendType GetQnnBackendType() { return qnn_backend_type_; } diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc index fc737b566cd4d..582c11531467f 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.cc +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.cc @@ -160,6 +160,20 @@ static void ParseHtpArchitecture(const std::string& htp_arch_string, QnnHtpDevic } } +qnn::ProfilingLevel QNNExecutionProvider::GetProfilingLevelFromETWLevel(unsigned char level) { + if (level == 5) { + LOGS_DEFAULT(INFO) << "Overriding profiling to basic based on ETW level: " << static_cast(level); + return qnn::ProfilingLevel::BASIC; + } else if (level < 5) { + LOGS_DEFAULT(INFO) << "QNN Profiler ETW level not supported below level 5. Level: " + << static_cast(level); + return qnn::ProfilingLevel::OFF; + } else { + LOGS_DEFAULT(INFO) << "Overriding profiling to detailed based on ETW level: " << static_cast(level); + return qnn::ProfilingLevel::DETAILED; + } +} + QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_options_map, const SessionOptions* session_options) : IExecutionProvider{onnxruntime::kQnnExecutionProvider} { @@ -210,17 +224,7 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio 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); - profiling_level_etw = qnn::ProfilingLevel::BASIC; - } else if (level < 5) { - LOGS_DEFAULT(INFO) << "QNN Profiler ETW level not supported below level 5. Level: " - << static_cast(level); - profiling_level_etw = qnn::ProfilingLevel::OFF; - } else { - LOGS_DEFAULT(INFO) << "Overriding profiling to detailed based on ETW level: " << static_cast(level); - profiling_level_etw = qnn::ProfilingLevel::DETAILED; - } + profiling_level_etw = GetProfilingLevelFromETWLevel(level); } } } @@ -237,22 +241,32 @@ QNNExecutionProvider::QNNExecutionProvider(const ProviderOptions& provider_optio ULONGLONG MatchAllKeyword, PEVENT_FILTER_DESCRIPTOR FilterData, PVOID CallbackContext) { - (void)SourceId; - (void)Level; - (void)MatchAnyKeyword; - (void)MatchAllKeyword; - (void)FilterData; - (void)CallbackContext; + ORT_UNUSED_PARAMETER(SourceId); + ORT_UNUSED_PARAMETER(MatchAnyKeyword); + ORT_UNUSED_PARAMETER(MatchAllKeyword); + ORT_UNUSED_PARAMETER(FilterData); + ORT_UNUSED_PARAMETER(CallbackContext); if (IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { if ((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0) { auto ortETWSeverity = etwRegistrationManager.MapLevelToSeverity(); - qnn_backend_manager_->UpdateQnnLogLevel(ortETWSeverity); + (void)qnn_backend_manager_->UpdateQnnLogLevel(ortETWSeverity); + } + if ((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Profiling)) != 0) { + if (Level != 0) { + // Commenting out Dynamic QNN Profiling for now + // There seems to be a crash in 3rd party QC QnnHtp.dll with this. + // Repro Scenario - start ETW tracing prior to session creation. + // Then disable/enable ETW Tracing with the code below uncommented a few times + // auto profiling_level_etw = GetProfilingLevelFromETWLevel(Level); + // (void)qnn_backend_manager_->SetProfilingLevelETW(profiling_level_etw); + } } } if (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) { - qnn_backend_manager_->ResetQnnLogLevel(); + // (void)qnn_backend_manager_->SetProfilingLevelETW(qnn::ProfilingLevel::INVALID); + (void)qnn_backend_manager_->ResetQnnLogLevel(); } }); #endif diff --git a/onnxruntime/core/providers/qnn/qnn_execution_provider.h b/onnxruntime/core/providers/qnn/qnn_execution_provider.h index 82dceb8ae3973..a644f1c843e1f 100644 --- a/onnxruntime/core/providers/qnn/qnn_execution_provider.h +++ b/onnxruntime/core/providers/qnn/qnn_execution_provider.h @@ -70,6 +70,8 @@ class QNNExecutionProvider : public IExecutionProvider { void InitQnnGraphConfigs(qnn::QnnConfigsBuilder& configs_builder) const; + qnn::ProfilingLevel GetProfilingLevelFromETWLevel(unsigned char level); + private: qnn::HtpGraphFinalizationOptimizationMode htp_graph_finalization_opt_mode_ = qnn::HtpGraphFinalizationOptimizationMode::kDefault; std::unique_ptr qnn_backend_manager_; From 2eec678b7367d366fbcfedb56fc44e883176312b Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Thu, 2 May 2024 12:20:46 -0700 Subject: [PATCH 06/12] Fix build and spelling errors for PR --- onnxruntime/core/common/logging/logging.cc | 2 +- onnxruntime/core/platform/windows/telemetry.cc | 14 +++++++------- 2 files changed, 8 insertions(+), 8 deletions(-) diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 014316e46d3c9..9f930e3a182e8 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -266,7 +266,7 @@ std::unique_ptr EnhanceSinkWithEtw(std::unique_ptr existingSink, l // On non-Windows platforms, just return the existing logger (void)originalSeverity; (void)etwSeverity; - return existingLogger; + return existingSink; #endif // _WIN32 } diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index f3063219c7875..850f40e846248 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -216,17 +216,17 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio // build the strings we need - std::string domain_to_verison_string; + std::string domain_to_version_string; bool first = true; for (auto& i : domain_to_version_map) { if (first) { first = false; } else { - domain_to_verison_string += ','; + domain_to_version_string += ','; } - domain_to_verison_string += i.first; - domain_to_verison_string += '='; - domain_to_verison_string += std::to_string(i.second); + domain_to_version_string += i.first; + domain_to_version_string += '='; + domain_to_version_string += std::to_string(i.second); } std::string model_metadata_string; @@ -271,7 +271,7 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio TraceLoggingString(model_producer_version.c_str(), "modelProducerVersion"), TraceLoggingString(model_domain.c_str(), "modelDomain"), TraceLoggingBool(use_fp16, "usefp16"), - TraceLoggingString(domain_to_verison_string.c_str(), "domainToVersionMap"), + TraceLoggingString(domain_to_version_string.c_str(), "domainToVersionMap"), TraceLoggingString(model_graph_name.c_str(), "modelGraphName"), TraceLoggingString(model_metadata_string.c_str(), "modelMetaData"), TraceLoggingString(loaded_from.c_str(), "loadedFrom"), @@ -293,7 +293,7 @@ void WindowsTelemetry::LogSessionCreation(uint32_t session_id, int64_t ir_versio TraceLoggingString(model_producer_version.c_str(), "modelProducerVersion"), TraceLoggingString(model_domain.c_str(), "modelDomain"), TraceLoggingBool(use_fp16, "usefp16"), - TraceLoggingString(domain_to_verison_string.c_str(), "domainToVersionMap"), + TraceLoggingString(domain_to_version_string.c_str(), "domainToVersionMap"), TraceLoggingString(model_graph_name.c_str(), "modelGraphName"), TraceLoggingString(model_metadata_string.c_str(), "modelMetaData"), TraceLoggingString(loaded_from.c_str(), "loadedFrom"), From 7fdf2f566414fd975e59be05214aff493f5e86f7 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Thu, 2 May 2024 14:34:03 -0700 Subject: [PATCH 07/12] Fix PR compile error with WinML which does not seem to support dynamic_cast and RTTI. Instead use a custom type system on ISink that is safe for use with static_cast --- include/onnxruntime/core/common/logging/isink.h | 5 +++++ onnxruntime/core/common/logging/logging.cc | 13 ++++++------- .../core/common/logging/sinks/composite_sink.h | 2 ++ .../core/platform/windows/logging/etw_sink.h | 2 ++ .../providers/qnn/builder/qnn_backend_manager.cc | 2 +- 5 files changed, 16 insertions(+), 8 deletions(-) diff --git a/include/onnxruntime/core/common/logging/isink.h b/include/onnxruntime/core/common/logging/isink.h index a67777d4ccc8b..a7d64a310fbcf 100644 --- a/include/onnxruntime/core/common/logging/isink.h +++ b/include/onnxruntime/core/common/logging/isink.h @@ -13,6 +13,11 @@ class ISink { public: ISink() = default; + enum SinkType { BaseSink, + CompositeSink, + EtwSink }; + virtual SinkType GetType() const { return BaseSink; } + /** Sends the message to the sink. @param timestamp The timestamp. diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 9f930e3a182e8..e9b61e80f46a1 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -291,13 +291,11 @@ void LoggingManager::AddEtwSink(logging::Severity etwSeverity) { return; // ETW not enabled, no operation needed } - CompositeSink* current_composite = dynamic_cast(sink_.get()); - if (!current_composite) { + if (sink_->GetType() != ISink::CompositeSink) { // Current sink is not a composite, create a new composite sink and add the current sink to it auto new_composite = std::make_unique(); new_composite->AddSink(std::move(sink_), default_min_severity_); // Move the current sink into the new composite sink_ = std::move(new_composite); // Now sink_ is pointing to the new composite - current_composite = static_cast(sink_.get()); // Update pointer to the new composite sink } // Adjust the default minimum severity level to accommodate ETW logging needs @@ -306,10 +304,11 @@ void LoggingManager::AddEtwSink(logging::Severity etwSeverity) { s_default_logger_->SetSeverity(default_min_severity_); } + CompositeSink* current_composite = static_cast(sink_.get()); // Check if an EtwSink already exists in the current composite const auto& sinks = current_composite->GetSinks(); if (std::any_of(sinks.begin(), sinks.end(), [](const auto& pair) { - return dynamic_cast(pair.first.get()) != nullptr; + return pair.first->GetType() == ISink::EtwSink; })) { return; // EtwSink already exists, do not add another } @@ -320,16 +319,16 @@ void LoggingManager::AddEtwSink(logging::Severity etwSeverity) { void LoggingManager::RemoveEtwSink() { std::lock_guard guard(sink_mutex_); - auto composite_sink = dynamic_cast(sink_.get()); - if (composite_sink) { + if (sink_->GetType() == ISink::CompositeSink) { + auto composite_sink = static_cast(sink_.get()); const auto& sinks_with_severity = composite_sink->GetSinks(); std::unique_ptr remaining_sink; Severity newSeverity = Severity::kFATAL; for (const auto& sink_pair : sinks_with_severity) { - if (dynamic_cast(sink_pair.first.get()) == nullptr) { + if (sink_pair.first->GetType() != ISink::EtwSink) { if (remaining_sink) { // If more than one non-EtwSink is found, we leave the CompositeSink intact return; diff --git a/onnxruntime/core/common/logging/sinks/composite_sink.h b/onnxruntime/core/common/logging/sinks/composite_sink.h index 9d18eb527ffdd..832e0327d23b9 100644 --- a/onnxruntime/core/common/logging/sinks/composite_sink.h +++ b/onnxruntime/core/common/logging/sinks/composite_sink.h @@ -25,6 +25,8 @@ class CompositeSink : public ISink { /// CompositeSink() {} + SinkType GetType() const override { return ISink::CompositeSink; } + /// /// Adds a sink. Takes ownership of the sink (so pass unique_ptr by value). /// diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index 143c3fcfdfc52..4efa6ed4e32df 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.h +++ b/onnxruntime/core/platform/windows/logging/etw_sink.h @@ -34,6 +34,8 @@ class EtwSink : public ISink { EtwSink() = default; ~EtwSink() = default; + SinkType GetType() const override { return ISink::EtwSink; } + constexpr static const char* kEventName = "ONNXRuntimeLogEvent"; private: diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index b6bc34964c8bd..75ddc1b162759 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -317,7 +317,7 @@ QnnLog_Level_t QnnBackendManager::MapOrtSeverityToQNNLogLevel(logging::Severity Status QnnBackendManager::ResetQnnLogLevel() { auto ort_log_level = logger_->GetSeverity(); - LOGS(*logger_, INFO) << "Reset Qnn log level to ORT Logger level: " << (UINT)ort_log_level; + LOGS(*logger_, INFO) << "Reset Qnn log level to ORT Logger level: " << (unsigned int)ort_log_level; return UpdateQnnLogLevel(ort_log_level); } From 24255674f73922575bf0f36ebd525ec683ef4395 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Wed, 29 May 2024 11:14:00 -0700 Subject: [PATCH 08/12] Per PR comment - revert to original behavior of always logging QNN EP events as ORT verbose. This is to preserve existing expected behavior by some customers. It also unfortunately means the only pratical method to get any QNN logs is to fully set the level to VERBOSE --- .../qnn/builder/qnn_backend_manager.cc | 20 ++----------------- 1 file changed, 2 insertions(+), 18 deletions(-) diff --git a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index 75ddc1b162759..3826efc781a4f 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -234,29 +234,13 @@ void QnnLogging(const char* format, QnnLog_Level_t level, uint64_t timestamp, va_list argument_parameter) { + ORT_UNUSED_PARAMETER(level); ORT_UNUSED_PARAMETER(timestamp); const auto& logger = ::onnxruntime::logging::LoggingManager::DefaultLogger(); + const auto severity = ::onnxruntime::logging::Severity::kVERBOSE; const auto data_type = ::onnxruntime::logging::DataType::SYSTEM; - ::onnxruntime::logging::Severity severity; - switch (level) { - case QNN_LOG_LEVEL_ERROR: - severity = ::onnxruntime::logging::Severity::kERROR; - break; - case QNN_LOG_LEVEL_WARN: - severity = ::onnxruntime::logging::Severity::kWARNING; - break; - case QNN_LOG_LEVEL_INFO: - severity = ::onnxruntime::logging::Severity::kINFO; - break; - case QNN_LOG_LEVEL_VERBOSE: - case QNN_LOG_LEVEL_DEBUG: // Treat DEBUG as VERBOSE in ORT - default: - severity = ::onnxruntime::logging::Severity::kVERBOSE; - break; - } - if (logger.OutputIsEnabled(severity, data_type)) { ::onnxruntime::logging::Capture(logger, severity, From 0e523c7056645123efaced6635e381a7581f9045 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Tue, 4 Jun 2024 11:42:54 -0700 Subject: [PATCH 09/12] Address PR comments --- .../onnxruntime/core/common/logging/isink.h | 10 ++--- .../onnxruntime/core/common/logging/logging.h | 13 +++--- .../core/common/logging/sink_types.h | 11 +++++ onnxruntime/core/common/logging/logging.cc | 41 ++++++++----------- .../common/logging/sinks/composite_sink.h | 4 +- .../core/platform/windows/logging/etw_sink.h | 4 +- onnxruntime/core/session/inference_session.cc | 14 +++++-- 7 files changed, 51 insertions(+), 46 deletions(-) create mode 100644 include/onnxruntime/core/common/logging/sink_types.h diff --git a/include/onnxruntime/core/common/logging/isink.h b/include/onnxruntime/core/common/logging/isink.h index a7d64a310fbcf..fd011e71611fc 100644 --- a/include/onnxruntime/core/common/logging/isink.h +++ b/include/onnxruntime/core/common/logging/isink.h @@ -6,17 +6,15 @@ #include #include "core/common/logging/logging.h" +#include "core/common/logging/sink_types.h" namespace onnxruntime { namespace logging { class ISink { public: - ISink() = default; + explicit ISink(SinkType type = SinkType::BaseSink) : type_(type) {} - enum SinkType { BaseSink, - CompositeSink, - EtwSink }; - virtual SinkType GetType() const { return BaseSink; } + SinkType GetType() const { return type_; } /** Sends the message to the sink. @@ -37,6 +35,8 @@ class ISink { virtual ~ISink() = default; private: + SinkType type_; + // Make Code Analysis happy by disabling all for now. Enable as needed. ORT_DISALLOW_COPY_ASSIGNMENT_AND_MOVE(ISink); diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index c07a4e14a6bd3..6f8459599241b 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -16,6 +16,7 @@ #include "core/common/logging/capture.h" #include "core/common/logging/macros.h" #include "core/common/logging/severity.h" +#include "core/common/logging/sink_types.h" #include "core/platform/ort_mutex.h" #include "date/date.h" @@ -171,18 +172,16 @@ class LoggingManager final { */ static LoggingManager* GetDefaultInstance(); -#ifdef _WIN32 /** - Removes the ETW Sink if one is present + Removes a Sink if one is present */ - void RemoveEtwSink(); + void RemoveSink(SinkType sinkType); /** - Adds an ETW Sink to the current sink creating a CompositeSink if necessary - @param etwSeverity The severity level for the ETW Sink + Adds a Sink to the current sink creating a CompositeSink if necessary + @param severity The severity level for the new Sink */ - void AddEtwSink(logging::Severity etwSeverity); -#endif + void AddSink(SinkType sinkType, std::function()> sinkFactory, logging::Severity severity); /** Change the minimum severity level for log messages to be output by the default logger. diff --git a/include/onnxruntime/core/common/logging/sink_types.h b/include/onnxruntime/core/common/logging/sink_types.h new file mode 100644 index 0000000000000..a99b0fca58d9d --- /dev/null +++ b/include/onnxruntime/core/common/logging/sink_types.h @@ -0,0 +1,11 @@ +#pragma once + +namespace onnxruntime { +namespace logging { +enum class SinkType { + BaseSink, + CompositeSink, + EtwSink +}; +} // namespace logging +} // namespace onnxruntime diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index e9b61e80f46a1..eb171e0953fd6 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -281,46 +281,39 @@ Severity OverrideLevelWithEtw(Severity originalSeverity) { return originalSeverity; } -#ifdef _WIN32 -void LoggingManager::AddEtwSink(logging::Severity etwSeverity) { +void LoggingManager::AddSink(SinkType sinkType, std::function()> sinkFactory, logging::Severity severity) { std::lock_guard guard(sink_mutex_); - // Check if the EtwRegistrationManager is enabled - auto& manager = EtwRegistrationManager::Instance(); - if (!manager.IsEnabled()) { - return; // ETW not enabled, no operation needed - } - - if (sink_->GetType() != ISink::CompositeSink) { + if (sink_->GetType() != SinkType::CompositeSink) { // Current sink is not a composite, create a new composite sink and add the current sink to it auto new_composite = std::make_unique(); new_composite->AddSink(std::move(sink_), default_min_severity_); // Move the current sink into the new composite sink_ = std::move(new_composite); // Now sink_ is pointing to the new composite } - // Adjust the default minimum severity level to accommodate ETW logging needs - default_min_severity_ = std::min(default_min_severity_, etwSeverity); + // Adjust the default minimum severity level to accommodate new sink needs + default_min_severity_ = std::min(default_min_severity_, severity); if (s_default_logger_ != nullptr) { s_default_logger_->SetSeverity(default_min_severity_); } CompositeSink* current_composite = static_cast(sink_.get()); - // Check if an EtwSink already exists in the current composite const auto& sinks = current_composite->GetSinks(); - if (std::any_of(sinks.begin(), sinks.end(), [](const auto& pair) { - return pair.first->GetType() == ISink::EtwSink; + + // Check if a sink of this type already exists + if (std::any_of(sinks.begin(), sinks.end(), [sinkType](const auto& pair) { + return pair.first->GetType() == sinkType; })) { - return; // EtwSink already exists, do not add another + return; // Sink of this type already exists, do not add another } - // Add a new EtwSink - current_composite->AddSink(std::make_unique(), etwSeverity); + current_composite->AddSink(sinkFactory(), severity); } -void LoggingManager::RemoveEtwSink() { +void LoggingManager::RemoveSink(SinkType sinkType) { std::lock_guard guard(sink_mutex_); - if (sink_->GetType() == ISink::CompositeSink) { + if (sink_->GetType() == SinkType::CompositeSink) { auto composite_sink = static_cast(sink_.get()); const auto& sinks_with_severity = composite_sink->GetSinks(); std::unique_ptr remaining_sink; @@ -328,9 +321,9 @@ void LoggingManager::RemoveEtwSink() { Severity newSeverity = Severity::kFATAL; for (const auto& sink_pair : sinks_with_severity) { - if (sink_pair.first->GetType() != ISink::EtwSink) { + if (sink_pair.first->GetType() != sinkType) { if (remaining_sink) { - // If more than one non-EtwSink is found, we leave the CompositeSink intact + // If more than one non sinkType is found, we leave the CompositeSink intact return; } newSeverity = std::min(newSeverity, sink_pair.second); @@ -338,13 +331,12 @@ void LoggingManager::RemoveEtwSink() { } } - // If only one non-EtwSink remains, replace the CompositeSink with this sink + // If only one non sinkType remains, replace the CompositeSink with this sink if (remaining_sink) { sink_ = std::move(remaining_sink); } else { - // Handle the case where all sinks were EtwSinks - // sink_ = std::make_unique(); // Assuming NullSink is a basic ISink that does nothing + // Handle the case where all sinks were sinkType } default_min_severity_ = newSeverity; @@ -353,7 +345,6 @@ void LoggingManager::RemoveEtwSink() { } } } -#endif } // 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 832e0327d23b9..fd613f1fab98e 100644 --- a/onnxruntime/core/common/logging/sinks/composite_sink.h +++ b/onnxruntime/core/common/logging/sinks/composite_sink.h @@ -23,9 +23,7 @@ class CompositeSink : public ISink { /// Initializes a new instance of the class. /// Use AddSink to add sinks. /// - CompositeSink() {} - - SinkType GetType() const override { return ISink::CompositeSink; } + CompositeSink() : ISink(SinkType::CompositeSink) {} /// /// Adds a sink. Takes ownership of the sink (so pass unique_ptr by value). diff --git a/onnxruntime/core/platform/windows/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index 4efa6ed4e32df..5d35d101f1242 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.h +++ b/onnxruntime/core/platform/windows/logging/etw_sink.h @@ -31,11 +31,9 @@ namespace logging { class EtwSink : public ISink { public: - EtwSink() = default; + EtwSink() : ISink(SinkType::EtwSink) {} ~EtwSink() = default; - SinkType GetType() const override { return ISink::EtwSink; } - constexpr static const char* kEventName = "ONNXRuntimeLogEvent"; private: diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index f801929557d51..3386a6ed15d58 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -12,6 +12,7 @@ #include #include "core/common/denormal.h" +#include "core/common/logging/isink.h" #include "core/common/logging/logging.h" #include "core/common/parse_string.h" #include "core/common/path_string.h" @@ -52,6 +53,7 @@ #include "core/platform/tracing.h" #include #include "core/platform/windows/telemetry.h" +#include "core/platform/windows/logging/etw_sink.h" #endif #include "core/providers/cpu/controlflow/utils.h" #include "core/providers/cpu/cpu_execution_provider.h" @@ -420,13 +422,19 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, if ((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0 && IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { LOGS(*session_logger_, VERBOSE) << "Adding ETW Sink to logger with severity level: " << (ULONG)ortETWSeverity; - logging_manager_->AddEtwSink(ortETWSeverity); - onnxruntime::logging::LoggingManager::GetDefaultInstance()->AddEtwSink(ortETWSeverity); + logging_manager_->AddSink( + onnxruntime::logging::SinkType::EtwSink, + []() -> std::unique_ptr { return std::make_unique(); }, + ortETWSeverity); + onnxruntime::logging::LoggingManager::GetDefaultInstance()->AddSink( + onnxruntime::logging::SinkType::EtwSink, + []() -> std::unique_ptr { return std::make_unique(); }, + ortETWSeverity); LOGS(*session_logger_, INFO) << "Done Adding ETW Sink to logger with severity level: " << (ULONG)ortETWSeverity; } if (IsEnabled == EVENT_CONTROL_CODE_DISABLE_PROVIDER) { LOGS(*session_logger_, INFO) << "Removing ETW Sink from logger"; - logging_manager_->RemoveEtwSink(); + logging_manager_->RemoveSink(onnxruntime::logging::SinkType::EtwSink); LOGS(*session_logger_, VERBOSE) << "Done Removing ETW Sink from logger"; } } From 3205bab6b4e8c3b9a4ff27bf8cd9c8c0e1e9f461 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Tue, 4 Jun 2024 11:53:40 -0700 Subject: [PATCH 10/12] Attempt to fix Linux build error with missing CompositeSink --- onnxruntime/core/common/logging/logging.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index eb171e0953fd6..9a9afd252aa50 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -9,11 +9,11 @@ #include "core/common/exceptions.h" #include "core/common/logging/isink.h" #include "core/common/logging/logging.h" +#include "core/common/logging/sinks/composite_sink.h" #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) From bda6b3b6ab65d61891a8c4d1db2c8e5cc5130ebb Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Wed, 5 Jun 2024 11:29:11 -0700 Subject: [PATCH 11/12] Address more PR comments --- onnxruntime/core/common/logging/logging.cc | 61 ++++++------------- .../common/logging/sinks/composite_sink.h | 55 +++++++++++++++-- onnxruntime/test/common/logging/helpers.h | 10 +++ onnxruntime/test/common/logging/sinks_test.cc | 59 +++++++++++++++++- 4 files changed, 136 insertions(+), 49 deletions(-) diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 9a9afd252aa50..608340be456f5 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -250,27 +250,27 @@ unsigned int GetProcessId() { #endif } -std::unique_ptr EnhanceSinkWithEtw(std::unique_ptr existingSink, logging::Severity originalSeverity, - logging::Severity etwSeverity) { +std::unique_ptr EnhanceSinkWithEtw(std::unique_ptr existing_sink, logging::Severity original_severity, + logging::Severity etw_severity) { #ifdef _WIN32 auto& manager = EtwRegistrationManager::Instance(); if (manager.IsEnabled()) { auto compositeSink = std::make_unique(); - compositeSink->AddSink(std::move(existingSink), originalSeverity); - compositeSink->AddSink(std::make_unique(), etwSeverity); + compositeSink->AddSink(std::move(existing_sink), original_severity); + compositeSink->AddSink(std::make_unique(), etw_severity); return compositeSink; } else { - return existingSink; + return existing_sink; } #else // On non-Windows platforms, just return the existing logger - (void)originalSeverity; - (void)etwSeverity; - return existingSink; + (void)original_severity; + (void)etw_severity; + return existing_sink; #endif // _WIN32 } -Severity OverrideLevelWithEtw(Severity originalSeverity) { +Severity OverrideLevelWithEtw(Severity original_severity) { #ifdef _WIN32 auto& manager = logging::EtwRegistrationManager::Instance(); if (manager.IsEnabled() && @@ -278,65 +278,40 @@ Severity OverrideLevelWithEtw(Severity originalSeverity) { return manager.MapLevelToSeverity(); } #endif // _WIN32 - return originalSeverity; + return original_severity; } -void LoggingManager::AddSink(SinkType sinkType, std::function()> sinkFactory, logging::Severity severity) { +void LoggingManager::AddSink(SinkType sink_type, std::function()> sinkFactory, + logging::Severity severity) { std::lock_guard guard(sink_mutex_); - if (sink_->GetType() != SinkType::CompositeSink) { // Current sink is not a composite, create a new composite sink and add the current sink to it auto new_composite = std::make_unique(); new_composite->AddSink(std::move(sink_), default_min_severity_); // Move the current sink into the new composite sink_ = std::move(new_composite); // Now sink_ is pointing to the new composite } - // Adjust the default minimum severity level to accommodate new sink needs default_min_severity_ = std::min(default_min_severity_, severity); if (s_default_logger_ != nullptr) { s_default_logger_->SetSeverity(default_min_severity_); } - CompositeSink* current_composite = static_cast(sink_.get()); - const auto& sinks = current_composite->GetSinks(); - - // Check if a sink of this type already exists - if (std::any_of(sinks.begin(), sinks.end(), [sinkType](const auto& pair) { - return pair.first->GetType() == sinkType; - })) { + if (current_composite->HasType(sink_type)) { return; // Sink of this type already exists, do not add another } - - current_composite->AddSink(sinkFactory(), severity); } -void LoggingManager::RemoveSink(SinkType sinkType) { +void LoggingManager::RemoveSink(SinkType sink_type) { std::lock_guard guard(sink_mutex_); if (sink_->GetType() == SinkType::CompositeSink) { auto composite_sink = static_cast(sink_.get()); - const auto& sinks_with_severity = composite_sink->GetSinks(); - std::unique_ptr remaining_sink; - - Severity newSeverity = Severity::kFATAL; - - for (const auto& sink_pair : sinks_with_severity) { - if (sink_pair.first->GetType() != sinkType) { - if (remaining_sink) { - // If more than one non sinkType is found, we leave the CompositeSink intact - return; - } - newSeverity = std::min(newSeverity, sink_pair.second); - remaining_sink = std::move(const_cast&>(sink_pair.first)); - } - } - // If only one non sinkType remains, replace the CompositeSink with this sink - if (remaining_sink) { - sink_ = std::move(remaining_sink); + Severity newSeverity = composite_sink->RemoveSink(sink_type); - } else { - // Handle the case where all sinks were sinkType + if (composite_sink->HasOnlyOneSink()) { + // If only one sink remains, replace the CompositeSink with this single sink + sink_ = composite_sink->GetRemoveSingleSink(); } default_min_severity_ = newSeverity; diff --git a/onnxruntime/core/common/logging/sinks/composite_sink.h b/onnxruntime/core/common/logging/sinks/composite_sink.h index fd613f1fab98e..e4a85f7d556bc 100644 --- a/onnxruntime/core/common/logging/sinks/composite_sink.h +++ b/onnxruntime/core/common/logging/sinks/composite_sink.h @@ -25,6 +25,16 @@ class CompositeSink : public ISink { /// CompositeSink() : ISink(SinkType::CompositeSink) {} + /// + /// Check if the composite sink contains a sink of the specified type. + /// + bool HasType(SinkType sink_type) const { + return std::any_of(sinks_with_severity_.begin(), sinks_with_severity_.end(), + [&](const auto& sink_pair) { + return sink_pair.first->GetType() == sink_type; + }); + } + /// /// Adds a sink. Takes ownership of the sink (so pass unique_ptr by value). /// @@ -37,11 +47,48 @@ class CompositeSink : public ISink { } /// - /// Gets a const reference to the collection of sinks and min severity for that sink + /// Remove a sink of the specified type. + /// + /// Sink type to remove + /// Minimum severity of the remaining sinks + logging::Severity RemoveSink(SinkType sink_type) { + logging::Severity severity = Severity::kFATAL; // default if we end up with no sinks + + // find entries to remove and the minimum severity of the remaining sinks + auto entries_to_remove = std::remove_if(sinks_with_severity_.begin(), sinks_with_severity_.end(), + [&](const auto& entry) { + if (entry.first->GetType() == sink_type) { + return true; + } else { + severity = std::min(severity, entry.second); + return false; + } + }); + + sinks_with_severity_.erase(entries_to_remove, sinks_with_severity_.end()); + + return severity; + } + + /// + /// Check if there's only one sink left + /// + /// True if only 1 sink remaining + bool HasOnlyOneSink() const { + return sinks_with_severity_.size() == 1; + } + + /// + /// If one sink is remaining then returns it and empties the composite 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_; + /// If one sink remains then returns the sink, otherwise nullptr + std::unique_ptr GetRemoveSingleSink() { + if (HasOnlyOneSink()) { + auto single_sink = std::move(sinks_with_severity_.begin()->first); + sinks_with_severity_.clear(); + return single_sink; + } + return nullptr; } private: diff --git a/onnxruntime/test/common/logging/helpers.h b/onnxruntime/test/common/logging/helpers.h index 7fd03b72e53a4..0b623fe9ee09a 100644 --- a/onnxruntime/test/common/logging/helpers.h +++ b/onnxruntime/test/common/logging/helpers.h @@ -18,6 +18,16 @@ class MockSink : public ::onnxruntime::logging::ISink { const ::onnxruntime::logging::Capture& message)); }; +class MockEtwSink : public ::onnxruntime::logging::ISink { + public: + MockEtwSink() : ISink(onnxruntime::logging::SinkType::EtwSink) {} + ~MockEtwSink() = default; + + MOCK_METHOD3(SendImpl, void(const ::onnxruntime::logging::Timestamp& timestamp, + const std::string& logger_id, + const ::onnxruntime::logging::Capture& message)); +}; + // The ACTION*() macros trigger warning C4100 (unreferenced formal // parameter) in MSVC with -W4. Unfortunately they cannot be fixed in // the macro definition, as the warnings are generated when the macro diff --git a/onnxruntime/test/common/logging/sinks_test.cc b/onnxruntime/test/common/logging/sinks_test.cc index 7ca8d5fc1152c..4f83ceaadf95d 100644 --- a/onnxruntime/test/common/logging/sinks_test.cc +++ b/onnxruntime/test/common/logging/sinks_test.cc @@ -144,8 +144,8 @@ TEST(LoggingTests, TestFileSink) { /// /// Tests that a composite_sink works correctly. /// -TEST(LoggingTests, TestCompositeSink) { - const std::string logid{"TestCompositeSink"}; +TEST(LoggingTests, TestCompositeSinkBasic) { + const std::string logid{"TestCompositeSinkBasic"}; const Severity min_log_level = Severity::kWARNING; MockSink* sink_ptr1 = new MockSink(); @@ -163,3 +163,58 @@ TEST(LoggingTests, TestCompositeSink) { LOGS_CATEGORY(*logger, WARNING, "ArbitraryCategory") << "Warning"; } + +/// +/// Tests that removing a sink of a specific type correctly updates the composite sink. +/// +TEST(LoggingTests, TestRemoveSink) { + CompositeSink sink; + MockSink* mock_sink1 = new MockSink(); + MockEtwSink* mock_sink2 = new MockEtwSink(); + sink.AddSink(std::unique_ptr(mock_sink1), Severity::kWARNING); + sink.AddSink(std::unique_ptr(mock_sink2), Severity::kERROR); + + // Set expectations that no SendImpl will be called on the removed sink + EXPECT_CALL(*mock_sink1, SendImpl(testing::_, testing::_, testing::_)).Times(0); + + // Remove the sink and check severity update + auto new_severity = sink.RemoveSink(SinkType::EtwSink); + EXPECT_EQ(new_severity, Severity::kERROR); // assuming mock_sink1 had SpecificType and was removed + + // Verify that sink2 is still in the composite + EXPECT_TRUE(sink.HasType(SinkType::BaseSink)); +} + +/// +/// Tests the HasOnlyOneSink method to ensure it correctly identifies when one sink is left. +/// +TEST(LoggingTests, TestHasOnlyOneSink) { + CompositeSink sink; + sink.AddSink(std::unique_ptr(new MockEtwSink()), Severity::kWARNING); + sink.AddSink(std::unique_ptr(new MockSink()), Severity::kERROR); + + EXPECT_FALSE(sink.HasOnlyOneSink()); + + sink.RemoveSink(SinkType::EtwSink); + EXPECT_TRUE(sink.HasOnlyOneSink()); + + sink.RemoveSink(SinkType::BaseSink); // Remove the last one + EXPECT_FALSE(sink.HasOnlyOneSink()); +} + +/// +/// Tests the GetRemoveSingleSink method to ensure it returns the last sink and empties the composite sink. +/// +TEST(LoggingTests, TestGetRemoveSingleSink) { + CompositeSink sink; + auto* single_mock_sink = new MockSink(); + sink.AddSink(std::unique_ptr(single_mock_sink), Severity::kWARNING); + + // Check we have one sink + EXPECT_TRUE(sink.HasOnlyOneSink()); + + // Get and remove the single sink + auto removed_sink = sink.GetRemoveSingleSink(); + EXPECT_EQ(removed_sink.get(), single_mock_sink); // Check it's the same sink + EXPECT_FALSE(sink.HasOnlyOneSink()); // Should be empty now +} From a5acd4c238c2484f25a3bce0e09ea9a5617371e1 Mon Sep 17 00:00:00 2001 From: Ivan Berg Date: Thu, 6 Jun 2024 13:05:38 -0700 Subject: [PATCH 12/12] Address PR comment. Rename to clarify. Fix sink UT. Re-test all ETW tracing scenarios --- include/onnxruntime/core/common/logging/logging.h | 3 ++- onnxruntime/core/common/logging/logging.cc | 9 ++++++--- onnxruntime/core/session/inference_session.cc | 4 ++-- onnxruntime/test/common/logging/sinks_test.cc | 2 +- 4 files changed, 11 insertions(+), 7 deletions(-) diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index 6f8459599241b..55b5c25d1a222 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -179,9 +179,10 @@ class LoggingManager final { /** Adds a Sink to the current sink creating a CompositeSink if necessary + Sinks types must be unique @param severity The severity level for the new Sink */ - void AddSink(SinkType sinkType, std::function()> sinkFactory, logging::Severity severity); + bool AddSinkOfType(SinkType sinkType, std::function()> sinkFactory, logging::Severity severity); /** Change the minimum severity level for log messages to be output by the default logger. diff --git a/onnxruntime/core/common/logging/logging.cc b/onnxruntime/core/common/logging/logging.cc index 608340be456f5..ad6f666a2d989 100644 --- a/onnxruntime/core/common/logging/logging.cc +++ b/onnxruntime/core/common/logging/logging.cc @@ -281,8 +281,8 @@ Severity OverrideLevelWithEtw(Severity original_severity) { return original_severity; } -void LoggingManager::AddSink(SinkType sink_type, std::function()> sinkFactory, - logging::Severity severity) { +bool LoggingManager::AddSinkOfType(SinkType sink_type, std::function()> sinkFactory, + logging::Severity severity) { std::lock_guard guard(sink_mutex_); if (sink_->GetType() != SinkType::CompositeSink) { // Current sink is not a composite, create a new composite sink and add the current sink to it @@ -297,8 +297,11 @@ void LoggingManager::AddSink(SinkType sink_type, std::function(sink_.get()); if (current_composite->HasType(sink_type)) { - return; // Sink of this type already exists, do not add another + return false; // Sink of this type already exists, do not add another } + + current_composite->AddSink(sinkFactory(), severity); + return true; } void LoggingManager::RemoveSink(SinkType sink_type) { diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 3386a6ed15d58..bf06ea4580f8a 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -422,11 +422,11 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, if ((MatchAnyKeyword & static_cast(onnxruntime::logging::ORTTraceLoggingKeyword::Logs)) != 0 && IsEnabled == EVENT_CONTROL_CODE_ENABLE_PROVIDER) { LOGS(*session_logger_, VERBOSE) << "Adding ETW Sink to logger with severity level: " << (ULONG)ortETWSeverity; - logging_manager_->AddSink( + logging_manager_->AddSinkOfType( onnxruntime::logging::SinkType::EtwSink, []() -> std::unique_ptr { return std::make_unique(); }, ortETWSeverity); - onnxruntime::logging::LoggingManager::GetDefaultInstance()->AddSink( + onnxruntime::logging::LoggingManager::GetDefaultInstance()->AddSinkOfType( onnxruntime::logging::SinkType::EtwSink, []() -> std::unique_ptr { return std::make_unique(); }, ortETWSeverity); diff --git a/onnxruntime/test/common/logging/sinks_test.cc b/onnxruntime/test/common/logging/sinks_test.cc index 4f83ceaadf95d..ea6c34d0221d2 100644 --- a/onnxruntime/test/common/logging/sinks_test.cc +++ b/onnxruntime/test/common/logging/sinks_test.cc @@ -179,7 +179,7 @@ TEST(LoggingTests, TestRemoveSink) { // Remove the sink and check severity update auto new_severity = sink.RemoveSink(SinkType::EtwSink); - EXPECT_EQ(new_severity, Severity::kERROR); // assuming mock_sink1 had SpecificType and was removed + EXPECT_EQ(new_severity, Severity::kWARNING); // assuming mock_sink2 had SpecificType and was removed // Verify that sink2 is still in the composite EXPECT_TRUE(sink.HasType(SinkType::BaseSink));