From 9ab3f807e8bb4ab4b874a2b1a6b65657a55158b7 Mon Sep 17 00:00:00 2001 From: Martin Braun Date: Thu, 18 Jan 2018 17:01:13 -0800 Subject: logging: Minor refactoring, skip empty log messages Empty log messages are now skipped for faster processing. The 'terminating' log message is now also empty (and thus skipped). Reviewed-by: Brent Stapleton --- host/lib/utils/log.cpp | 177 ++++++++++++++++++++++++++++--------------------- 1 file changed, 102 insertions(+), 75 deletions(-) diff --git a/host/lib/utils/log.cpp b/host/lib/utils/log.cpp index 0dd06e99c..af2cf4aa8 100644 --- a/host/lib/utils/log.cpp +++ b/host/lib/utils/log.cpp @@ -33,49 +33,52 @@ namespace pt = boost::posix_time; /*********************************************************************** * Helpers **********************************************************************/ -static std::string verbosity_color(const uhd::log::severity_level &level){ - switch(level){ - case (uhd::log::trace): - return PURPLE; - case(uhd::log::debug): - return BLUE; - case(uhd::log::info): - return GREEN; - case(uhd::log::warning): - return YELLOW; - case(uhd::log::error): - return RED; - case(uhd::log::fatal): - return BRED; - default: - return RESET_COLORS; +namespace { + std::string verbosity_color(const uhd::log::severity_level &level){ + switch(level){ + case (uhd::log::trace): + return PURPLE; + case(uhd::log::debug): + return BLUE; + case(uhd::log::info): + return GREEN; + case(uhd::log::warning): + return YELLOW; + case(uhd::log::error): + return RED; + case(uhd::log::fatal): + return BRED; + default: + return RESET_COLORS; + } } -} -static std::string verbosity_name(const uhd::log::severity_level &level){ - switch(level){ - case (uhd::log::trace): - return "TRACE"; - case(uhd::log::debug): - return "DEBUG"; - case(uhd::log::info): - return "INFO"; - case(uhd::log::warning): - return "WARNING"; - case(uhd::log::error): - return "ERROR"; - case(uhd::log::fatal): - return "FATAL"; - default: - return "-"; + std::string verbosity_name(const uhd::log::severity_level &level){ + switch(level){ + case (uhd::log::trace): + return "TRACE"; + case(uhd::log::debug): + return "DEBUG"; + case(uhd::log::info): + return "INFO"; + case(uhd::log::warning): + return "WARNING"; + case(uhd::log::error): + return "ERROR"; + case(uhd::log::fatal): + return "FATAL"; + default: + return "-"; + } + return ""; + } + + //! get the relative file path from the host directory + inline std::string path_to_filename(std::string path) + { + return path.substr(path.find_last_of("/\\") + 1); } - return ""; -} -//! get the relative file path from the host directory -inline std::string path_to_filename(std::string path) -{ - return path.substr(path.find_last_of("/\\") + 1); } /*********************************************************************** @@ -165,7 +168,6 @@ private: class log_resource { public: uhd::log::severity_level global_level; - std::map logger_level; log_resource(void): global_level(uhd::log::off), @@ -177,7 +179,10 @@ public: { //allow override from macro definition #ifdef UHD_LOG_MIN_LEVEL - this->global_level = _get_log_level(BOOST_STRINGIZE(UHD_LOG_MIN_LEVEL), this->global_level); + this->global_level = _get_log_level( + BOOST_STRINGIZE(UHD_LOG_MIN_LEVEL), + this->global_level + ); #endif //allow override from environment variables const char * log_level_env = std::getenv("UHD_LOG_LEVEL"); @@ -191,15 +196,18 @@ public: #ifndef UHD_LOG_CONSOLE_DISABLE uhd::log::severity_level console_level = uhd::log::trace; #ifdef UHD_LOG_CONSOLE_LEVEL - console_level = _get_log_level(BOOST_STRINGIZE(UHD_LOG_CONSOLE_LEVEL), console_level); + console_level = _get_log_level( + BOOST_STRINGIZE(UHD_LOG_CONSOLE_LEVEL), + console_level + ); #endif - const char * log_console_level_env = std::getenv("UHD_LOG_CONSOLE_LEVEL"); + const char* log_console_level_env = std::getenv("UHD_LOG_CONSOLE_LEVEL"); if (log_console_level_env != NULL && log_console_level_env[0] != '\0') { console_level = _get_log_level(log_console_level_env, console_level); } - logger_level[UHD_CONSOLE_LOGGER_KEY] = console_level; - _loggers[UHD_CONSOLE_LOGGER_KEY] = &console_log; + _loggers[UHD_CONSOLE_LOGGER_KEY] = + level_logfn_pair{console_level, &console_log}; #endif /***** File logging **************************************************/ @@ -218,9 +226,11 @@ public: log_file_target = std::string(log_file_env); } if (!log_file_target.empty()){ - logger_level[UHD_FILE_LOGGER_KEY] = file_level; auto F = boost::make_shared(log_file_target); - _loggers[UHD_FILE_LOGGER_KEY] = [F](const uhd::log::logging_info& log_info){F->log(log_info);}; + _loggers[UHD_FILE_LOGGER_KEY] = level_logfn_pair{ + file_level, + [F](const uhd::log::logging_info& log_info){F->log(log_info);} + }; } // On boot, we print the current UHD version info: @@ -245,8 +255,12 @@ public: } // Launch log message consumer - _pop_task = std::make_shared(std::thread([this](){this->pop_task();})); - _pop_fastpath_task = std::make_shared(std::thread([this](){this->pop_fastpath_task();})); + _pop_task = std::make_shared( + std::thread([this](){this->pop_task();}) + ); + _pop_fastpath_task = std::make_shared( + std::thread([this](){this->pop_fastpath_task();}) + ); } ~log_resource(void){ @@ -262,7 +276,7 @@ public: "LOGGING", boost::this_thread::get_id() ); - final_message.message = "Terminating logger."; + final_message.message = ""; push(final_message); #ifndef UHD_LOG_FASTPATH_DISABLE push_fastpath(""); @@ -294,36 +308,38 @@ public: #endif } + void _handle_log_info(const uhd::log::logging_info& log_info) + { + if (log_info.message.empty()) { + return; + } + std::lock_guard l(_logmap_mutex); + for (const auto& logger_pair : _loggers) { + const auto& logger = logger_pair.second; + if (log_info.verbosity < logger.first){ + continue; + } + logger.second(log_info); + } + } + void pop_task() { uhd::log::logging_info log_info; log_info.message = ""; + // For the lifetime of this thread, we run the following loop: while (!_exit) { - _log_queue.pop_with_wait(log_info); - { - std::lock_guard l(_logmap_mutex); - for (const auto &logger : _loggers) { - auto level = logger_level.find(logger.first); - if(level != logger_level.end() && log_info.verbosity < level->second){ - continue; - } - logger.second(log_info); - } - } + _log_queue.pop_with_wait(log_info); // Blocking call + _handle_log_info(log_info); } // Exit procedure: Clear the queue while (_log_queue.pop_with_haste(log_info)) { - std::lock_guard l(_logmap_mutex); - for (const auto &logger : _loggers) { - auto level = logger_level.find(logger.first); - if (level != logger_level.end() && log_info.verbosity < level->second){ - continue; - } - logger.second(log_info); - } + _handle_log_info(log_info); } + + // Terminate this thread. } void pop_fastpath_task() @@ -345,11 +361,20 @@ public: #endif } + void add_logger( + const std::string &key, + uhd::log::log_fn_t logger_fn + ) { + std::lock_guard l(_logmap_mutex); + _loggers[key] = level_logfn_pair{global_level, logger_fn}; + } - void add_logger(const std::string &key, uhd::log::log_fn_t logger_fn) - { + void set_log_level( + const std::string &key, + const uhd::log::severity_level level + ) { std::lock_guard l(_logmap_mutex); - _loggers[key] = logger_fn; + _loggers[key].first = level; } private: @@ -385,7 +410,9 @@ private: std::mutex _logmap_mutex; std::atomic _exit; - std::map _loggers; + using level_logfn_pair = + std::pair; + std::map _loggers; #ifndef UHD_LOG_FASTPATH_DISABLE uhd::transport::bounded_buffer _fastpath_queue; #endif @@ -414,7 +441,7 @@ uhd::_log::log::log( line, component, thread_id); - } + } } uhd::_log::log::~log(void) @@ -448,7 +475,7 @@ uhd::log::set_log_level(uhd::log::severity_level level){ void uhd::log::set_logger_level(const std::string &key, uhd::log::severity_level level){ - log_rs().logger_level[key] = level; + log_rs().set_log_level(key, level); } void -- cgit v1.2.3