Log out ORT session options (#16259)

### Description
Logs out ORT session options as INFO if LogSeverityLevel is set high
enough. Also log out ORT session options on Windows if the provider is
enabled. The events are not Telemetry are will be emitted for local
analysis (if enabled).
[Microsoft.ML.ONNXRuntime](https://github.com/microsoft/onnxruntime/blob/main/onnxruntime/core/platform/windows/telemetry.cc#L47)
- 3a26b1ff-7484-7484-7484-15261f42614d

### Motivation and Context
ORT session options are key to understanding ORT behavior. This allows
better diagnosability to see what the options are set to.

onnxruntime/core/common/path_string.h

@@ -13,6 +13,15 @@
 #include <cctype>
 #endif
 
+// for converting / printing ORT_TSTR path strings to std::string
+#ifdef _WIN32
+#define ORT_TSTR_CONVERT_TO_PRINTABLE_STRING(X) std::wstring_convert<std::codecvt_utf8<wchar_t>>().to_bytes(X)
+#define ORT_TSTR_CONVERT_FROM_STRING(X) std::wstring_convert<std::codecvt_utf8<wchar_t>>().from_bytes(X);
+#else
+#define ORT_TSTR_CONVERT_TO_PRINTABLE_STRING(X) X
+#define ORT_TSTR_CONVERT_FROM_STRING(X) X
+#endif
+
 #include "core/common/common.h"
 #include "core/session/onnxruntime_c_api.h"
 

onnxruntime/core/framework/config_options.cc

@@ -52,4 +52,11 @@ Status ConfigOptions::AddConfigEntry(const char* config_key, const char* config_
   return Status::OK();
 }
 
+std::ostream& operator<<(std::ostream& os, const ConfigOptions& config_options) {
+  for (const auto& [key, value] : config_options.configurations) {
+    os << "  " << key << ": " << value;
+  }
+  return os;
+}
+
 }  // namespace onnxruntime

onnxruntime/core/framework/config_options.h

@@ -32,6 +32,8 @@ struct ConfigOptions {
 
   // Add a config pair (config_key, config_value) to this instance of ConfigOptions
   Status AddConfigEntry(const char* config_key, const char* config_value) noexcept;
+
+  friend std::ostream& operator<<(std::ostream& os, const ConfigOptions& config_options);
 };
 
 }  // namespace onnxruntime

onnxruntime/core/framework/execution_providers.h

@@ -12,6 +12,9 @@
 #include "core/framework/execution_provider.h"
 #include "core/graph/graph_viewer.h"
 #include "core/common/logging/logging.h"
