diff --git a/include/xgboost/logging.h b/include/xgboost/logging.h index 7a0493944b4f..ac6adf36a5cd 100644 --- 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,21 +124,30 @@ using LogCallbackRegistryStore = dmlc::ThreadLocalStore; #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 @@ -145,8 +155,8 @@ using LogCallbackRegistryStore = dmlc::ThreadLocalStore; #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 index 254b92bb88b5..bb9d14893824 100644 --- a/src/common/device_helpers.cuh +++ b/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 streams; std::vector 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 &device_ordinals, bool debug_verbose) { + void Init(const std::vector &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 index a9c00e03782e..2d9a5ac62849 100644 --- a/src/common/timer.h +++ b/src/common/timer.h @@ -52,16 +52,12 @@ struct Monitor { std::string label = ""; std::map 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 index 8b28255459cf..b292f8f81c1e 100644 --- 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& 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 index ff17cdabf023..09f33a014568 100644 --- 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 index 7a85c88a8699..b55520cf1bd5 100644 --- 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{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 index 086eb00153fe..46fb47ac1141 100644 --- 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 index 31063ba4ff00..d32cab088508 100644 --- a/tests/cpp/test_logging.cc +++ b/tests/cpp/test_logging.cc @@ -7,10 +7,13 @@ namespace xgboost { TEST(Logging, Basic) { std::map 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); }