Fix and optimize logger (#4002)

* Fix logging switch statement. * Remove debug_verbose_ in AllReducer. * Don't construct the stream when not needed. * Make default constructor deleted. * Remove redundant IsVerbose.
dmlc · Dec 17, 2018 · c8c7b96 · c8c7b96
1 parent a2dc929
commit c8c7b96
Show file tree

Hide file tree

Showing 8 changed files with 59 additions and 40 deletions.
diff --git a/include/xgboost/logging.h b/include/xgboost/logging.h
@@ -77,8 +77,9 @@ class ConsoleLogger : public BaseLogger {
 
   static LogVerbosity GlobalVerbosity();
   static LogVerbosity DefaultVerbosity();
+  static bool ShouldLog(LogVerbosity verbosity);
 
-  ConsoleLogger();
+  ConsoleLogger() = delete;
   explicit ConsoleLogger(LogVerbosity cur_verb);
   ConsoleLogger(const std::string& file, int line, LogVerbosity cur_verb);
   ~ConsoleLogger();
@@ -123,30 +124,39 @@ using LogCallbackRegistryStore = dmlc::ThreadLocalStore<LogCallbackRegistry>;
 #if defined(LOG_WARNING)
 #undef  LOG_WARNING
 #endif
-#define LOG_WARNING ::xgboost::ConsoleLogger(                           \
-    __FILE__, __LINE__, ::xgboost::ConsoleLogger::LogVerbosity::kWarning)
+#define LOG_WARNING                                                            \
+  if (::xgboost::ConsoleLogger::ShouldLog(                                     \
+          ::xgboost::ConsoleLogger::LV::kWarning))                             \
+  ::xgboost::ConsoleLogger(__FILE__, __LINE__,                                 \
+                           ::xgboost::ConsoleLogger::LogVerbosity::kWarning)
 
 // Redefines LOG_INFO for controling verbosity
 #if defined(LOG_INFO)
 #undef  LOG_INFO
 #endif
-#define LOG_INFO    ::xgboost::ConsoleLogger(                           \
-    __FILE__, __LINE__, ::xgboost::ConsoleLogger::LogVerbosity::kInfo)
+#define LOG_INFO                                                               \
+  if (::xgboost::ConsoleLogger::ShouldLog(                                     \
+          ::xgboost::ConsoleLogger::LV::kInfo))                                \
+  ::xgboost::ConsoleLogger(__FILE__, __LINE__,                                 \
+                           ::xgboost::ConsoleLogger::LogVerbosity::kInfo)
 
 #if defined(LOG_DEBUG)
 #undef LOG_DEBUG
 #endif
-#define LOG_DEBUG  ::xgboost::ConsoleLogger(                           \
-    __FILE__, __LINE__, ::xgboost::ConsoleLogger::LogVerbosity::kDebug)
+#define LOG_DEBUG                                                              \
+  if (::xgboost::ConsoleLogger::ShouldLog(                                     \
+          ::xgboost::ConsoleLogger::LV::kDebug))                               \
+  ::xgboost::ConsoleLogger(__FILE__, __LINE__,                                 \
+                           ::xgboost::ConsoleLogger::LogVerbosity::kDebug)
 
 // redefines the logging macro if not existed
 #ifndef LOG
 #define LOG(severity) LOG_##severity.stream()
 #endif
 
 // Enable LOG(CONSOLE) for print messages to console.
-#define LOG_CONSOLE ::xgboost::ConsoleLogger(   \
-  ::xgboost::ConsoleLogger::LogVerbosity::kIgnore)
+#define LOG_CONSOLE ::xgboost::ConsoleLogger(           \
+    ::xgboost::ConsoleLogger::LogVerbosity::kIgnore)
 // Enable LOG(TRACKER) for print messages to tracker
 #define LOG_TRACKER ::xgboost::TrackerLogger()
 }  // namespace xgboost.

