From 3618e5c66dca7a220cbd02c89634f317213cd0a7 Mon Sep 17 00:00:00 2001 From: ivberg Date: Tue, 6 Jun 2023 14:33:19 -0700 Subject: [PATCH 01/10] Log out ORT session options --- onnxruntime/core/framework/config_options.cc | 7 +++++ onnxruntime/core/framework/config_options.h | 3 ++ onnxruntime/core/framework/session_options.h | 19 ++++++++++++ onnxruntime/core/session/inference_session.cc | 31 +++++++++++++++++++ onnxruntime/core/util/thread_utils.cc | 17 ++++++++++ onnxruntime/core/util/thread_utils.h | 2 ++ 6 files changed, 79 insertions(+) diff --git a/onnxruntime/core/framework/config_options.cc b/onnxruntime/core/framework/config_options.cc index 3b322e1fcd689..1a4acb6dabf71 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 4297819bed111..8faf4db900009 100644 --- a/onnxruntime/core/framework/config_options.h +++ b/onnxruntime/core/framework/config_options.h @@ -32,6 +32,9 @@ 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/session_options.h b/onnxruntime/core/framework/session_options.h index 8deeb4c2b8b64..c3cdb74d60cd5 100644 --- a/onnxruntime/core/framework/session_options.h +++ b/onnxruntime/core/framework/session_options.h @@ -5,6 +5,7 @@ #include #include +#include #include "core/common/gsl.h" #include "core/common/inlined_containers.h" #include "core/framework/config_options.h" @@ -24,6 +25,23 @@ 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 +107,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). diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 1163be27b1685..cf6564fcae88f 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -10,6 +10,7 @@ #include #include #include +#include #include "core/common/denormal.h" #include "core/common/logging/logging.h" @@ -344,6 +345,36 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, // after the invocation of FinalizeSessionOptions. InitLogger(logging_manager_); // this sets session_logger_ so that it can be used for logging after this point. + LOGS(*session_logger_, INFO) << "Session Options { " + << " execution_mode:" << session_options_.execution_mode + << " execution_order:" << session_options_.execution_order + << " enable_profiling:" << session_options_.enable_profiling + << " optimized_model_filepath:" << std::wstring_convert>().to_bytes(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:" << std::wstring_convert>().to_bytes(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 + << " }"; + #if !defined(ORT_MINIMAL_BUILD) // Update the number of steps for the graph transformer manager using the "finalized" session options ORT_ENFORCE(graph_transformer_mgr_.SetSteps(session_options_.max_num_graph_transformation_steps).IsOK()); diff --git a/onnxruntime/core/util/thread_utils.cc b/onnxruntime/core/util/thread_utils.cc index 54602e70a0326..52e946a554262 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 6108450389c1a..d63d620dbc321 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; From 6b3120ae8488d9fda4a1f483a83aa78bb706c669 Mon Sep 17 00:00:00 2001 From: ivberg Date: Tue, 6 Jun 2023 16:02:53 -0700 Subject: [PATCH 02/10] Apply LintRunner patch for PR --- onnxruntime/core/framework/config_options.h | 1 - onnxruntime/core/framework/session_options.h | 28 ++++++------- onnxruntime/core/session/inference_session.cc | 42 +++++++++---------- onnxruntime/core/util/thread_utils.cc | 26 ++++++------ 4 files changed, 47 insertions(+), 50 deletions(-) diff --git a/onnxruntime/core/framework/config_options.h b/onnxruntime/core/framework/config_options.h index 8faf4db900009..7b7c226819e79 100644 --- a/onnxruntime/core/framework/config_options.h +++ b/onnxruntime/core/framework/config_options.h @@ -34,7 +34,6 @@ struct 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/session_options.h b/onnxruntime/core/framework/session_options.h index c3cdb74d60cd5..9d65a69ae6c20 100644 --- a/onnxruntime/core/framework/session_options.h +++ b/onnxruntime/core/framework/session_options.h @@ -25,21 +25,19 @@ 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; +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 { diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index cf6564fcae88f..3373327324db9 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -346,32 +346,32 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, InitLogger(logging_manager_); // this sets session_logger_ so that it can be used for logging after this point. LOGS(*session_logger_, INFO) << "Session Options { " - << " execution_mode:" << session_options_.execution_mode - << " execution_order:" << session_options_.execution_order - << " enable_profiling:" << session_options_.enable_profiling - << " optimized_model_filepath:" << std::wstring_convert>().to_bytes(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:" << std::wstring_convert>().to_bytes(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 + << " execution_mode:" << session_options_.execution_mode + << " execution_order:" << session_options_.execution_order + << " enable_profiling:" << session_options_.enable_profiling + << " optimized_model_filepath:" << std::wstring_convert>().to_bytes(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:" << std::wstring_convert>().to_bytes(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 + << " 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 + << " 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 + //<< " 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 + //<< " custom_op_libs:" << session_options_.custom_op_libs #endif << " }"; diff --git a/onnxruntime/core/util/thread_utils.cc b/onnxruntime/core/util/thread_utils.cc index 52e946a554262..48f58add8237b 100644 --- a/onnxruntime/core/util/thread_utils.cc +++ b/onnxruntime/core/util/thread_utils.cc @@ -14,19 +14,19 @@ #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 << " }"; + 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; } From e13d1c8f1504da2ed98553f8afd163be96ba63a4 Mon Sep 17 00:00:00 2001 From: ivberg Date: Wed, 7 Jun 2023 10:46:01 -0700 Subject: [PATCH 03/10] Fix cross-platform Linux Build --- onnxruntime/core/common/path_string.h | 9 +++++++++ onnxruntime/core/session/inference_session.cc | 4 ++-- 2 files changed, 11 insertions(+), 2 deletions(-) diff --git a/onnxruntime/core/common/path_string.h b/onnxruntime/core/common/path_string.h index 76434f5453549..6cfb327cce08a 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/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 3373327324db9..d760a3e02bc68 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -349,11 +349,11 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, << " execution_mode:" << session_options_.execution_mode << " execution_order:" << session_options_.execution_order << " enable_profiling:" << session_options_.enable_profiling - << " optimized_model_filepath:" << std::wstring_convert>().to_bytes(session_options_.optimized_model_filepath) + << " 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:" << std::wstring_convert>().to_bytes(session_options_.profile_file_prefix) + << " 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 From bc185cd2676fd1854f08231836b3ef20b8d82b32 Mon Sep 17 00:00:00 2001 From: ivberg Date: Fri, 3 Nov 2023 14:08:14 -0700 Subject: [PATCH 04/10] Move string/stream logging implementation closer to definition per PR comment. Log out structured sessions options to Microsoft.ML.ONNXRuntime TraceLogging provider. This will make it easier to see session options, as the log severity level will often not be set to view what the options are in print log form. The ETW events are NOT marked as Telemetry and only for local logging. --- onnxruntime/core/framework/session_options.h | 35 +++++++++ onnxruntime/core/session/inference_session.cc | 72 +++++++++++-------- 2 files changed, 77 insertions(+), 30 deletions(-) diff --git a/onnxruntime/core/framework/session_options.h b/onnxruntime/core/framework/session_options.h index 9d65a69ae6c20..70f4b69c0456b 100644 --- a/onnxruntime/core/framework/session_options.h +++ b/onnxruntime/core/framework/session_options.h @@ -6,6 +6,7 @@ #include #include #include +#include #include "core/common/gsl.h" #include "core/common/inlined_containers.h" #include "core/framework/config_options.h" @@ -171,4 +172,38 @@ 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 d760a3e02bc68..e3943add801b6 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -10,7 +10,6 @@ #include #include #include -#include #include "core/common/denormal.h" #include "core/common/logging/logging.h" @@ -49,6 +48,7 @@ #include "core/platform/Barrier.h" #include "core/platform/ort_mutex.h" #include "core/platform/threadpool.h" +#include "core/platform/tracing.h" #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 @@ -345,35 +345,47 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, // after the invocation of FinalizeSessionOptions. InitLogger(logging_manager_); // this sets session_logger_ so that it can be used for logging after this point. - LOGS(*session_logger_, INFO) << "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 - << " }"; + LOGS(*session_logger_, INFO) << session_options; + // const Env& env = Env::Default(); + // env.GetTelemetryProvider().LogSessionOptions(session_options); + + 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")); + } #if !defined(ORT_MINIMAL_BUILD) // Update the number of steps for the graph transformer manager using the "finalized" session options From 3669ab3db989b79c70b74fd93185bca1acb75492 Mon Sep 17 00:00:00 2001 From: ivberg Date: Fri, 3 Nov 2023 14:12:16 -0700 Subject: [PATCH 05/10] Lintrunner --- onnxruntime/core/framework/session_options.h | 7 +++---- onnxruntime/core/session/inference_session.cc | 10 +++++----- 2 files changed, 8 insertions(+), 9 deletions(-) diff --git a/onnxruntime/core/framework/session_options.h b/onnxruntime/core/framework/session_options.h index 70f4b69c0456b..40c59cfcf699d 100644 --- a/onnxruntime/core/framework/session_options.h +++ b/onnxruntime/core/framework/session_options.h @@ -194,16 +194,15 @@ inline std::ostream& operator<<(std::ostream& os, const SessionOptions& session_ << " 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 + //<< " 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 + //<< " 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 + //<< " 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 e3943add801b6..1f4b33e37f208 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -380,11 +380,11 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, 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")); + TraceLoggingWrite( + telemetry_provider_handle, + "SessionOptions_ConfigEntry", + TraceLoggingString(config_pair.first.c_str(), "Key"), + TraceLoggingString(config_pair.second.c_str(), "Value")); } #if !defined(ORT_MINIMAL_BUILD) From 61fb48dd121ed0e00e58107c7d825ff29a8c3d02 Mon Sep 17 00:00:00 2001 From: ivberg Date: Mon, 6 Nov 2023 12:24:35 -0800 Subject: [PATCH 06/10] Address PR comment by moving session log to seperate func --- onnxruntime/core/session/inference_session.cc | 85 ++++++++++--------- onnxruntime/core/session/inference_session.h | 2 + 2 files changed, 45 insertions(+), 42 deletions(-) diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 1f4b33e37f208..433bfa7ba4917 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -344,48 +344,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. - - LOGS(*session_logger_, INFO) << session_options; - // const Env& env = Env::Default(); - // env.GetTelemetryProvider().LogSessionOptions(session_options); - - 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")); - } + TraceSessionOptions(session_options); #if !defined(ORT_MINIMAL_BUILD) // Update the number of steps for the graph transformer manager using the "finalized" session options @@ -499,6 +458,48 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, telemetry_ = {}; } +void InferenceSession::TraceSessionOptions(const SessionOptions& session_options) { + LOGS(*session_logger_, INFO) << session_options; + + 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")); + } +} + 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 4db436f132d11..96db49aabdaf6 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; From 54cd9c923450fd0bb92f97ccb0952ba063369d97 Mon Sep 17 00:00:00 2001 From: ivberg Date: Tue, 7 Nov 2023 11:39:58 -0800 Subject: [PATCH 07/10] Attempt to fix Linux build --- include/onnxruntime/core/platform/tracing.h | 1 - 1 file changed, 1 deletion(-) diff --git a/include/onnxruntime/core/platform/tracing.h b/include/onnxruntime/core/platform/tracing.h index fb61632aae238..1172c00da6463 100644 --- a/include/onnxruntime/core/platform/tracing.h +++ b/include/onnxruntime/core/platform/tracing.h @@ -3,7 +3,6 @@ #pragma once -#include #include TRACELOGGING_DECLARE_PROVIDER(telemetry_provider_handle); From 7bcba7cf77031f1ef14dbf76a4741340286fe741 Mon Sep 17 00:00:00 2001 From: ivberg Date: Mon, 4 Dec 2023 17:37:57 -0800 Subject: [PATCH 08/10] Attempt to fix Linux Build 2 by having TraceLogging only for Win32. Also log out EP Key/Value options --- .../core/framework/execution_providers.h | 17 ++++++++++++++++- onnxruntime/core/session/inference_session.cc | 5 +++++ .../core/session/provider_registration.cc | 17 +++++++++++++++++ 3 files changed, 38 insertions(+), 1 deletion(-) diff --git a/onnxruntime/core/framework/execution_providers.h b/onnxruntime/core/framework/execution_providers.h index 7bf11f8293a36..d97953fd9d5ea 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/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 433bfa7ba4917..3c9fec5f14876 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -48,7 +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 @@ -461,6 +463,7 @@ void InferenceSession::ConstructorCommon(const SessionOptions& session_options, 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"), @@ -498,6 +501,8 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options 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) diff --git a/onnxruntime/core/session/provider_registration.cc b/onnxruntime/core/session/provider_registration.cc index 4649ac35c3647..c5477bad20171 100644 --- a/onnxruntime/core/session/provider_registration.cc +++ b/onnxruntime/core/session/provider_registration.cc @@ -12,6 +12,12 @@ #include "core/session/ort_apis.h" #include "core/providers/openvino/openvino_provider_factory_creator.h" +#ifdef _WIN32 +#include // For some reason, including tracing.h is having compile errors without this + +#include "core/platform/tracing.h" +#endif + #if defined(USE_DML) #include "core/providers/dml/dml_provider_factory_creator.h" #endif @@ -66,6 +72,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()); From ecd7fa365c570b3860b8d28d06989033f600beab Mon Sep 17 00:00:00 2001 From: ivberg Date: Mon, 4 Dec 2023 18:29:37 -0800 Subject: [PATCH 09/10] Lintrunner NIT --- onnxruntime/core/session/inference_session.cc | 1 - 1 file changed, 1 deletion(-) diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 3c9fec5f14876..f066ea27b5d37 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -502,7 +502,6 @@ void InferenceSession::TraceSessionOptions(const SessionOptions& session_options TraceLoggingString(config_pair.second.c_str(), "Value")); } #endif - } InferenceSession::InferenceSession(const SessionOptions& session_options, const Environment& session_env) From 9c96c4ddc60f210147c7990c50f02dd2d0acb558 Mon Sep 17 00:00:00 2001 From: ivberg Date: Mon, 11 Dec 2023 14:41:35 -0800 Subject: [PATCH 10/10] Address PR comment adding back Windows header as before PR for platform tracing --- include/onnxruntime/core/platform/tracing.h | 1 + onnxruntime/core/session/provider_registration.cc | 2 -- 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/include/onnxruntime/core/platform/tracing.h b/include/onnxruntime/core/platform/tracing.h index 1172c00da6463..fb61632aae238 100644 --- a/include/onnxruntime/core/platform/tracing.h +++ b/include/onnxruntime/core/platform/tracing.h @@ -3,6 +3,7 @@ #pragma once +#include #include TRACELOGGING_DECLARE_PROVIDER(telemetry_provider_handle); diff --git a/onnxruntime/core/session/provider_registration.cc b/onnxruntime/core/session/provider_registration.cc index c5477bad20171..29291050fafb1 100644 --- a/onnxruntime/core/session/provider_registration.cc +++ b/onnxruntime/core/session/provider_registration.cc @@ -13,8 +13,6 @@ #include "core/providers/openvino/openvino_provider_factory_creator.h" #ifdef _WIN32 -#include // For some reason, including tracing.h is having compile errors without this - #include "core/platform/tracing.h" #endif