More improvements to the async logger

include/spdlog/async_logger.h

@@ -46,9 +46,9 @@ class async_logger :public logger
 {
 public:
     template<class It>
-    async_logger(const std::string& name, const It& begin, const It& end, size_t queue_size, const log_clock::duration& shutdown_duration);
-    async_logger(const std::string& logger_name, sinks_init_list sinks, size_t queue_size, const log_clock::duration& shutdown_duration);
-    async_logger(const std::string& logger_name, sink_ptr single_sink, size_t queue_size, const log_clock::duration& shutdown_duration);
+    async_logger(const std::string& name, const It& begin, const It& end, size_t queue_size);
+    async_logger(const std::string& logger_name, sinks_init_list sinks, size_t queue_size);
+    async_logger(const std::string& logger_name, sink_ptr single_sink, size_t queue_size);
 
 
 protected:
@@ -58,7 +58,6 @@ protected:
     void _stop() override;
 
 private:
-    log_clock::duration _shutdown_duration;
     std::unique_ptr<details::async_log_helper> _async_log_helper;
 };
 }

include/spdlog/details/async_log_helper.h

@@ -52,8 +52,8 @@ namespace details
 
 class async_log_helper
 {
-	// Async msg to move to/from the queue
-	// Movable only. should never be copied
+    // Async msg to move to/from the queue
+    // Movable only. should never be copied
     struct async_msg
     {
         std::string logger_name;
@@ -61,11 +61,11 @@ class async_log_helper
         log_clock::time_point time;
         std::string txt;
 
-		async_msg() = default;
-		~async_msg() = default;
+        async_msg() = default;
+        ~async_msg() = default;
 
-		async_msg(const async_msg&) = delete;
-		async_msg& operator=(async_msg& other) = delete;
+        async_msg(const async_msg&) = delete;
+        async_msg& operator=(async_msg& other) = delete;
 
         async_msg(const details::log_msg& m) :
             logger_name(m.logger_name),
@@ -74,26 +74,26 @@ class async_log_helper
             txt(m.raw.data(), m.raw.size())
         {}
 
-		async_msg(async_msg&& other) :
+        async_msg(async_msg&& other) :
             logger_name(std::move(other.logger_name)),
             level(std::move(other.level)),
             time(std::move(other.time)),
             txt(std::move(other.txt))
         {}
 
-		async_msg& operator=(async_msg&& other)
-		{
-			logger_name = std::move(other.logger_name);
-			level = other.level;
-			time = std::move(other.time);
-			txt = std::move(other.txt);
-			return *this;
-		}
+        async_msg& operator=(async_msg&& other)
+        {
+            logger_name = std::move(other.logger_name);
+            level = other.level;
+            time = std::move(other.time);
+            txt = std::move(other.txt);
+            return *this;
+        }
 
 
         void fill_log_msg(log_msg &msg)
         {
-			msg.clear();
+            msg.clear();
             msg.logger_name = logger_name;
             msg.level = level;
             msg.time = time;
@@ -103,42 +103,41 @@ class async_log_helper
 
 public:
 
-	using item_type = async_msg;
+    using item_type = async_msg;
     using q_type = details::mpmc_bounded_queue<item_type>;
 
     using clock = std::chrono::steady_clock;
 
 
-	async_log_helper(formatter_ptr formatter, const std::vector<sink_ptr>& sinks, size_t queue_size);
+    async_log_helper(formatter_ptr formatter, const std::vector<sink_ptr>& sinks, size_t queue_size);
     void log(const details::log_msg& msg);
 
     //Stop logging and join the back thread
-    ~async_log_helper();   
+    ~async_log_helper();
     void set_formatter(formatter_ptr);
-    //Wait to remaining items (if any) in the queue to be written and shutdown
-    void shutdown(const log_clock::duration& timeout);
-
 
 
-private:	
-	std::atomic<bool> _active;
-	formatter_ptr _formatter;
-    std::vector<std::shared_ptr<sinks::sink>> _sinks;    
+private:
+    std::atomic<bool> _active;
+    formatter_ptr _formatter;
+    std::vector<std::shared_ptr<sinks::sink>> _sinks;
     q_type _q;
-    std::thread _worker_thread;    
+    std::thread _worker_thread;
 
     // last exception thrown from the worker thread
     std::shared_ptr<spdlog_ex> _last_workerthread_ex;
-    
 
 
-
-    // will throw last worker thread exception or if worker thread no active
+    // throw last worker thread exception or if worker thread is not active
     void throw_if_bad_worker();
 
-    // worker thread loop
+    // worker thread main loop
     void worker_loop();
 
+    //pop next message from the queue and process it
+    //return true if a message was available (queue was not empty), will set the last_pop to the pop time
+    bool process_next_msg(clock::time_point& last_pop);
+
     // guess how much to sleep if queue is empty/full using last succesful op time as hint
     static void sleep_or_yield(const clock::time_point& last_op_time);
 
@@ -146,7 +145,6 @@ private:
     // clear all remaining messages(if any), stop the _worker_thread and join it
     void join_worker();
 
-
 };
 }
 }