diff --git a/src/common/device_helpers.cuh b/src/common/device_helpers.cuh
@@ -842,16 +842,16 @@ void Gather(int device_idx, T *out, const T *in, const int *instId, int nVals) {
 
 class AllReducer {
   bool initialised_;
-  bool debug_verbose_;
   size_t allreduce_bytes_;  // Keep statistics of the number of bytes communicated
   size_t allreduce_calls_;  // Keep statistics of the number of reduce calls
 #ifdef XGBOOST_USE_NCCL
   std::vector<ncclComm_t> comms;
   std::vector<cudaStream_t> streams;
   std::vector<int> device_ordinals;
 #endif
+
  public:
-  AllReducer() : initialised_(false),debug_verbose_(false), allreduce_bytes_(0),
+  AllReducer() : initialised_(false), allreduce_bytes_(0),
                  allreduce_calls_(0) {}
 
   /**
@@ -863,10 +863,9 @@ class AllReducer {
    * \param device_ordinals The device ordinals.
    */
 
-  void Init(const std::vector<int> &device_ordinals, bool debug_verbose) {
+  void Init(const std::vector<int> &device_ordinals) {
 #ifdef XGBOOST_USE_NCCL
     /** \brief this >monitor . init. */
-    this->debug_verbose_ = debug_verbose;
     this->device_ordinals = device_ordinals;
     comms.resize(device_ordinals.size());
     dh::safe_nccl(ncclCommInitAll(comms.data(),
@@ -893,7 +892,7 @@ class AllReducer {
         ncclCommDestroy(comm);
       }
     }
-    if (debug_verbose_) {
+    if (xgboost::ConsoleLogger::ShouldLog(xgboost::ConsoleLogger::LV::kDebug)) {
       LOG(CONSOLE) << "======== NCCL Statistics========";
       LOG(CONSOLE) << "AllReduce calls: " << allreduce_calls_;
       LOG(CONSOLE) << "AllReduce total MB communicated: " << allreduce_bytes_/1000000;

diff --git a/src/common/timer.h b/src/common/timer.h
@@ -52,16 +52,12 @@ struct Monitor {
   std::string label = "";
   std::map<std::string, Statistics> statistics_map;
   Timer self_timer;
-  bool IsVerbose() {
-    // Don't cache debug verbosity in here to deal with changed parameter.
-    return (ConsoleLogger::GlobalVerbosity() == ConsoleLogger::LV::kDebug);
-  }
 
  public:
   Monitor() { self_timer.Start(); }
 
   ~Monitor() {
-    if (!IsVerbose()) return;
+    if (!ConsoleLogger::ShouldLog(ConsoleLogger::LV::kDebug)) return;
 
     LOG(CONSOLE) << "======== Monitor: " << label << " ========";
     for (auto &kv : statistics_map) {
@@ -79,7 +75,7 @@ struct Monitor {
   }
   void Start(const std::string &name) { statistics_map[name].timer.Start(); }
   void Start(const std::string &name, GPUSet devices) {
-    if (IsVerbose()) {
+    if (ConsoleLogger::ShouldLog(ConsoleLogger::LV::kDebug)) {
 #ifdef __CUDACC__
       for (auto device : devices) {
         cudaSetDevice(device);
@@ -94,7 +90,7 @@ struct Monitor {
     statistics_map[name].count++;
   }
   void Stop(const std::string &name, GPUSet devices) {
-    if (IsVerbose()) {
+    if (ConsoleLogger::ShouldLog(ConsoleLogger::LV::kDebug)) {
 #ifdef __CUDACC__
       for (auto device : devices) {
         cudaSetDevice(device);

diff --git a/src/logging.cc b/src/logging.cc
@@ -23,8 +23,7 @@ void dmlc::CustomLogMessage::Log(const std::string& msg) {
 namespace xgboost {
 
 ConsoleLogger::~ConsoleLogger() {
-  if (cur_verbosity_ == LogVerbosity::kIgnore ||
-      cur_verbosity_ <= global_verbosity_) {
+  if (ShouldLog(cur_verbosity_)) {
     dmlc::CustomLogMessage::Log(BaseLogger::log_stream_.str());
   }
 }
@@ -46,6 +45,11 @@ ConsoleLogger::LogVerbosity ConsoleLogger::global_verbosity_ =
     ConsoleLogger::DefaultVerbosity();
 
 ConsoleLoggerParam ConsoleLogger::param_ = ConsoleLoggerParam();
+
+bool ConsoleLogger::ShouldLog(LogVerbosity verbosity) {
+  return verbosity <= global_verbosity_ || verbosity == LV::kIgnore;
+}
+
 void ConsoleLogger::Configure(const std::map<std::string, std::string>& args) {
   param_.InitAllowUnknown(args);
   // Deprecated, but when trying to display deprecation message some R
@@ -80,7 +84,6 @@ ConsoleLogger::LogVerbosity ConsoleLogger::GlobalVerbosity() {
   return global_verbosity_;
 }
 
-ConsoleLogger::ConsoleLogger() : cur_verbosity_{LogVerbosity::kInfo} {}
 ConsoleLogger::ConsoleLogger(LogVerbosity cur_verb) :
     cur_verbosity_{cur_verb} {}
 
@@ -89,11 +92,17 @@ ConsoleLogger::ConsoleLogger(
   cur_verbosity_ = cur_verb;
   switch (cur_verbosity_) {
     case LogVerbosity::kWarning:
-      BaseLogger::log_stream_ << "WARNING: ";
+      BaseLogger::log_stream_ << "WARNING: "
+                              << file << ":" << line << ": ";
+      break;
     case LogVerbosity::kDebug:
-      BaseLogger::log_stream_ << "DEBUG: ";
+      BaseLogger::log_stream_ << "DEBUG: "
+                              << file << ":" << line << ": ";
+      break;
     case LogVerbosity::kInfo:
-      BaseLogger::log_stream_ << "INFO: ";
+      BaseLogger::log_stream_ << "INFO: "
+                              << file << ":" << line << ": ";
+      break;
     case LogVerbosity::kIgnore:
       BaseLogger::log_stream_ << file << ":" << line << ": ";
       break;

diff --git a/src/tree/updater_gpu_hist.cu b/src/tree/updater_gpu_hist.cu
@@ -971,9 +971,7 @@ class GPUHistMakerSpecialised{
       device_list_[index] = device_id;
     }
 
-    reducer_.Init(
-        device_list_,
-        ConsoleLogger::GlobalVerbosity() > ConsoleLogger::DefaultVerbosity());
+    reducer_.Init(device_list_);
 
     auto batch_iter = dmat->GetRowBatches().begin();
     const SparsePage& batch = *batch_iter;

diff --git a/src/tree/updater_quantile_hist.cc b/src/tree/updater_quantile_hist.cc
@@ -206,10 +206,6 @@ void QuantileHistMaker::Builder::Update(const GHistIndexMatrix& gmat,
 
   pruner_->Update(gpair, p_fmat, std::vector<RegTree*>{p_tree});
 
-  if (ConsoleLogger::GlobalVerbosity() <= ConsoleLogger::DefaultVerbosity()) {
-    // Don't construct the following huge stream.
-    return;
-  }
   double total_time = dmlc::GetTime() - gstart;
   LOG(INFO) << "\nInitData:          "
             << std::fixed << std::setw(6) << std::setprecision(4) << time_init_data

diff --git a/tests/cpp/common/test_monitor.cc b/tests/cpp/common/test_monitor.cc
@@ -5,7 +5,7 @@
 
 namespace xgboost {
 namespace common {
-TEST(Monitor, Basic) {
+TEST(Monitor, Logging) {
   auto run_monitor =
       []() {
         Monitor monitor_;
@@ -21,12 +21,13 @@ TEST(Monitor, Basic) {
   std::string output = testing::internal::GetCapturedStderr();
   ASSERT_NE(output.find("Monitor"), std::string::npos);
 
+  // Monitor only prints messages when set to DEBUG.
   args = {std::make_pair("verbosity", "2")};
   ConsoleLogger::Configure(args.cbegin(), args.cend());
   testing::internal::CaptureStderr();
   run_monitor();
   output = testing::internal::GetCapturedStderr();
-  ASSERT_EQ(output.find("Monitor"), std::string::npos);
+  ASSERT_EQ(output.size(), 0);
 }
 }  // namespace common
 }  // namespace xgboost
diff --git a/tests/cpp/test_logging.cc b/tests/cpp/test_logging.cc
@@ -7,10 +7,13 @@ namespace xgboost {
 
 TEST(Logging, Basic) {
   std::map<std::string, std::string> args {};
+  std::string output;
+
   args["verbosity"] = "0";  // silent
   ConsoleLogger::Configure(args.cbegin(), args.cend());
   testing::internal::CaptureStderr();
-  std::string output = testing::internal::GetCapturedStderr();
+  LOG(DEBUG) << "Test silent.";
+  output = testing::internal::GetCapturedStderr();
   ASSERT_EQ(output.length(), 0);
 
   args["verbosity"] = "3";  // debug
@@ -22,7 +25,7 @@ TEST(Logging, Basic) {
   ASSERT_NE(output.find("WARNING"), std::string::npos);
 
   testing::internal::CaptureStderr();
-  LOG(INFO) << "Test Log Info";
+  LOG(INFO) << "Test Log Info.";
   output = testing::internal::GetCapturedStderr();
   ASSERT_NE(output.find("Test Log Info"), std::string::npos);
 
@@ -31,15 +34,22 @@ TEST(Logging, Basic) {
   output = testing::internal::GetCapturedStderr();
   ASSERT_NE(output.find("DEBUG"), std::string::npos);
 
+  args["verbosity"] = "1";  // warning
+  ConsoleLogger::Configure(args.cbegin(), args.cend());
+  testing::internal::CaptureStderr();
+  LOG(INFO) << "INFO should not be displayed when set to warning.";
+  output = testing::internal::GetCapturedStderr();
+  ASSERT_EQ(output.size(), 0);
+
   args["silent"] = "True";
   ConsoleLogger::Configure(args.cbegin(), args.cend());
   testing::internal::CaptureStderr();
-  LOG(INFO) << "Test Log Info";
+  LOG(INFO) << "Test silent parameter.";
   output = testing::internal::GetCapturedStderr();
   ASSERT_EQ(output.length(), 0);
 
   testing::internal::CaptureStderr();
-  LOG(CONSOLE) << "Test Log Console";
+  LOG(CONSOLE) << "Test Log Console";  // ignore global setting.
   output = testing::internal::GetCapturedStderr();
   ASSERT_NE(output.find("Test Log Console"), std::string::npos);
 }