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.

src/common/device_helpers.cuh

@@ -842,7 +842,6 @@ 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
@@ -850,8 +849,9 @@ class AllReducer {
   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;

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);

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;

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;

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