+#ifdef _WIN32
+#include "core/platform/tracing.h"
+#endif
 
 namespace onnxruntime {
 
@@ -36,7 +39,19 @@ class ExecutionProviders {
     ORT_IGNORE_RETURN_VALUE(provider_idx_map_.insert({provider_id, new_provider_idx}));
 
     // update execution provider options
-    exec_provider_options_[provider_id] = p_exec_provider->GetProviderOptions();
+    auto providerOptions = p_exec_provider->GetProviderOptions();
+    exec_provider_options_[provider_id] = providerOptions;
+
+#ifdef _WIN32
+    for (const auto& config_pair : providerOptions) {
+      TraceLoggingWrite(
+          telemetry_provider_handle,
+          "ProviderOptions",
+          TraceLoggingString(provider_id.c_str(), "ProviderId"),
+          TraceLoggingString(config_pair.first.c_str(), "Key"),
+          TraceLoggingString(config_pair.second.c_str(), "Value"));
+    }
+#endif
 
     exec_provider_ids_.push_back(provider_id);
     exec_providers_.push_back(p_exec_provider);

onnxruntime/core/framework/session_options.h

@@ -5,6 +5,8 @@
 
 #include <string>
 #include <vector>
+#include <iostream>
+#include <codecvt>
 #include "core/common/gsl.h"
 #include "core/common/inlined_containers.h"
 #include "core/framework/config_options.h"
@@ -24,6 +26,21 @@ enum class ExecutionOrder {
   PRIORITY_BASED = 1  // priority-based topological sort
 };
 
+inline std::ostream& operator<<(std::ostream& os, const ExecutionOrder& order) {
+  switch (order) {
+    case ExecutionOrder::DEFAULT:
+      os << "DEFAULT";
+      break;
+    case ExecutionOrder::PRIORITY_BASED:
+      os << "PRIORITY_BASED";
+      break;
+    default:
+      os << "UNKNOWN";
+      break;
+  }
+  return os;
+}
+
 enum class FreeDimensionOverrideType {
   Invalid = 0,
   Denotation = 1,
@@ -89,6 +106,7 @@ struct SessionOptions {
 
   /// Log severity for the inference session. Applies to session load, initialization, etc.
   /// See https://github.com/microsoft/onnxruntime/blob/main/include/onnxruntime/core/common/logging/severity.h
+  /// See https://github.com/microsoft/onnxruntime/blob/main/include/onnxruntime/core/session/onnxruntime_c_api.h#L231 for OrtLoggingLevel mappings
   /// Default = -1 (use default logger severity)
   int session_log_severity_level = -1;
   int session_log_verbosity_level = 0;  ///< VLOG level if debug build and session_log_severity_level is 0 (VERBOSE).
@@ -154,4 +172,37 @@ struct SessionOptions {
   void* user_logging_param = nullptr;
 };
 
+inline std::ostream& operator<<(std::ostream& os, const SessionOptions& session_options) {
+  os << "Session Options { "
+     << " execution_mode:" << session_options.execution_mode
+     << " execution_order:" << session_options.execution_order
+     << " enable_profiling:" << session_options.enable_profiling
+     << " optimized_model_filepath:" << ORT_TSTR_CONVERT_TO_PRINTABLE_STRING(session_options.optimized_model_filepath)
+     << " enable_mem_pattern:" << session_options.enable_mem_pattern
+     << " enable_mem_reuse:" << session_options.enable_mem_reuse
+     << " enable_cpu_mem_arena:" << session_options.enable_cpu_mem_arena
+     << " profile_file_prefix:" << ORT_TSTR_CONVERT_TO_PRINTABLE_STRING(session_options.profile_file_prefix)
+     << " session_logid:" << session_options.session_logid
+     << " session_log_severity_level:" << session_options.session_log_severity_level
+     << " session_log_verbosity_level:" << session_options.session_log_verbosity_level
+     << " max_num_graph_transformation_steps:" << session_options.max_num_graph_transformation_steps
+     << " graph_optimization_level:" << static_cast<int>(session_options.graph_optimization_level)
+     << " intra_op_param:" << session_options.intra_op_param
+     << " inter_op_param:" << session_options.inter_op_param
+     //<< " free_dimension_overrides:"           << session_options.free_dimension_overrides
+     << " use_per_session_threads:" << session_options.use_per_session_threads
+     << " thread_pool_allow_spinning:" << session_options.thread_pool_allow_spinning
+     << " use_deterministic_compute:" << session_options.use_deterministic_compute
+     << " config_options: { " << session_options.config_options << " }"
+  //<< " initializers_to_share_map:"          << session_options.initializers_to_share_map
+#if !defined(ORT_MINIMAL_BUILD) && !defined(DISABLE_EXTERNAL_INITIALIZERS)
+  //<< " external_initializers:"             << session_options.external_initializers
+#endif
+#if !defined(ORT_MINIMAL_BUILD) || defined(ORT_MINIMAL_BUILD_CUSTOM_OPS)
+  //<< " custom_op_libs:" << session_options.custom_op_libs
+#endif
+     << " }";
+  return os;
+}
+
 }  // namespace onnxruntime

onnxruntime/core/session/inference_session.cc

@@ -48,6 +48,9 @@
 #include "core/platform/Barrier.h"
 #include "core/platform/ort_mutex.h"
 #include "core/platform/threadpool.h"
+#ifdef _WIN32
+#include "core/platform/tracing.h"
+#endif
 #include "core/providers/cpu/controlflow/utils.h"
 #include "core/providers/cpu/cpu_execution_provider.h"
 #ifdef USE_DML  // TODO: This is necessary for the workaround in TransformGraph
@@ -344,6 +347,7 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options,
   // The call to InitLogger depends on the final state of session_options_. Hence it should be invoked
   // after the invocation of FinalizeSessionOptions.
   InitLogger(logging_manager_);  // this sets session_logger_ so that it can be used for logging after this point.
+  TraceSessionOptions(session_options);
 
 #if !defined(ORT_MINIMAL_BUILD)
   // Update the number of steps for the graph transformer manager using the "finalized" session options
@@ -457,6 +461,50 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options,
   telemetry_ = {};
 }
 
+void InferenceSession::TraceSessionOptions(const SessionOptions& session_options) {
+  LOGS(*session_logger_, INFO) << session_options;
+
+#ifdef _WIN32
+  TraceLoggingWrite(telemetry_provider_handle,
+                    "SessionOptions",
+                    TraceLoggingUInt8(static_cast<UINT8>(session_options.execution_mode), "execution_mode"),
+                    TraceLoggingUInt8(static_cast<UINT8>(session_options.execution_order), "execution_order"),
+                    TraceLoggingBoolean(session_options.enable_profiling, "enable_profiling"),
+                    TraceLoggingString(ORT_TSTR_CONVERT_TO_PRINTABLE_STRING(session_options.optimized_model_filepath).c_str(), "optimized_model_filepath"),
+                    TraceLoggingBoolean(session_options.enable_mem_pattern, "enable_mem_pattern"),
+                    TraceLoggingBoolean(session_options.enable_mem_reuse, "enable_mem_reuse"),
+                    TraceLoggingBoolean(session_options.enable_cpu_mem_arena, "enable_cpu_mem_arena"),
+                    TraceLoggingString(ORT_TSTR_CONVERT_TO_PRINTABLE_STRING(session_options.profile_file_prefix).c_str(), "profile_file_prefix"),
+                    TraceLoggingString(session_options.session_logid.c_str(), "session_logid"),
+                    TraceLoggingInt8(static_cast<INT8>(session_options.session_log_severity_level), "session_log_severity_level"),
+                    TraceLoggingInt8(static_cast<INT8>(session_options.session_log_verbosity_level), "session_log_verbosity_level"),
+                    TraceLoggingUInt32(session_options.max_num_graph_transformation_steps, "max_num_graph_transformation_steps"),
+                    TraceLoggingUInt8(static_cast<UINT8>(session_options.graph_optimization_level), "graph_optimization_level"),
+                    TraceLoggingBoolean(session_options.use_per_session_threads, "use_per_session_threads"),
+                    TraceLoggingBoolean(session_options.thread_pool_allow_spinning, "thread_pool_allow_spinning"),
+                    TraceLoggingBoolean(session_options.use_deterministic_compute, "use_deterministic_compute"));
+
+  TraceLoggingWrite(
+      telemetry_provider_handle,
+      "SessionOptions_IntraOrtThreadPoolParams",
+      TraceLoggingInt32(session_options.intra_op_param.thread_pool_size, "thread_pool_size"),
+      TraceLoggingBoolean(session_options.intra_op_param.auto_set_affinity, "auto_set_affinity"),
+      TraceLoggingBoolean(session_options.intra_op_param.allow_spinning, "allow_spinning"),
+      TraceLoggingInt32(session_options.intra_op_param.dynamic_block_base_, "dynamic_block_base_"),
+      TraceLoggingUInt32(session_options.intra_op_param.stack_size, "stack_size"),
+      TraceLoggingString(!session_options.intra_op_param.affinity_str.empty() ? session_options.intra_op_param.affinity_str.c_str() : "", "affinity_str"),
+      TraceLoggingBoolean(session_options.intra_op_param.set_denormal_as_zero, "set_denormal_as_zero"));
+
+  for (const auto& config_pair : session_options.config_options.configurations) {
+    TraceLoggingWrite(
+        telemetry_provider_handle,
+        "SessionOptions_ConfigEntry",
+        TraceLoggingString(config_pair.first.c_str(), "Key"),
+        TraceLoggingString(config_pair.second.c_str(), "Value"));
+  }
+#endif
+}
+
 InferenceSession::InferenceSession(const SessionOptions& session_options, const Environment& session_env)
     :
 #if !defined(ORT_MINIMAL_BUILD)

onnxruntime/core/session/inference_session.h

@@ -642,6 +642,8 @@ class InferenceSession {
 
   void InitLogger(logging::LoggingManager* logging_manager);
 
+  void TraceSessionOptions(const SessionOptions& session_options);
+
   [[nodiscard]] common::Status CheckShapes(const std::string& input_name, const TensorShape& input_shape,
                                            const TensorShape& expected_shape, const char* input_output_moniker) const;
 

onnxruntime/core/session/provider_registration.cc

@@ -12,6 +12,10 @@
 #include "core/session/ort_apis.h"
 #include "core/providers/openvino/openvino_provider_factory_creator.h"
 
+#ifdef _WIN32
+#include "core/platform/tracing.h"
+#endif
+
 #if defined(USE_DML)
 #include "core/providers/dml/dml_provider_factory_creator.h"
 #endif
@@ -66,6 +70,17 @@ ORT_API_STATUS_IMPL(OrtApis::SessionOptionsAppendExecutionProvider,
     return status;
   }
 
+#ifdef _WIN32
+  for (const auto& config_pair : provider_options) {
+    TraceLoggingWrite(
+        telemetry_provider_handle,
+        "ProviderOptionsAppendExecutionProvider",
+        TraceLoggingString(provider_name, "ProviderName"),
+        TraceLoggingString(config_pair.first.c_str(), "Key"),
+        TraceLoggingString(config_pair.second.c_str(), "Value"));
+  }
+#endif
+
   auto create_not_supported_status = [&provider_name]() {
     return OrtApis::CreateStatus(ORT_INVALID_ARGUMENT,
                                  (std::string(provider_name) + " execution provider is not supported in this build. ").c_str());

onnxruntime/core/util/thread_utils.cc

@@ -13,6 +13,23 @@
 #include "core/common/string_utils.h"
 #include "core/common/logging/logging.h"
 
+std::ostream& operator<<(std::ostream& os, const OrtThreadPoolParams& params) {
+  os << "OrtThreadPoolParams {";
+  os << " thread_pool_size: " << params.thread_pool_size;
+  os << " auto_set_affinity: " << params.auto_set_affinity;
+  os << " allow_spinning: " << params.allow_spinning;
+  os << " dynamic_block_base_: " << params.dynamic_block_base_;
+  os << " stack_size: " << params.stack_size;
+  os << " affinity_str: " << params.affinity_str;
+  // os << " name: " << (params.name ? params.name : L"nullptr");
+  os << " set_denormal_as_zero: " << params.set_denormal_as_zero;
+  // os << " custom_create_thread_fn: " << (params.custom_create_thread_fn ? "set" : "nullptr");
+  // os << " custom_thread_creation_options: " << (params.custom_thread_creation_options ? "set" : "nullptr");
+  // os << " custom_join_thread_fn: " << (params.custom_join_thread_fn ? "set" : "nullptr");
+  os << " }";
+  return os;
+}
+
 namespace onnxruntime {
 namespace concurrency {
 

onnxruntime/core/util/thread_utils.h

@@ -48,6 +48,8 @@ struct OrtThreadPoolParams {
   OrtCustomJoinThreadFn custom_join_thread_fn = nullptr;
 };
 
+std::ostream& operator<<(std::ostream& os, const OrtThreadPoolParams& params);
+
 struct OrtThreadingOptions {
   // Params for creating the threads that parallelizes execution of an op
   OrtThreadPoolParams intra_op_thread_pool_params;