From a85ef652ed0c0626fe04d1a7da3574f7f466c22e Mon Sep 17 00:00:00 2001 From: ivberg Date: Mon, 11 Dec 2023 17:56:27 -0800 Subject: [PATCH] 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 | 9 ++++ onnxruntime/core/framework/config_options.cc | 7 +++ onnxruntime/core/framework/config_options.h | 2 + .../core/framework/execution_providers.h | 17 ++++++- onnxruntime/core/framework/session_options.h | 51 +++++++++++++++++++ onnxruntime/core/session/inference_session.cc | 48 +++++++++++++++++ onnxruntime/core/session/inference_session.h | 2 + .../core/session/provider_registration.cc | 15 ++++++ onnxruntime/core/util/thread_utils.cc | 17 +++++++ onnxruntime/core/util/thread_utils.h | 2 + 10 files changed, 169 insertions(+), 1 deletion(-) diff --git a/onnxruntime/core/common/path_string.h b/onnxruntime/core/common/path_string.h index 76434f5453..6cfb327cce 100644 --- a/onnxruntime/core/common/path_string.h +++ b/onnxruntime/core/common/path_string.h @@ -13,6 +13,15 @@ #include #endif +// for converting / printing ORT_TSTR path strings to std::string +#ifdef _WIN32 +#define ORT_TSTR_CONVERT_TO_PRINTABLE_STRING(X) std::wstring_convert>().to_bytes(X) +#define ORT_TSTR_CONVERT_FROM_STRING(X) std::wstring_convert>().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" diff --git a/onnxruntime/core/framework/config_options.cc b/onnxruntime/core/framework/config_options.cc index 3b322e1fcd..1a4acb6dab 100644 --- a/onnxruntime/core/framework/config_options.cc +++ b/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 diff --git a/onnxruntime/core/framework/config_options.h b/onnxruntime/core/framework/config_options.h index 4297819bed..7b7c226819 100644 --- a/onnxruntime/core/framework/config_options.h +++ b/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 diff --git a/onnxruntime/core/framework/execution_providers.h b/onnxruntime/core/framework/execution_providers.h index 7bf11f8293..d97953fd9d 100644 --- a/onnxruntime/core/framework/execution_providers.h +++ b/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); diff --git a/onnxruntime/core/framework/session_options.h b/onnxruntime/core/framework/session_options.h index 8deeb4c2b8..40c59cfcf6 100644 --- a/onnxruntime/core/framework/session_options.h +++ b/onnxruntime/core/framework/session_options.h @@ -5,6 +5,8 @@ #include #include +#include +#include #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(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 diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 5935f29299..575529a06f 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/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(session_options.execution_mode), "execution_mode"), + TraceLoggingUInt8(static_cast(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(session_options.session_log_severity_level), "session_log_severity_level"), + TraceLoggingInt8(static_cast(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(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) diff --git a/onnxruntime/core/session/inference_session.h b/onnxruntime/core/session/inference_session.h index 4db436f132..96db49aabd 100644 --- a/onnxruntime/core/session/inference_session.h +++ b/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; diff --git a/onnxruntime/core/session/provider_registration.cc b/onnxruntime/core/session/provider_registration.cc index cb51a0c460..81e58c9dd0 100644 --- a/onnxruntime/core/session/provider_registration.cc +++ b/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()); diff --git a/onnxruntime/core/util/thread_utils.cc b/onnxruntime/core/util/thread_utils.cc index 54602e70a0..48f58add82 100644 --- a/onnxruntime/core/util/thread_utils.cc +++ b/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 { diff --git a/onnxruntime/core/util/thread_utils.h b/onnxruntime/core/util/thread_utils.h index 6108450389..d63d620dbc 100644 --- a/onnxruntime/core/util/thread_utils.h +++ b/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;