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 <brent.stapleton@ettus.com>

1 files 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<std::string, uhd::log::severity_level> 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<file_logger_backend>(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>(std::thread([this](){this->pop_task();}));
-        _pop_fastpath_task = std::make_shared<std::thread>(std::thread([this](){this->pop_fastpath_task();}));
+        _pop_task = std::make_shared<std::thread>(
+            std::thread([this](){this->pop_task();})
+        );
+        _pop_fastpath_task = std::make_shared<std::thread>(
+            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<std::mutex> 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<std::mutex> 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<std::mutex> 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<std::mutex> 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<std::mutex> l(_logmap_mutex);
-        _loggers[key] = logger_fn;
+        _loggers[key].first = level;
     }
 
 private:
@@ -385,7 +410,9 @@ private:
 
     std::mutex _logmap_mutex;
     std::atomic<bool> _exit;
-    std::map<std::string, uhd::log::log_fn_t> _loggers;
+    using level_logfn_pair =
+        std::pair<uhd::log::severity_level, uhd::log::log_fn_t>;
+    std::map<std::string, level_logfn_pair> _loggers;
 #ifndef UHD_LOG_FASTPATH_DISABLE
     uhd::transport::bounded_buffer<std::string> _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