From d37bded99485d2959ca932c1d9ceaa99304d77e3 Mon Sep 17 00:00:00 2001 From: gabi Date: Sun, 7 Dec 2014 04:18:07 +0200 Subject: [PATCH] More improvements to the async logger --- include/spdlog/async_logger.h | 7 +- include/spdlog/details/async_log_helper.h | 211 ++++++++++----------- include/spdlog/details/async_logger_impl.h | 14 +- include/spdlog/details/registry.h | 6 +- include/spdlog/details/spdlog_impl.h | 4 +- include/spdlog/spdlog.h | 3 +- 6 files changed, 114 insertions(+), 131 deletions(-) diff --git a/include/spdlog/async_logger.h b/include/spdlog/async_logger.h index 943a868a..7438d156 100644 --- a/include/spdlog/async_logger.h +++ b/include/spdlog/async_logger.h @@ -46,9 +46,9 @@ class async_logger :public logger { public: template - 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 _async_log_helper; }; } diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index 4d5e1513..af6efa26 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/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; using clock = std::chrono::steady_clock; - async_log_helper(formatter_ptr formatter, const std::vector& sinks, size_t queue_size); + async_log_helper(formatter_ptr formatter, const std::vector& 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 _active; - formatter_ptr _formatter; - std::vector> _sinks; +private: + std::atomic _active; + formatter_ptr _formatter; + std::vector> _sinks; q_type _q; - std::thread _worker_thread; + std::thread _worker_thread; // last exception thrown from the worker thread std::shared_ptr _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& 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(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(ex.what()); - } - catch (...) - { - _last_workerthread_ex = std::make_shared("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 bool spdlog::details::async_log_helper::process_next_msg(clock::time_point& last_pop) +{ + + async_msg incoming_async_msg; + log_msg incoming_log_msg; + + if (_q.dequeue(incoming_async_msg)) + { + last_pop = clock::now(); + try + { + 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(std::string("async_logger worker thread exception: ") + ex.what()); + } + catch (...) + { + _last_workerthread_ex = std::make_shared("async_logger worker thread exception"); + } + return true; + } + // sleep or yield if queue is empty. + else + { + sleep_or_yield(last_pop); + return false; + } +} + inline void spdlog::details::async_log_helper::set_formatter(formatter_ptr msg_formatter) { _formatter = msg_formatter; } -inline void spdlog::details::async_log_helper::shutdown(const log_clock::duration& timeout) -{ - /* - if (timeout > std::chrono::milliseconds::zero()) - { - auto until = log_clock::now() + timeout; - while (_q.approx_size() > 0 && log_clock::now() < until) - { - std::this_thread::sleep_for(std::chrono::milliseconds(5)); - } - } - join_worker(); - */ -} - -// 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 - { - _worker_thread.join(); - } - catch (const std::system_error&) //Dont crash if thread not joinable - { - } - } + try + { + _worker_thread.join(); + } + catch (const std::system_error&) //Dont crash if thread not joinable + {} } diff --git a/include/spdlog/details/async_logger_impl.h b/include/spdlog/details/async_logger_impl.h index 03a09f9c..0b3022ec 100644 --- a/include/spdlog/details/async_logger_impl.h +++ b/include/spdlog/details/async_logger_impl.h @@ -34,18 +34,17 @@ template -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) diff --git a/include/spdlog/details/registry.h b/include/spdlog/details/registry.h index ee6c7d95..0e24ba26 100644 --- a/include/spdlog/details/registry.h +++ b/include/spdlog/details/registry.h @@ -61,7 +61,7 @@ public: return found->second; std::shared_ptr new_logger; if (_async_mode) - new_logger = std::make_shared(logger_name, sinks_begin, sinks_end, _async_q_size, _async_shutdown_duration); + new_logger = std::make_shared(logger_name, sinks_begin, sinks_end, _async_q_size); else new_logger = std::make_shared(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 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; }; } } diff --git a/include/spdlog/details/spdlog_impl.h b/include/spdlog/details/spdlog_impl.h index a3a76111..6b559064 100644 --- a/include/spdlog/details/spdlog_impl.h +++ b/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() diff --git a/include/spdlog/spdlog.h b/include/spdlog/spdlog.h index 6db7ca3d..4841854e 100644 --- a/include/spdlog/spdlog.h +++ b/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();