From 87d65389e6eb197fd71de24f5e30b5b15ca3780d Mon Sep 17 00:00:00 2001 From: Scott McKay Date: Wed, 12 Jun 2019 08:54:03 +1000 Subject: [PATCH] Add ability to change the logging severity of the default logger. (#1165) Add ability to set the session and run logger severity via SessionOptions and RunOptions Inherit severity from the next logger up if logger severity isn't specified in SessionOptions or RunOptions Expose ability to set default logger severity in python bindings. --- .../onnxruntime/core/common/logging/logging.h | 30 +++- .../onnxruntime/core/framework/run_options.h | 9 +- onnxruntime/__init__.py | 2 +- onnxruntime/core/session/inference_session.cc | 39 +++-- onnxruntime/core/session/inference_session.h | 9 +- .../python/onnxruntime_pybind_state.cc | 156 ++++++++++-------- .../test/framework/inference_session_test.cc | 6 +- 7 files changed, 158 insertions(+), 93 deletions(-) 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());