diff --git a/include/onnxruntime/core/common/logging/isink.h b/include/onnxruntime/core/common/logging/isink.h index a67777d4ccc8b..fd011e71611fc 100644 --- a/include/onnxruntime/core/common/logging/isink.h +++ b/include/onnxruntime/core/common/logging/isink.h @@ -6,12 +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) {} + + SinkType GetType() const { return type_; } /** Sends the message to the sink. @@ -32,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 f62053a5e44ab..55b5c25d1a222 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -14,10 +14,10 @@ #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/common/logging/sink_types.h" +#include "core/platform/ort_mutex.h" #include "date/date.h" /* @@ -167,6 +167,23 @@ class LoggingManager final { */ static bool HasDefaultLogger() { return nullptr != s_default_logger_; } + /** + Gets the default instance of the LoggingManager. + */ + static LoggingManager* GetDefaultInstance(); + + /** + Removes a Sink if one is present + */ + void RemoveSink(SinkType sinkType); + + /** + 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 + */ + 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. @param severity The severity. @@ -214,7 +231,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,8 +382,8 @@ unsigned int GetProcessId(); /** If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then adds to the existing logger. */ -std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, logging::Severity originalSeverity, - logging::Severity etwSeverity); +std::unique_ptr EnhanceSinkWithEtw(std::unique_ptr existingSink, logging::Severity originalSeverity, + logging::Severity etwSeverity); /** If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then can override the logging level. 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 eac9a7fa08081..ad6f666a2d989 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) @@ -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) @@ -245,27 +250,27 @@ unsigned int GetProcessId() { #endif } -std::unique_ptr EnhanceLoggerWithEtw(std::unique_ptr existingLogger, 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(existingLogger), 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 existingLogger; + return existing_sink; } #else // On non-Windows platforms, just return the existing logger - (void)originalSeverity; - (void)etwSeverity; - return existingLogger; + (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() && @@ -273,7 +278,50 @@ Severity OverrideLevelWithEtw(Severity originalSeverity) { return manager.MapLevelToSeverity(); } #endif // _WIN32 - return originalSeverity; + return original_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 + 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()); + if (current_composite->HasType(sink_type)) { + 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) { + std::lock_guard guard(sink_mutex_); + + if (sink_->GetType() == SinkType::CompositeSink) { + auto composite_sink = static_cast(sink_.get()); + + Severity newSeverity = composite_sink->RemoveSink(sink_type); + + if (composite_sink->HasOnlyOneSink()) { + // If only one sink remains, replace the CompositeSink with this single sink + sink_ = composite_sink->GetRemoveSingleSink(); + } + + default_min_severity_ = newSeverity; + if (s_default_logger_ != nullptr) { + s_default_logger_->SetSeverity(default_min_severity_); + } + } } } // namespace logging diff --git a/onnxruntime/core/common/logging/sinks/composite_sink.h b/onnxruntime/core/common/logging/sinks/composite_sink.h index 9d18eb527ffdd..e4a85f7d556bc 100644 --- a/onnxruntime/core/common/logging/sinks/composite_sink.h +++ b/onnxruntime/core/common/logging/sinks/composite_sink.h @@ -23,7 +23,17 @@ class CompositeSink : public ISink { /// Initializes a new instance of the class. /// Use AddSink to add sinks. /// - CompositeSink() {} + 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/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/logging/etw_sink.h b/onnxruntime/core/platform/windows/logging/etw_sink.h index 143c3fcfdfc52..5d35d101f1242 100644 --- a/onnxruntime/core/platform/windows/logging/etw_sink.h +++ b/onnxruntime/core/platform/windows/logging/etw_sink.h @@ -31,7 +31,7 @@ namespace logging { class EtwSink : public ISink { public: - EtwSink() = default; + EtwSink() : ISink(SinkType::EtwSink) {} ~EtwSink() = default; constexpr static const char* kEventName = "ONNXRuntimeLogEvent"; diff --git a/onnxruntime/core/platform/windows/telemetry.cc b/onnxruntime/core/platform/windows/telemetry.cc index 654281d526e4d..850f40e846248 100644 --- a/onnxruntime/core/platform/windows/telemetry.cc +++ b/onnxruntime/core/platform/windows/telemetry.cc @@ -210,23 +210,23 @@ 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; // 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; @@ -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_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"), + 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_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"), + 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/providers/qnn/builder/qnn_backend_manager.cc b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc index f322a27da22ff..3826efc781a4f 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.cc @@ -237,10 +237,10 @@ void QnnLogging(const char* format, 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; + if (logger.OutputIsEnabled(severity, data_type)) { ::onnxruntime::logging::Capture(logger, severity, @@ -251,31 +251,77 @@ void QnnLogging(const char* format, } } -void QnnBackendManager::InitializeQnnLog() { +Status 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; + } + } + + 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) { + // 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; +} + +Status QnnBackendManager::ResetQnnLogLevel() { + auto ort_log_level = logger_->GetSeverity(); + LOGS(*logger_, INFO) << "Reset Qnn log level to ORT Logger level: " << (unsigned int)ort_log_level; + return UpdateQnnLogLevel(ort_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."; +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; + + // 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."; + } } + ORT_RETURN_IF(QNN_BACKEND_NO_ERROR != result, "Failed to set log level in Qnn backend"); + return Status::OK(); } Status QnnBackendManager::InitializeBackend() { @@ -422,6 +468,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 673e3c2f33d64..18e4d7bdc905b 100644 --- a/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h +++ b/onnxruntime/core/providers/qnn/builder/qnn_backend_manager.h @@ -111,11 +111,15 @@ class QnnBackendManager { void SetLogger(const logging::Logger* logger) { if (logger_ == nullptr) { logger_ = logger; - InitializeQnnLog(); + (void)InitializeQnnLog(); } } - void InitializeQnnLog(); + Status InitializeQnnLog(); + + Status UpdateQnnLogLevel(logging::Severity ort_log_level); + + Status ResetQnnLogLevel(); // Terminate logging in the backend Status TerminateQnnLog() { @@ -142,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_; } @@ -206,6 +212,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 235ea45cd4dde..582c11531467f 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"; @@ -155,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} { @@ -205,21 +224,53 @@ 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); } } } +#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) { + 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(); + (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) { + // (void)qnn_backend_manager_->SetProfilingLevelETW(qnn::ProfilingLevel::INVALID); + (void)qnn_backend_manager_->ResetQnnLogLevel(); + } + }); +#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/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_; diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index c1cd21570a6a4..bf06ea4580f8a 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" @@ -345,7 +347,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 +373,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 +396,49 @@ 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_->AddSinkOfType( + onnxruntime::logging::SinkType::EtwSink, + []() -> std::unique_ptr { return std::make_unique(); }, + ortETWSeverity); + onnxruntime::logging::LoggingManager::GetDefaultInstance()->AddSinkOfType( + 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_->RemoveSink(onnxruntime::logging::SinkType::EtwSink); + LOGS(*session_logger_, VERBOSE) << "Done Removing ETW Sink from logger"; + } + } + }); #endif SetLoggingManager(session_options, session_env); @@ -528,7 +575,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; @@ -2027,8 +2074,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."; } @@ -3169,9 +3216,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); } } diff --git a/onnxruntime/core/session/ort_env.cc b/onnxruntime/core/session/ort_env.cc index 331f1db26a029..3c178fd1e91d3 100644 --- a/onnxruntime/core/session/ort_env.cc +++ b/onnxruntime/core/session/ort_env.cc @@ -48,8 +48,8 @@ OrtEnv* OrtEnv::GetInstance(const OrtEnv::LoggingManagerConstructionInfo& lm_inf sink = MakePlatformDefaultLogSink(); } auto etwOverrideSeverity = logging::OverrideLevelWithEtw(static_cast(lm_info.default_warning_level)); - sink = EnhanceLoggerWithEtw(std::move(sink), static_cast(lm_info.default_warning_level), - etwOverrideSeverity); + sink = 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), false, 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..ea6c34d0221d2 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::kWARNING); // assuming mock_sink2 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 +} 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 +