@@ -155,11 +153,11 @@ private:
 // async_sink class implementation
 ///////////////////////////////////////////////////////////////////////////////
 inline spdlog::details::async_log_helper::async_log_helper(formatter_ptr formatter, const std::vector<sink_ptr>& sinks, size_t queue_size):
-	_active(false),
-	_formatter(formatter),
-	_sinks(sinks),
-     _q(queue_size),
-     _worker_thread(&async_log_helper::worker_loop, this)
+    _active(true),
+    _formatter(formatter),
+    _sinks(sinks),
+    _q(queue_size),
+    _worker_thread(&async_log_helper::worker_loop, this)
 {}
 
 inline spdlog::details::async_log_helper::~async_log_helper()
@@ -172,97 +170,92 @@ inline spdlog::details::async_log_helper::~async_log_helper()
 inline void spdlog::details::async_log_helper::log(const details::log_msg& msg)
 {
     throw_if_bad_worker();
-
-    //Only if queue is full, enter wait loop
-    //if (!_q.push(std::unique_ptr < async_msg >(new async_msg(msg))))
-    //async_msg* as = new async_msg(msg);
-    //if (!_q.enqueue(std::unique_ptr<async_msg>(new async_msg(msg))))
-	if (!_q.enqueue(std::move(async_msg(msg))))
-    {	
+    async_msg new_msg(msg);
+    if (!_q.enqueue(std::move(new_msg)))
+    {
         auto last_op_time = clock::now();
         do
         {
             sleep_or_yield(last_op_time);
         }
-        while (!_q.enqueue(std::move(async_msg(msg))));
+        while (!_q.enqueue(std::move(new_msg)));
     }
-	
+
 }
 
 inline void spdlog::details::async_log_helper::worker_loop()
 {
-	log_msg popped_log_msg;
-    clock::time_point last_pop = clock::now();	
-	_active = true;
+    clock::time_point last_pop = clock::now();
     while (_active)
     {
-        q_type::item_type popped_msg;
-
-        if (_q.dequeue(popped_msg))
-        {			
-            last_pop = clock::now();
-
-            try
-            {
-                popped_msg.fill_log_msg(popped_log_msg);
-                _formatter->format(popped_log_msg);
-                for (auto &s : _sinks)
-                    s->log(popped_log_msg);								
-            }
-            catch (const std::exception& ex)
-            {
-                _last_workerthread_ex = std::make_shared<spdlog_ex>(ex.what());
-            }
-            catch (...)
-            {
-                _last_workerthread_ex = std::make_shared<spdlog_ex>("Unknown exception");
-            }
-        }
-        // sleep or yield if queue is empty.
-        else
-        {			 
-            sleep_or_yield(last_pop);
-        }
+        //Dont die if there are still messages in the q to process
+        while(process_next_msg(last_pop));
     }
 }
 
 
-inline void spdlog::details::async_log_helper::set_formatter(formatter_ptr msg_formatter)
+inline bool spdlog::details::async_log_helper::process_next_msg(clock::time_point& last_pop)
 {
-    _formatter = msg_formatter;
-}
 
-inline void spdlog::details::async_log_helper::shutdown(const log_clock::duration& timeout)
-{
-    /*
-    if (timeout > std::chrono::milliseconds::zero())
+    async_msg incoming_async_msg;
+    log_msg incoming_log_msg;
+
+    if (_q.dequeue(incoming_async_msg))
     {
-        auto until = log_clock::now() + timeout;
-        while (_q.approx_size() > 0 && log_clock::now() < until)
+        last_pop = clock::now();
+        try
         {
-            std::this_thread::sleep_for(std::chrono::milliseconds(5));
+            incoming_async_msg.fill_log_msg(incoming_log_msg);
+            _formatter->format(incoming_log_msg);
+            for (auto &s : _sinks)
+                s->log(incoming_log_msg);
         }
+        catch (const std::exception& ex)
+        {
+            _last_workerthread_ex = std::make_shared<spdlog_ex>(std::string("async_logger worker thread exception: ") + ex.what());
+        }
+        catch (...)
+        {
+            _last_workerthread_ex = std::make_shared<spdlog_ex>("async_logger worker thread exception");
+        }
+        return true;
+    }
+    // sleep or yield if queue is empty.
+    else
+    {
+        sleep_or_yield(last_pop);
+        return false;
     }
-    join_worker();
-     */
+}
+
+inline void spdlog::details::async_log_helper::set_formatter(formatter_ptr msg_formatter)
+{
+    _formatter = msg_formatter;
 }
 
 
-// Sleep or yield using the time passed since last message as a hint
+// Sleep,yield or return immediatly using the time passed since last message as a hint
 inline void spdlog::details::async_log_helper::sleep_or_yield(const clock::time_point& last_op_time)
 {
     using std::chrono::milliseconds;
-    using std::this_thread::sleep_for;
-    using std::this_thread::yield;
+    using namespace std::this_thread;
 
-    clock::duration sleep_duration;
     auto time_since_op = clock::now() - last_op_time;
-    if (time_since_op > milliseconds(1000))
-        sleep_for(milliseconds(500));
-    else if (time_since_op > milliseconds(1))
-        sleep_for(time_since_op / 2);
-    else
-        yield();
+
+    //spin upto 1 ms
+    if (time_since_op <= milliseconds(1))
+        return;
+
+    // yield upto 10ms
+    if (time_since_op <= milliseconds(10))
+        return yield();
+
+
+    // sleep for half of duration since last op
+    if (time_since_op <= milliseconds(100))
+        return sleep_for(time_since_op / 2);
+
+    return sleep_for(milliseconds(100));
 }
 
 //throw if the worker thread threw an exception or not active
@@ -282,17 +275,13 @@ inline void spdlog::details::async_log_helper::throw_if_bad_worker()
 inline void spdlog::details::async_log_helper::join_worker()
 {
     _active = false;
-    if (_worker_thread.joinable())
+
+    try
     {
-        try
-        {
-            _worker_thread.join();
-        }
-        catch (const std::system_error&) //Dont crash if thread not joinable
-        {
-        }
+        _worker_thread.join();
     }
-
+    catch (const std::system_error&) //Dont crash if thread not joinable
+    {}
 }
 
 

include/spdlog/details/async_logger_impl.h

@@ -34,18 +34,17 @@
 
 
 template<class It>
-inline spdlog::async_logger::async_logger(const std::string& logger_name, const It& begin, const It& end, size_t queue_size, const log_clock::duration& shutdown_duration) :
+inline spdlog::async_logger::async_logger(const std::string& logger_name, const It& begin, const It& end, size_t queue_size) :
     logger(logger_name, begin, end),
-    _shutdown_duration(shutdown_duration),
     _async_log_helper(new details::async_log_helper(_formatter, _sinks, queue_size))
-{    
+{
 }
 
-inline spdlog::async_logger::async_logger(const std::string& logger_name, sinks_init_list sinks, size_t queue_size, const log_clock::duration& shutdown_duration) :
-    async_logger(logger_name, sinks.begin(), sinks.end(), queue_size, shutdown_duration) {}
+inline spdlog::async_logger::async_logger(const std::string& logger_name, sinks_init_list sinks, size_t queue_size) :
+    async_logger(logger_name, sinks.begin(), sinks.end(), queue_size) {}
 
-inline spdlog::async_logger::async_logger(const std::string& logger_name, sink_ptr single_sink, size_t queue_size, const log_clock::duration& shutdown_duration) :
-    async_logger(logger_name, { single_sink }, queue_size, shutdown_duration) {}
+inline spdlog::async_logger::async_logger(const std::string& logger_name, sink_ptr single_sink, size_t queue_size) :
+    async_logger(logger_name, { single_sink }, queue_size) {}
 
 
 inline void spdlog::async_logger::_set_formatter(spdlog::formatter_ptr msg_formatter)
@@ -65,7 +64,6 @@ inline void spdlog::async_logger::_set_pattern(const std::string& pattern)
 inline void spdlog::async_logger::_stop()
 {
     set_level(level::OFF);
-    _async_log_helper->shutdown(_shutdown_duration);
 }
 
 inline void spdlog::async_logger::_log_msg(details::log_msg& msg)

include/spdlog/details/registry.h

@@ -61,7 +61,7 @@ public:
             return found->second;
         std::shared_ptr<logger> new_logger;
         if (_async_mode)
-            new_logger = std::make_shared<async_logger>(logger_name, sinks_begin, sinks_end, _async_q_size, _async_shutdown_duration);
+            new_logger = std::make_shared<async_logger>(logger_name, sinks_begin, sinks_end, _async_q_size);
         else
             new_logger = std::make_shared<logger>(logger_name, sinks_begin, sinks_end);
 
@@ -114,12 +114,11 @@ public:
             l.second->set_level(log_level);
     }
 
-    void set_async_mode(size_t q_size, const log_clock::duration& shutdown_duration)
+    void set_async_mode(size_t q_size)
     {
         std::lock_guard<std::mutex> lock(_mutex);
         _async_mode = true;
         _async_q_size = q_size;
-        _async_shutdown_duration = shutdown_duration;
     }
 
     void set_sync_mode()
@@ -153,7 +152,6 @@ private:
     level::level_enum _level = level::INFO;
     bool _async_mode = false;
     size_t _async_q_size = 0;
-    log_clock::duration _async_shutdown_duration;
 };
 }
 }

include/spdlog/details/spdlog_impl.h

@@ -133,9 +133,9 @@ inline void spdlog::set_level(level::level_enum log_level)
 }
 
 
-inline void spdlog::set_async_mode(size_t queue_size, const log_clock::duration& shutdown_duration)
+inline void spdlog::set_async_mode(size_t queue_size)
 {
-    details::registry::instance().set_async_mode(queue_size, shutdown_duration);
+    details::registry::instance().set_async_mode(queue_size);
 }
 
 inline void spdlog::set_sync_mode()

include/spdlog/spdlog.h

@@ -65,9 +65,8 @@ void set_level(level::level_enum log_level);
 //
 
 // Turn on async mode and set the queue size for each async_logger
-// shutdown_duration indicates max time to wait for the worker thread to log its messages before terminating.
 
-void set_async_mode(size_t queue_size, const log_clock::duration& shutdown_duration = std::chrono::seconds(5));
+void set_async_mode(size_t queue_size);
 // Turn off async mode
 void set_sync_mode();