log: Moved fastpath logging to its own thread

4 files changed, 62 insertions, 4 deletions

diff --git a/host/include/uhd/utils/log.hpp b/host/include/uhd/utils/log.hpp
index a27a536b1..24c7bc1c6 100644
--- a/host/include/uhd/utils/log.hpp
+++ b/host/include/uhd/utils/log.hpp
@@ -248,8 +248,12 @@ namespace uhd {
 #endif
 
 #ifndef UHD_LOG_FASTPATH_DISABLE
+//! Extra-fast logging macro for when speed matters.
+// No metadata is tracked. Only the message is displayed. This does not go
+// through the regular backends. Mostly used for printing the UOSDL characters
+// during streaming.
 #define UHD_LOG_FASTPATH(message)               \
-    std::cerr << message << std::flush;
+    uhd::_log::log_fastpath(message);
 #else
 #define UHD_LOG_FASTPATH(message)
 #endif
@@ -284,7 +288,10 @@ namespace uhd {
 //! \cond
 namespace uhd{ namespace _log {
 
-    //! \internal Internal logging object (called by UHD_LOG macros)
+    //! Fastpath logging
+    void UHD_API log_fastpath(const std::string &msg);
+
+    //! Internal logging object (called by UHD_LOG* macros)
     class UHD_API log {
     public:
         log(
@@ -297,7 +304,7 @@ namespace uhd{ namespace _log {
 
         ~log(void);
 
-        // \internal Macro for overloading insertion operators to avoid costly
+        // Macro for overloading insertion operators to avoid costly
         // conversion of types if not logging.
         #define INSERTION_OVERLOAD(x)   log& operator<< (x)             \
                                         {                               \
diff --git a/host/lib/usrp/n230/n230_resource_manager.cpp b/host/lib/usrp/n230/n230_resource_manager.cpp
index 4de5f77ec..61a80ae43 100644
--- a/host/lib/usrp/n230/n230_resource_manager.cpp
+++ b/host/lib/usrp/n230/n230_resource_manager.cpp
@@ -488,7 +488,7 @@ bool n230_resource_manager::_radio_data_loopback_self_test(wb_iface::sptr iface)
         const uint32_t rb_rx = uint32_t(rb_word64 & 0xffffffff);
         test_fail = word32 != rb_tx or word32 != rb_rx;
         if (test_fail){
-            UHD_LOG_FASTPATH(boost::format("mismatch (exp:%x, got:%x and %x)... ") % word32 % rb_tx % rb_rx)
+            UHD_LOG_ERROR("N230", str(boost::format("mismatch (exp:%x, got:%x and %x)... ") % word32 % rb_tx % rb_rx));
             break; //exit loop on any failure
         }
     }
diff --git a/host/lib/utils/log.cpp b/host/lib/utils/log.cpp
index c77e082ef..10baaf3f4 100644
--- a/host/lib/utils/log.cpp
+++ b/host/lib/utils/log.cpp
@@ -179,6 +179,9 @@ public:
     log_resource(void):
         global_level(uhd::log::off),
         _exit(false),
+#ifndef UHD_LOG_FASTPATH_DISABLE
+        _fastpath_queue(10),
+#endif
         _log_queue(10)
     {
         //allow override from macro definition
@@ -231,6 +234,7 @@ 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();}));
     }
 
     ~log_resource(void){
@@ -240,6 +244,11 @@ public:
             std::lock_guard<std::mutex> l(_logmap_mutex);
             _loggers.clear();
         }
+        _pop_task.reset();
+#ifndef UHD_LOG_FASTPATH_DISABLE
+        _pop_fastpath_task->join();
+        _pop_fastpath_task.reset();
+#endif
     }
 
     void push(const uhd::log::logging_info& log_info)
@@ -247,6 +256,15 @@ public:
         _log_queue.push_with_haste(log_info);
     }
 
+    void push_fastpath(const std::string &message)
+    {
+        // Never wait. If the buffer is full, we just don't see the message.
+        // Too bad.
+#ifndef UHD_LOG_FASTPATH_DISABLE
+        _fastpath_queue.push_with_haste(message);
+#endif
+    }
+
     void pop_task()
     {
         uhd::log::logging_info log_info;
@@ -278,6 +296,25 @@ public:
         }
     }
 
+    void pop_fastpath_task()
+    {
+#ifndef UHD_LOG_FASTPATH_DISABLE
+        while (!_exit) {
+            std::string msg;
+            if (_fastpath_queue.pop_with_timed_wait(msg, 1)){
+                std::cerr << msg << std::flush;
+            }
+        }
+
+        // Exit procedure: Clear the queue
+        std::string msg;
+        while (_fastpath_queue.pop_with_haste(msg)) {
+            std::cerr << msg << std::flush;
+        }
+#endif
+    }
+
+
     void add_logger(const std::string &key, uhd::log::log_fn_t logger_fn)
     {
         std::lock_guard<std::mutex> l(_logmap_mutex);
@@ -286,6 +323,9 @@ public:
 
 private:
     std::shared_ptr<std::thread> _pop_task;
+#ifndef UHD_LOG_FASTPATH_DISABLE
+    std::shared_ptr<std::thread> _pop_fastpath_task;
+#endif
     uhd::log::severity_level _get_log_level(const std::string &log_level_str,
                                             const uhd::log::severity_level &previous_level){
         if (std::isdigit(log_level_str[0])) {
@@ -316,6 +356,9 @@ private:
     std::atomic<bool> _exit;
     std::map<std::string, uhd::log::log_fn_t> _loggers;
     uhd::transport::bounded_buffer<uhd::log::logging_info> _log_queue;
+#ifndef UHD_LOG_FASTPATH_DISABLE
+    uhd::transport::bounded_buffer<std::string> _fastpath_queue;
+#endif
 };
 
 UHD_SINGLETON_FCN(log_resource, log_rs);
@@ -351,6 +394,12 @@ uhd::_log::log::~log(void)
     }
 }
 
+void uhd::_log::log_fastpath(const std::string &msg)
+{
+#ifndef UHD_LOG_FASTPATH_DISABLE
+    log_rs().push_fastpath(msg);
+#endif
+}
 
 /***********************************************************************
  * Public API calls
diff --git a/host/tests/log_test.cpp b/host/tests/log_test.cpp
index d42e5ffbd..c466777fc 100644
--- a/host/tests/log_test.cpp
+++ b/host/tests/log_test.cpp
@@ -20,6 +20,8 @@
 #include <iostream>
 
 BOOST_AUTO_TEST_CASE(test_messages){
+    UHD_LOG_FASTPATH("foo");
+    UHD_LOG_FASTPATH("bar");
     uhd::log::set_log_level(uhd::log::debug);
     uhd::log::set_console_level(uhd::log::info);
     uhd::log::add_logger("test",