Fully dynamic ETW controlled logging for ORT and QNN logs

include/onnxruntime/core/common/logging/isink.h

@@ -6,12 +6,15 @@
 #include <string>
 
 #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);
 

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,22 @@ 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
+     @param severity The severity level for the new Sink
+  */
+  void AddSink(SinkType sinkType, std::function<std::unique_ptr<ISink>()> 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 +230,10 @@ class LoggingManager final {
   void CreateDefaultLogger(const std::string& logger_id);
 
   std::unique_ptr<ISink> 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 +381,8 @@ unsigned int GetProcessId();
 /**
    If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then adds to the existing logger.
 */
-std::unique_ptr<ISink> EnhanceLoggerWithEtw(std::unique_ptr<ISink> existingLogger, logging::Severity originalSeverity,
-                                            logging::Severity etwSeverity);
+std::unique_ptr<ISink> EnhanceSinkWithEtw(std::unique_ptr<ISink> existingSink, logging::Severity originalSeverity,
+                                          logging::Severity etwSeverity);
 
 /**
   If the ONNXRuntimeTraceLoggingProvider ETW Provider is enabled, then can override the logging level.

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

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 <Windows.h>
 #include "core/platform/windows/logging/etw_sink.h"
-#include "core/common/logging/sinks/composite_sink.h"
 #else
 #include <unistd.h>
 #if defined(__MACH__) || defined(__wasm__) || defined(_AIX)
@@ -22,10 +22,10 @@
 #include <sys/syscall.h>
 #endif
 #endif
-#include "core/platform/ort_mutex.h"
 
 #if __FreeBSD__
 #include <sys/thr.h>  // Use thr_self() syscall under FreeBSD to get thread id
+#include "logging.h"
 #endif
 
 namespace onnxruntime {
@@ -52,7 +52,11 @@
   return default_instance;
 }
 
+LoggingManager* LoggingManager::GetDefaultInstance() {
+  return static_cast<LoggingManager*>(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
 #ifdef _MSC_VER
@@ -66,6 +70,7 @@
 }
 
 Logger* LoggingManager::s_default_logger_ = nullptr;
+OrtMutex sink_mutex_;
 
 #ifdef _MSC_VER
 #pragma warning(pop)
@@ -245,23 +250,23 @@
 #endif
 }
 
-std::unique_ptr<ISink> EnhanceLoggerWithEtw(std::unique_ptr<ISink> existingLogger, logging::Severity originalSeverity,
-                                            logging::Severity etwSeverity) {
+std::unique_ptr<ISink> EnhanceSinkWithEtw(std::unique_ptr<ISink> existingSink, logging::Severity originalSeverity,
+                                          logging::Severity etwSeverity) {
 #ifdef _WIN32
   auto& manager = EtwRegistrationManager::Instance();
   if (manager.IsEnabled()) {
     auto compositeSink = std::make_unique<CompositeSink>();
-    compositeSink->AddSink(std::move(existingLogger), originalSeverity);
+    compositeSink->AddSink(std::move(existingSink), originalSeverity);
     compositeSink->AddSink(std::make_unique<EtwSink>(), etwSeverity);
     return compositeSink;
   } else {
-    return existingLogger;
+    return existingSink;
   }
 #else
   // On non-Windows platforms, just return the existing logger
   (void)originalSeverity;
   (void)etwSeverity;
-  return existingLogger;
+  return existingSink;
 #endif  // _WIN32
 }
 
@@ -276,5 +281,70 @@
   return originalSeverity;
 }
 
+void LoggingManager::AddSink(SinkType sinkType, std::function<std::unique_ptr<ISink>()> sinkFactory, logging::Severity severity) {
+  std::lock_guard<OrtMutex> 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<CompositeSink>();
+    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<CompositeSink*>(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;
+      })) {
+    return;  // Sink of this type already exists, do not add another
+  }
+
+  current_composite->AddSink(sinkFactory(), severity);
+}
+
+void LoggingManager::RemoveSink(SinkType sinkType) {
+  std::lock_guard<OrtMutex> guard(sink_mutex_);
+
+  if (sink_->GetType() == SinkType::CompositeSink) {
+    auto composite_sink = static_cast<CompositeSink*>(sink_.get());
+    const auto& sinks_with_severity = composite_sink->GetSinks();
+    std::unique_ptr<ISink> 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<std::unique_ptr<ISink>&>(sink_pair.first));
+      }
+    }
+
+    // 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 sinkType
+    }
+
+    default_min_severity_ = newSeverity;
+    if (s_default_logger_ != nullptr) {
+      s_default_logger_->SetSeverity(default_min_severity_);
+    }
+  }
+}
+
 }  // namespace logging
 }  // namespace onnxruntime

onnxruntime/core/common/logging/sinks/composite_sink.h

@@ -23,7 +23,7 @@ class CompositeSink : public ISink {
   /// Initializes a new instance of the <see cref="CompositeSink"/> class.
   /// Use AddSink to add sinks.
   /// </summary>
-  CompositeSink() {}
+  CompositeSink() : ISink(SinkType::CompositeSink) {}
 
   /// <summary>
   /// Adds a sink. Takes ownership of the sink (so pass unique_ptr by value).

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<std::string, std::string>& model_metadata,
                                    const std::string& loadedFrom, const std::vector<std::string>& 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,

onnxruntime/core/platform/telemetry.h

@@ -60,7 +60,7 @@ class Telemetry {
                                   const std::string& model_graph_name,
                                   const std::unordered_map<std::string, std::string>& model_metadata,
                                   const std::string& loadedFrom, const std::vector<std::string>& 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;

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

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<std::string, std::string>& model_metadata,
                                           const std::string& loaded_from, const std::vector<std::string>& 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<uint64_t>(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<uint64_t>(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<uint64_t>(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,

onnxruntime/core/platform/windows/telemetry.h

@@ -51,7 +51,7 @@ class WindowsTelemetry : public Telemetry {
                           const std::string& model_graph_name,
                           const std::unordered_map<std::string, std::string>& model_metadata,
                           const std::string& loadedFrom, const std::vector<std::string>& 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;