diff --git a/include/onnxruntime/core/common/logging/logging.h b/include/onnxruntime/core/common/logging/logging.h index 3c808b9adb..10869779d4 100644 --- a/include/onnxruntime/core/common/logging/logging.h +++ b/include/onnxruntime/core/common/logging/logging.h @@ -91,6 +91,7 @@ struct EventRecord { std::unordered_map args; }; } // namespace profiling + namespace logging { using Timestamp = std::chrono::time_point; @@ -175,6 +176,12 @@ class LoggingManager final { */ static const Logger& DefaultLogger(); + /** + Change the minimum severity level for log messages to be output by the default logger. + @param severity The severity. + */ + static void SetDefaultLoggerSeverity(Severity severity); + /** Logs a FATAL level message and creates an exception that can be thrown with error information. @param category The log category. @@ -246,6 +253,18 @@ class Logger { max_vlog_level_{severity > Severity::kVERBOSE ? -1 : vlog_level} { // disable unless logging VLOG messages } + /** + Get the minimum severity level for log messages to be output. + @returns The severity. + */ + Severity GetSeverity() const noexcept { return min_severity_; } + + /** + Change the minimum severity level for log messages to be output. + @param severity The severity. + */ + void SetSeverity(Severity severity) noexcept { min_severity_ = severity; } + /** Check if output is enabled for the provided LogSeverity and DataType values. @param severity The severity. @@ -282,7 +301,7 @@ class Logger { private: const LoggingManager* logging_manager_; const std::string id_; - const Severity min_severity_; + Severity min_severity_; const bool filter_user_data_; const int max_vlog_level_; }; @@ -296,6 +315,15 @@ inline const Logger& LoggingManager::DefaultLogger() { return *s_default_logger_; } +inline void LoggingManager::SetDefaultLoggerSeverity(Severity severity) { + if (s_default_logger_ == nullptr) { + // fail early for attempted misuse. don't use logging macros as we have no logger. + throw std::logic_error("Attempt to use DefaultLogger but none has been registered."); + } + + s_default_logger_->SetSeverity(severity); +} + inline Timestamp LoggingManager::GetTimestamp() const noexcept { static const Epochs& epochs = GetEpochs(); diff --git a/include/onnxruntime/core/framework/run_options.h b/include/onnxruntime/core/framework/run_options.h index 572bc186d9..52285311e5 100644 --- a/include/onnxruntime/core/framework/run_options.h +++ b/include/onnxruntime/core/framework/run_options.h @@ -11,14 +11,17 @@ * Configuration information for a Run call. */ struct OrtRunOptions { - unsigned run_log_verbosity_level = 0; ///< Logging level + /// Log severity. See https://github.com/microsoft/onnxruntime/blob/master/include/onnxruntime/core/common/logging/severity.h + /// Default = -1 (use the log severity from the InferenceSession that the Run is for). + int run_log_severity_level = -1; + unsigned run_log_verbosity_level = 0; ///< VLOG level if debug build and run_log_severity_level is 0 (VERBOSE). std::string run_tag; ///< A tag for the Run() calls using this. - // Set to 'true' to ensure the termination of all the outstanding Run() calls + // Set to 'true' to ensure the termination of all the outstanding Run() calls // that use this OrtRunOptions instance. Some of the outstanding Run() calls may // be forced to terminate with an error status. bool terminate = false; - + OrtRunOptions() = default; ~OrtRunOptions() = default; diff --git a/onnxruntime/__init__.py b/onnxruntime/__init__.py index 18428a2370..ad73baf144 100644 --- a/onnxruntime/__init__.py +++ b/onnxruntime/__init__.py @@ -18,4 +18,4 @@ __author__ = "Microsoft" from onnxruntime.capi import onnxruntime_validation onnxruntime_validation.check_distro_info() from onnxruntime.capi.session import InferenceSession -from onnxruntime.capi._pybind_state import RunOptions, SessionOptions, get_device, NodeArg, ModelMetadata +from onnxruntime.capi._pybind_state import RunOptions, SessionOptions, set_default_logger_severity, get_device, NodeArg, ModelMetadata diff --git a/onnxruntime/core/session/inference_session.cc b/onnxruntime/core/session/inference_session.cc index 435711b25c..0330e788b1 100644 --- a/onnxruntime/core/session/inference_session.cc +++ b/onnxruntime/core/session/inference_session.cc @@ -855,15 +855,23 @@ const logging::Logger& InferenceSession::CreateLoggerForRun(const RunOptions& ru run_log_id += run_options.run_tag; - if (run_options.run_log_verbosity_level > 0) { - new_run_logger = logging_manager_->CreateLogger(run_log_id, - logging::Severity::kVERBOSE, - false, - run_options.run_log_verbosity_level); + logging::Severity severity = logging::Severity::kWARNING; + + if (run_options.run_log_severity_level < 0) { + severity = session_logger_->GetSeverity(); } else { - new_run_logger = logging_manager_->CreateLogger(run_log_id); + ORT_ENFORCE(run_options.run_log_severity_level >= 0 && + run_options.run_log_severity_level <= static_cast(logging::Severity::kFATAL), + "Invalid run log severity level. Must be a valid onnxruntime::logging::Severity value. Got ", + run_options.run_log_severity_level); + severity = static_cast(run_options.run_log_severity_level); } + new_run_logger = logging_manager_->CreateLogger(run_log_id, + severity, + false, + run_options.run_log_verbosity_level); + run_logger = new_run_logger.get(); VLOGS(*run_logger, 1) << "Created logger for run with id of " << run_log_id; } else { @@ -882,14 +890,21 @@ void InferenceSession::InitLogger(logging::LoggingManager* logging_manager) { ? session_options_.session_logid : "InferenceSession"; // there's probably a better default... - if (session_options_.session_log_verbosity_level > 0) { - owned_session_logger_ = logging_manager->CreateLogger(session_logid, - logging::Severity::kVERBOSE, - false, - session_options_.session_log_verbosity_level); + logging::Severity severity = logging::Severity::kWARNING; + + if (session_options_.session_log_severity_level < 0) { + severity = logging::LoggingManager::DefaultLogger().GetSeverity(); } else { - owned_session_logger_ = logging_manager->CreateLogger(session_logid); + ORT_ENFORCE(session_options_.session_log_severity_level >= 0 && + session_options_.session_log_severity_level <= static_cast(logging::Severity::kFATAL), + "Invalid session log severity level. Must be a valid onnxruntime::logging::Severity value. Got ", + session_options_.session_log_severity_level); + severity = static_cast(session_options_.session_log_severity_level); } + + owned_session_logger_ = logging_manager_->CreateLogger(session_logid, severity, false, + session_options_.session_log_verbosity_level); + session_logger_ = owned_session_logger_.get(); } else { session_logger_ = &logging::LoggingManager::DefaultLogger(); diff --git a/onnxruntime/core/session/inference_session.h b/onnxruntime/core/session/inference_session.h index bee3c92ffe..0bf91e8caf 100644 --- a/onnxruntime/core/session/inference_session.h +++ b/onnxruntime/core/session/inference_session.h @@ -71,8 +71,13 @@ struct SessionOptions { // the prefix of the profile file. The current time will be appended to the file name. std::basic_string profile_file_prefix = ORT_TSTR("onnxruntime_profile_"); - std::string session_logid; ///< logger id to use for session output - unsigned session_log_verbosity_level = 0; ///< applies to session load, initialization, etc + std::string session_logid; ///< logger id to use for session output + + /// Log severity for the inference session. Applies to session load, initialization, etc. + /// See https://github.com/microsoft/onnxruntime/blob/master/include/onnxruntime/core/common/logging/severity.h + /// Default = -1 (use default logger severity) + int session_log_severity_level = -1; + unsigned session_log_verbosity_level = 0; ///< VLOG level if debug build and session_log_severity_level is 0 (VERBOSE). unsigned max_num_graph_transformation_steps = 5; // TODO choose a good default here? diff --git a/onnxruntime/python/onnxruntime_pybind_state.cc b/onnxruntime/python/onnxruntime_pybind_state.cc index b4489b89d7..b1082491e7 100644 --- a/onnxruntime/python/onnxruntime_pybind_state.cc +++ b/onnxruntime/python/onnxruntime_pybind_state.cc @@ -258,22 +258,25 @@ void addGlobalMethods(py::module& m) { m.def( "get_device", []() -> std::string { return BACKEND_DEVICE; }, "Return the device used to compute the prediction (CPU, MKL, ...)"); + m.def("set_default_logger_severity", [](int severity) { + ORT_ENFORCE(severity >= 0 && severity <= 4, + "Invalid logging severity. 0:Verbose, 1:Info, 2:Warning, 3:Error, 4:Fatal"); + logging::LoggingManager* default_logging_manager = SessionObjectInitializer::Get(); + default_logging_manager->SetDefaultLoggerSeverity(static_cast(severity)); + }); #ifdef onnxruntime_PYBIND_EXPORT_OPSCHEMA m.def( - "get_all_operator_schema", - []() -> const std::vector { + "get_all_operator_schema", []() -> const std::vector { return ONNX_NAMESPACE::OpSchemaRegistry::get_all_schemas_with_history(); }, - "Return a vector of OpSchema all registed operators" - ); + "Return a vector of OpSchema all registed operators"); #endif } - #ifdef onnxruntime_PYBIND_EXPORT_OPSCHEMA -void addOpSchemaSubmodule(py::module& m){ +void addOpSchemaSubmodule(py::module& m) { auto schemadef = m.def_submodule("schemadef"); schemadef.doc() = "Schema submodule"; @@ -354,11 +357,9 @@ void addOpSchemaSubmodule(py::module& m){ py::enum_(op_schema, "SupportType") .value("COMMON", ONNX_NAMESPACE::OpSchema::SupportType::COMMON) .value("EXPERIMENTAL", ONNX_NAMESPACE::OpSchema::SupportType::EXPERIMENTAL); - - } -#endif //onnxruntime_PYBIND_EXPORT_OPSCHEMA +#endif //onnxruntime_PYBIND_EXPORT_OPSCHEMA void addObjectMethods(py::module& m) { py::class_(m, "SessionOptions", R"pbdoc(Configuration information for a session.)pbdoc") @@ -374,27 +375,36 @@ Set this option to false if you don't want it. Default is True.)pbdoc") R"pbdoc(Runs optimization steps on the execution graph. Default is 5.)pbdoc") .def_readwrite("session_logid", &SessionOptions::session_logid, R"pbdoc(Logger id to use for session output.)pbdoc") + .def_readwrite("session_log_severity_level", &SessionOptions::session_log_severity_level, + R"pbdoc(Log severity level. Applies to session load, initialization, etc. +0:Verbose, 1:Info, 2:Warning. 3:Error, 4:Fatal. Default is 2.)pbdoc") .def_readwrite("session_log_verbosity_level", &SessionOptions::session_log_verbosity_level, - R"pbdoc(Applies to session load, initialization, etc. Default is 0.)pbdoc") + R"pbdoc(VLOG level if DEBUG build and session_log_verbosity_level is 0. +Applies to session load, initialization, etc. Default is 0.)pbdoc") .def_readwrite("session_thread_pool_size", &SessionOptions::session_thread_pool_size, R"pbdoc(How many threads in the session thread pool. Default is 0 to let onnxruntime choose. This parameter is unused unless *enable_sequential_execution* is false.)pbdoc") - .def_property_readonly("graph_optimization_level", - [](const SessionOptions* options) -> uint32_t { - return static_cast(options->graph_optimization_level); - }, - R"pbdoc(Graph optimization level for this session.)pbdoc") - .def("set_graph_optimization_level", - [](SessionOptions* options, uint32_t level) -> void { - options->graph_optimization_level = static_cast(level); - }, - R"pbdoc(Graph optimization level for this session. 0 disables all optimizations. + .def_property_readonly( + "graph_optimization_level", + [](const SessionOptions* options) -> uint32_t { + return static_cast(options->graph_optimization_level); + }, + R"pbdoc(Graph optimization level for this session.)pbdoc") + .def( + "set_graph_optimization_level", + [](SessionOptions* options, uint32_t level) -> void { + options->graph_optimization_level = static_cast(level); + }, + R"pbdoc(Graph optimization level for this session. 0 disables all optimizations. Whereas 1 enables basic optimizations and 2 enables all optimizations.)pbdoc"); py::class_(m, "RunOptions", R"pbdoc(Configuration information for a single Run.)pbdoc") .def(py::init()) + .def_readwrite("run_log_severity_level", &RunOptions::run_log_severity_level, + R"pbdoc(Log severity level for a particular Run() invocation. 0:Verbose, 1:Info, 2:Warning. 3:Error, 4:Fatal. Default is 2.)pbdoc") .def_readwrite("run_log_verbosity_level", &RunOptions::run_log_verbosity_level, - "Applies to a particular Run() invocation.") + R"pbdoc(VLOG level if DEBUG build and run_log_severity_level is 0. +Applies to a particular Run() invocation. Default is 0.)pbdoc") .def_readwrite("run_tag", &RunOptions::run_tag, "To identify logs generated by a particular Run() invocation.") .def_readwrite("terminate", &RunOptions::terminate, @@ -419,50 +429,52 @@ including arg name, arg type (contains both type and shape).)pbdoc") return *(na.Type()); }, "node type") - .def("__str__", [](const onnxruntime::NodeArg& na) -> std::string { - std::ostringstream res; - res << "NodeArg(name='" << na.Name() << "', type='" << *(na.Type()) << "', shape="; - auto shape = na.Shape(); - std::vector arr; - if (shape == nullptr || shape->dim_size() == 0) { - res << "[]"; - } else { - res << "["; - for (int i = 0; i < shape->dim_size(); ++i) { - if (shape->dim(i).has_dim_value()) { - res << shape->dim(i).dim_value(); - } else if (shape->dim(i).has_dim_param()) { - res << "None"; + .def( + "__str__", [](const onnxruntime::NodeArg& na) -> std::string { + std::ostringstream res; + res << "NodeArg(name='" << na.Name() << "', type='" << *(na.Type()) << "', shape="; + auto shape = na.Shape(); + std::vector arr; + if (shape == nullptr || shape->dim_size() == 0) { + res << "[]"; + } else { + res << "["; + for (int i = 0; i < shape->dim_size(); ++i) { + if (shape->dim(i).has_dim_value()) { + res << shape->dim(i).dim_value(); + } else if (shape->dim(i).has_dim_param()) { + res << "None"; + } + if (i < shape->dim_size() - 1) { + res << ", "; + } + } + res << "]"; } - if (i < shape->dim_size() - 1) { - res << ", "; + res << ")"; + + return std::string(res.str()); + }, + "converts the node into a readable string") + .def_property_readonly( + "shape", [](const onnxruntime::NodeArg& na) -> std::vector { + auto shape = na.Shape(); + std::vector arr; + if (shape == nullptr || shape->dim_size() == 0) { + return arr; } - } - res << "]"; - } - res << ")"; - return std::string(res.str()); - }, - "converts the node into a readable string") - .def_property_readonly("shape", [](const onnxruntime::NodeArg& na) -> std::vector { - auto shape = na.Shape(); - std::vector arr; - if (shape == nullptr || shape->dim_size() == 0) { - return arr; - } - - arr.resize(shape->dim_size()); - for (int i = 0; i < shape->dim_size(); ++i) { - if (shape->dim(i).has_dim_value()) { - arr[i] = py::cast(shape->dim(i).dim_value()); - } else if (shape->dim(i).has_dim_param()) { - arr[i] = py::none(); - } - } - return arr; - }, - "node shape (assuming the node holds a tensor)"); + arr.resize(shape->dim_size()); + for (int i = 0; i < shape->dim_size(); ++i) { + if (shape->dim(i).has_dim_value()) { + arr[i] = py::cast(shape->dim(i).dim_value()); + } else if (shape->dim(i).has_dim_param()) { + arr[i] = py::none(); + } + } + return arr; + }, + "node shape (assuming the node holds a tensor)"); py::class_(m, "SessionObjectInitializer"); py::class_(m, "InferenceSession", R"pbdoc(This is the main class used to run a model.)pbdoc") @@ -477,15 +489,16 @@ including arg name, arg type (contains both type and shape).)pbdoc") InitializeSession(sess); }, R"pbdoc(Load a model saved in ONNX format.)pbdoc") - .def("read_bytes", [](InferenceSession* sess, const py::bytes& serializedModel) { - std::istringstream buffer(serializedModel); - auto status = sess->Load(buffer); - if (!status.IsOK()) { - throw std::runtime_error(status.ToString().c_str()); - } - InitializeSession(sess); - }, - R"pbdoc(Load a model serialized in ONNX format.)pbdoc") + .def( + "read_bytes", [](InferenceSession* sess, const py::bytes& serializedModel) { + std::istringstream buffer(serializedModel); + auto status = sess->Load(buffer); + if (!status.IsOK()) { + throw std::runtime_error(status.ToString().c_str()); + } + InitializeSession(sess); + }, + R"pbdoc(Load a model serialized in ONNX format.)pbdoc") .def("run", [](InferenceSession* sess, std::vector output_names, std::map pyfeeds, RunOptions* run_options = nullptr) -> std::vector { NameMLValMap feeds; for (auto _ : pyfeeds) { @@ -595,7 +608,6 @@ PYBIND11_MODULE(onnxruntime_pybind11_state, m) { #ifdef onnxruntime_PYBIND_EXPORT_OPSCHEMA addOpSchemaSubmodule(m); #endif - } } // namespace python diff --git a/onnxruntime/test/framework/inference_session_test.cc b/onnxruntime/test/framework/inference_session_test.cc index a19bd12a20..07291b5ee9 100644 --- a/onnxruntime/test/framework/inference_session_test.cc +++ b/onnxruntime/test/framework/inference_session_test.cc @@ -118,7 +118,6 @@ class FuseExecutionProvider : public IExecutionProvider { ORT_UNUSED_PARAMETER(dst); return Status::OK(); } - }; namespace test { @@ -440,6 +439,7 @@ TEST(InferenceSessionTests, CheckRunLogger) { RunOptions run_options; run_options.run_tag = "RunTag"; + run_options.run_log_severity_level = static_cast(Severity::kVERBOSE); RunModel(session_object, run_options); #ifndef NDEBUG @@ -579,6 +579,7 @@ TEST(InferenceSessionTests, ConfigureVerbosityLevel) { SessionOptions so; so.session_logid = "ConfigureVerbosityLevel"; + so.session_log_severity_level = static_cast(Severity::kVERBOSE); so.session_log_verbosity_level = 1; // create CapturingSink. LoggingManager will own it, but as long as the logging_manager @@ -597,6 +598,7 @@ TEST(InferenceSessionTests, ConfigureVerbosityLevel) { RunOptions run_options; run_options.run_tag = "ConfigureVerbosityLevel"; + run_options.run_log_severity_level = static_cast(Severity::kVERBOSE); run_options.run_log_verbosity_level = 1; RunModel(session_object, run_options); @@ -1399,7 +1401,7 @@ TEST(InferenceSessionTests, TestParallelExecutionWithCudaProvider) { so.enable_sequential_execution = false; so.session_logid = "InferenceSessionTests.TestParallelExecutionWithCudaProvider"; InferenceSession session_object{so}; - + CUDAExecutionProviderInfo epi; epi.device_id = 0; EXPECT_TRUE(session_object.RegisterExecutionProvider(std::make_unique(epi)).IsOK());