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.

include/onnxruntime/core/common/logging/logging.h

@@ -91,6 +91,7 @@ struct EventRecord {
   std::unordered_map<std::string, std::string> args;
 };
 }  // namespace profiling
+
 namespace logging {
 
 using Timestamp = std::chrono::time_point<std::chrono::system_clock>;
@@ -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();
 

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;
 

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

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<int>(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<logging::Severity>(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<int>(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<logging::Severity>(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();

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<ORTCHAR_T> 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?
 

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<logging::Severity>(severity));
+  });
 
 #ifdef onnxruntime_PYBIND_EXPORT_OPSCHEMA
   m.def(
-      "get_all_operator_schema",
-      []() -> const std::vector<ONNX_NAMESPACE::OpSchema> {
+      "get_all_operator_schema", []() -> const std::vector<ONNX_NAMESPACE::OpSchema> {
         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_<ONNX_NAMESPACE::OpSchema::SupportType>(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_<SessionOptions>(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<uint32_t>(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<TransformerLevel>(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<uint32_t>(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<TransformerLevel>(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_<RunOptions>(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<py::object> 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<py::object> 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<py::object> {
+            auto shape = na.Shape();
+            std::vector<py::object> 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<py::object> {
-        auto shape = na.Shape();
-        std::vector<py::object> 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_<SessionObjectInitializer>(m, "SessionObjectInitializer");
   py::class_<InferenceSession>(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<std::string> output_names, std::map<std::string, py::object> pyfeeds, RunOptions* run_options = nullptr) -> std::vector<py::object> {
         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

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<int>(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<int>(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<int>(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<CUDAExecutionProvider>(epi)).IsOK());