From f363fff109757840410d8d7b18947cc53e8744a6 Mon Sep 17 00:00:00 2001 From: Denis Ivaykin Date: Sat, 9 May 2015 22:30:05 +0200 Subject: [PATCH 1/3] async auto flush --- include/spdlog/async_logger.h | 9 ++++-- include/spdlog/details/async_log_helper.h | 37 ++++++++++++++++------ include/spdlog/details/async_logger_impl.h | 15 +++++---- 3 files changed, 42 insertions(+), 19 deletions(-) diff --git a/include/spdlog/async_logger.h b/include/spdlog/async_logger.h index 7bcde900..a802b03c 100644 --- a/include/spdlog/async_logger.h +++ b/include/spdlog/async_logger.h @@ -58,19 +58,22 @@ public: const It& end, size_t queue_size, const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, - const std::function& worker_warmup_cb = nullptr); + const std::function& worker_warmup_cb = nullptr, + const std::chrono::milliseconds auto_flush_millis = std::chrono::milliseconds::zero()); async_logger(const std::string& logger_name, sinks_init_list sinks, size_t queue_size, const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, - const std::function& worker_warmup_cb = nullptr); + const std::function& worker_warmup_cb = nullptr, + const std::chrono::milliseconds auto_flush_millis = std::chrono::milliseconds::zero()); async_logger(const std::string& logger_name, sink_ptr single_sink, size_t queue_size, const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, - const std::function& worker_warmup_cb = nullptr); + const std::function& worker_warmup_cb = nullptr, + const std::chrono::milliseconds auto_flush_millis = std::chrono::milliseconds::zero()); protected: diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index 657c70bb..9fe38cff 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -65,7 +65,7 @@ class async_log_helper async_msg() = default; ~async_msg() = default; -async_msg(async_msg&& other) SPDLOG_NOEXCEPT: + async_msg(async_msg&& other) SPDLOG_NOEXCEPT: logger_name(std::move(other.logger_name)), level(std::move(other.level)), time(std::move(other.time)), @@ -119,7 +119,8 @@ public: const std::vector& sinks, size_t queue_size, const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, - const std::function& worker_warmup_cb = nullptr); + const std::function& worker_warmup_cb = nullptr, + const std::chrono::milliseconds auto_flush_millis = std::chrono::milliseconds::zero()); void log(const details::log_msg& msg); @@ -145,6 +146,9 @@ private: // worker thread warmup callback - one can set thread priority, affinity, etc const std::function _worker_warmup_cb; + // auto periodic sink flush parameter + const std::chrono::milliseconds _auto_flush_millis; + // worker thread std::thread _worker_thread; @@ -159,7 +163,7 @@ private: bool process_next_msg(clock::time_point& last_pop); // sleep,yield or return immediatly using the time passed since last message as a hint - static void sleep_or_yield(const clock::time_point& last_op_time); + static std::chrono::nanoseconds sleep_or_yield(const clock::time_point& last_op_time); }; } @@ -168,12 +172,13 @@ 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, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb): +inline spdlog::details::async_log_helper::async_log_helper(formatter_ptr formatter, const std::vector& sinks, size_t queue_size, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb, const std::chrono::milliseconds auto_flush_millis): _formatter(formatter), _sinks(sinks), _q(queue_size), _overflow_policy(overflow_policy), _worker_warmup_cb(worker_warmup_cb), + _auto_flush_millis(auto_flush_millis), _worker_thread(&async_log_helper::worker_loop, this) {} @@ -249,7 +254,12 @@ inline bool spdlog::details::async_log_helper::process_next_msg(clock::time_poin } else //empty queue { - sleep_or_yield(last_pop); + auto time_since_op = sleep_or_yield(last_pop); + if (_auto_flush_millis > std::chrono::milliseconds::zero() && time_since_op > _auto_flush_millis) + { + for (auto &s : _sinks) + s->flush(); + } } return true; } @@ -261,7 +271,7 @@ inline void spdlog::details::async_log_helper::set_formatter(formatter_ptr msg_f // 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) +inline std::chrono::nanoseconds spdlog::details::async_log_helper::sleep_or_yield(const clock::time_point& last_op_time) { using std::chrono::milliseconds; using namespace std::this_thread; @@ -270,18 +280,25 @@ inline void spdlog::details::async_log_helper::sleep_or_yield(const clock::time_ // spin upto 1 ms if (time_since_op <= milliseconds(1)) - return; + return time_since_op; // yield upto 10ms if (time_since_op <= milliseconds(10)) - return yield(); + { + yield(); + return time_since_op; + } // sleep for half of duration since last op if (time_since_op <= milliseconds(100)) - return sleep_for(time_since_op / 2); + { + sleep_for(time_since_op / 2); + return time_since_op; + } - return sleep_for(milliseconds(100)); + sleep_for(milliseconds(100)); + return time_since_op; } // throw if the worker thread threw an exception or not active diff --git a/include/spdlog/details/async_logger_impl.h b/include/spdlog/details/async_logger_impl.h index e113e1d2..e6c21ec3 100644 --- a/include/spdlog/details/async_logger_impl.h +++ b/include/spdlog/details/async_logger_impl.h @@ -39,9 +39,10 @@ inline spdlog::async_logger::async_logger(const std::string& logger_name, const It& end, size_t queue_size, const async_overflow_policy overflow_policy, - const std::function& worker_warmup_cb) : + const std::function& worker_warmup_cb, + const std::chrono::milliseconds auto_flush_millis) : logger(logger_name, begin, end), - _async_log_helper(new details::async_log_helper(_formatter, _sinks, queue_size, overflow_policy, worker_warmup_cb)) + _async_log_helper(new details::async_log_helper(_formatter, _sinks, queue_size, overflow_policy, worker_warmup_cb, auto_flush_millis)) { } @@ -49,15 +50,17 @@ inline spdlog::async_logger::async_logger(const std::string& logger_name, sinks_init_list sinks, size_t queue_size, const async_overflow_policy overflow_policy, - const std::function& worker_warmup_cb) : - async_logger(logger_name, sinks.begin(), sinks.end(), queue_size, overflow_policy, worker_warmup_cb) {} + const std::function& worker_warmup_cb, + const std::chrono::milliseconds auto_flush_millis) : + async_logger(logger_name, sinks.begin(), sinks.end(), queue_size, overflow_policy, worker_warmup_cb, auto_flush_millis) {} inline spdlog::async_logger::async_logger(const std::string& logger_name, sink_ptr single_sink, size_t queue_size, const async_overflow_policy overflow_policy, - const std::function& worker_warmup_cb) : - async_logger(logger_name, { single_sink }, queue_size, overflow_policy, worker_warmup_cb) {} + const std::function& worker_warmup_cb, + const std::chrono::milliseconds auto_flush_millis) : + async_logger(logger_name, { single_sink }, queue_size, overflow_policy, worker_warmup_cb, auto_flush_millis) {} inline void spdlog::async_logger::_set_formatter(spdlog::formatter_ptr msg_formatter) From 432e1109dd315c53934b260961a7a47d1c88fb57 Mon Sep 17 00:00:00 2001 From: Denis Ivaykin Date: Mon, 11 May 2015 00:17:49 +0200 Subject: [PATCH 2/3] flush interval part 2 --- include/spdlog/async_logger.h | 6 +-- include/spdlog/details/async_log_helper.h | 60 +++++++++++----------- include/spdlog/details/async_logger_impl.h | 12 ++--- include/spdlog/details/registry.h | 6 ++- include/spdlog/details/spdlog_impl.h | 4 +- include/spdlog/spdlog.h | 2 +- 6 files changed, 47 insertions(+), 43 deletions(-) diff --git a/include/spdlog/async_logger.h b/include/spdlog/async_logger.h index a802b03c..517ce92f 100644 --- a/include/spdlog/async_logger.h +++ b/include/spdlog/async_logger.h @@ -59,21 +59,21 @@ public: size_t queue_size, const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, const std::function& worker_warmup_cb = nullptr, - const std::chrono::milliseconds auto_flush_millis = std::chrono::milliseconds::zero()); + const std::chrono::milliseconds& flush_interval_ms = std::chrono::milliseconds::zero()); async_logger(const std::string& logger_name, sinks_init_list sinks, size_t queue_size, const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, const std::function& worker_warmup_cb = nullptr, - const std::chrono::milliseconds auto_flush_millis = std::chrono::milliseconds::zero()); + const std::chrono::milliseconds& flush_interval_ms = std::chrono::milliseconds::zero()); async_logger(const std::string& logger_name, sink_ptr single_sink, size_t queue_size, const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, const std::function& worker_warmup_cb = nullptr, - const std::chrono::milliseconds auto_flush_millis = std::chrono::milliseconds::zero()); + const std::chrono::milliseconds& flush_interval_ms = std::chrono::milliseconds::zero()); protected: diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index 9fe38cff..6395567b 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -120,7 +120,7 @@ public: size_t queue_size, const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, const std::function& worker_warmup_cb = nullptr, - const std::chrono::milliseconds auto_flush_millis = std::chrono::milliseconds::zero()); + const std::chrono::milliseconds& flush_interval_ms = std::chrono::milliseconds::zero()); void log(const details::log_msg& msg); @@ -147,7 +147,7 @@ private: const std::function _worker_warmup_cb; // auto periodic sink flush parameter - const std::chrono::milliseconds _auto_flush_millis; + const std::chrono::milliseconds _flush_interval_ms; // worker thread std::thread _worker_thread; @@ -160,10 +160,10 @@ private: // 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); + bool process_next_msg(log_clock::time_point& last_pop, log_clock::time_point& last_flush); // sleep,yield or return immediatly using the time passed since last message as a hint - static std::chrono::nanoseconds sleep_or_yield(const clock::time_point& last_op_time); + static void sleep_or_yield(const spdlog::log_clock::time_point& now, const log_clock::time_point& last_op_time); }; } @@ -172,13 +172,13 @@ 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, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb, const std::chrono::milliseconds auto_flush_millis): +inline spdlog::details::async_log_helper::async_log_helper(formatter_ptr formatter, const std::vector& sinks, size_t queue_size, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb, const std::chrono::milliseconds& flush_interval_ms): _formatter(formatter), _sinks(sinks), _q(queue_size), _overflow_policy(overflow_policy), _worker_warmup_cb(worker_warmup_cb), - _auto_flush_millis(auto_flush_millis), + _flush_interval_ms(flush_interval_ms), _worker_thread(&async_log_helper::worker_loop, this) {} @@ -204,10 +204,12 @@ inline void spdlog::details::async_log_helper::log(const details::log_msg& msg) async_msg new_msg(msg); if (!_q.enqueue(std::move(new_msg)) && _overflow_policy != async_overflow_policy::discard_log_msg) { - auto last_op_time = clock::now(); + auto last_op_time = log_clock::now(); + auto now = last_op_time; do { - sleep_or_yield(last_op_time); + now = log_clock::now(); + sleep_or_yield(now, last_op_time); } while (!_q.enqueue(std::move(new_msg))); } @@ -219,8 +221,9 @@ inline void spdlog::details::async_log_helper::worker_loop() try { if (_worker_warmup_cb) _worker_warmup_cb(); - clock::time_point last_pop = clock::now(); - while(process_next_msg(last_pop)); + auto last_pop = log_clock::now(); + auto last_flush = last_pop; + while(process_next_msg(last_pop, last_flush)); } catch (const std::exception& ex) { @@ -234,7 +237,7 @@ inline void spdlog::details::async_log_helper::worker_loop() // process next message in the queue // return true if this thread should still be active (no msg with level::off was received) -inline bool spdlog::details::async_log_helper::process_next_msg(clock::time_point& last_pop) +inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_point& last_pop, log_clock::time_point& last_flush) { async_msg incoming_async_msg; @@ -242,7 +245,7 @@ inline bool spdlog::details::async_log_helper::process_next_msg(clock::time_poin if (_q.dequeue(incoming_async_msg)) { - last_pop = clock::now(); + last_pop = log_clock::now(); if(incoming_async_msg.level == level::off) return false; @@ -254,12 +257,18 @@ inline bool spdlog::details::async_log_helper::process_next_msg(clock::time_poin } else //empty queue { - auto time_since_op = sleep_or_yield(last_pop); - if (_auto_flush_millis > std::chrono::milliseconds::zero() && time_since_op > _auto_flush_millis) + auto now = log_clock::now(); + if (_flush_interval_ms > std::chrono::milliseconds::zero()) { - for (auto &s : _sinks) - s->flush(); + auto time_since_flush = now - last_flush; + if (time_since_flush >= _flush_interval_ms) + { + last_flush = now; + for (auto &s : _sinks) + s->flush(); + } } + sleep_or_yield(now, last_pop); } return true; } @@ -271,34 +280,27 @@ inline void spdlog::details::async_log_helper::set_formatter(formatter_ptr msg_f // sleep,yield or return immediatly using the time passed since last message as a hint -inline std::chrono::nanoseconds spdlog::details::async_log_helper::sleep_or_yield(const clock::time_point& last_op_time) +inline void spdlog::details::async_log_helper::sleep_or_yield(const spdlog::log_clock::time_point& now, const spdlog::log_clock::time_point& last_op_time) { using std::chrono::milliseconds; using namespace std::this_thread; - auto time_since_op = clock::now() - last_op_time; + auto time_since_op = now - last_op_time; // spin upto 1 ms if (time_since_op <= milliseconds(1)) - return time_since_op; + return; // yield upto 10ms if (time_since_op <= milliseconds(10)) - { - yield(); - return time_since_op; - } + return yield(); // sleep for half of duration since last op if (time_since_op <= milliseconds(100)) - { - sleep_for(time_since_op / 2); - return time_since_op; - } + return sleep_for(time_since_op / 2); - sleep_for(milliseconds(100)); - return time_since_op; + return sleep_for(milliseconds(100)); } // throw if the worker thread threw an exception or not active diff --git a/include/spdlog/details/async_logger_impl.h b/include/spdlog/details/async_logger_impl.h index e6c21ec3..f60407e3 100644 --- a/include/spdlog/details/async_logger_impl.h +++ b/include/spdlog/details/async_logger_impl.h @@ -40,9 +40,9 @@ inline spdlog::async_logger::async_logger(const std::string& logger_name, size_t queue_size, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb, - const std::chrono::milliseconds auto_flush_millis) : + const std::chrono::milliseconds& flush_interval_ms) : logger(logger_name, begin, end), - _async_log_helper(new details::async_log_helper(_formatter, _sinks, queue_size, overflow_policy, worker_warmup_cb, auto_flush_millis)) + _async_log_helper(new details::async_log_helper(_formatter, _sinks, queue_size, overflow_policy, worker_warmup_cb, flush_interval_ms)) { } @@ -51,16 +51,16 @@ inline spdlog::async_logger::async_logger(const std::string& logger_name, size_t queue_size, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb, - const std::chrono::milliseconds auto_flush_millis) : - async_logger(logger_name, sinks.begin(), sinks.end(), queue_size, overflow_policy, worker_warmup_cb, auto_flush_millis) {} + const std::chrono::milliseconds& flush_interval_ms) : + async_logger(logger_name, sinks.begin(), sinks.end(), queue_size, overflow_policy, worker_warmup_cb, flush_interval_ms) {} inline spdlog::async_logger::async_logger(const std::string& logger_name, sink_ptr single_sink, size_t queue_size, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb, - const std::chrono::milliseconds auto_flush_millis) : - async_logger(logger_name, { single_sink }, queue_size, overflow_policy, worker_warmup_cb, auto_flush_millis) {} + const std::chrono::milliseconds& flush_interval_ms) : + async_logger(logger_name, { single_sink }, queue_size, overflow_policy, worker_warmup_cb, flush_interval_ms) {} inline void spdlog::async_logger::_set_formatter(spdlog::formatter_ptr msg_formatter) diff --git a/include/spdlog/details/registry.h b/include/spdlog/details/registry.h index 5f708743..6092fe5f 100644 --- a/include/spdlog/details/registry.h +++ b/include/spdlog/details/registry.h @@ -69,7 +69,7 @@ public: if (_async_mode) - new_logger = std::make_shared(logger_name, sinks_begin, sinks_end, _async_q_size, _overflow_policy, _worker_warmup_cb); + new_logger = std::make_shared(logger_name, sinks_begin, sinks_end, _async_q_size, _overflow_policy, _worker_warmup_cb, _flush_interval_ms); else new_logger = std::make_shared(logger_name, sinks_begin, sinks_end); @@ -127,13 +127,14 @@ public: _level = log_level; } - void set_async_mode(size_t q_size, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb) + void set_async_mode(size_t q_size, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb, const std::chrono::milliseconds& flush_interval_ms) { std::lock_guard lock(_mutex); _async_mode = true; _async_q_size = q_size; _overflow_policy = overflow_policy; _worker_warmup_cb = worker_warmup_cb; + _flush_interval_ms = flush_interval_ms; } void set_sync_mode() @@ -167,6 +168,7 @@ private: size_t _async_q_size = 0; async_overflow_policy _overflow_policy = async_overflow_policy::block_retry; std::function _worker_warmup_cb = nullptr; + std::chrono::milliseconds _flush_interval_ms; }; } } diff --git a/include/spdlog/details/spdlog_impl.h b/include/spdlog/details/spdlog_impl.h index 5e1bc73a..cfd6f826 100644 --- a/include/spdlog/details/spdlog_impl.h +++ b/include/spdlog/details/spdlog_impl.h @@ -137,9 +137,9 @@ inline void spdlog::set_level(level::level_enum log_level) } -inline void spdlog::set_async_mode(size_t queue_size, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb) +inline void spdlog::set_async_mode(size_t queue_size, const async_overflow_policy overflow_policy, const std::function& worker_warmup_cb, const std::chrono::milliseconds& flush_interval_ms) { - details::registry::instance().set_async_mode(queue_size, overflow_policy, worker_warmup_cb); + details::registry::instance().set_async_mode(queue_size, overflow_policy, worker_warmup_cb, flush_interval_ms); } inline void spdlog::set_sync_mode() diff --git a/include/spdlog/spdlog.h b/include/spdlog/spdlog.h index 8601555f..5cec5623 100644 --- a/include/spdlog/spdlog.h +++ b/include/spdlog/spdlog.h @@ -68,7 +68,7 @@ void set_level(level::level_enum log_level); // worker_warmup_cb (optional): // callback function that will be called in worker thread upon start (can be used to init stuff like thread affinity) // -void set_async_mode(size_t queue_size, const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, const std::function& worker_warmup_cb = nullptr); +void set_async_mode(size_t queue_size, const async_overflow_policy overflow_policy = async_overflow_policy::block_retry, const std::function& worker_warmup_cb = nullptr, const std::chrono::milliseconds& flush_interval_ms = std::chrono::milliseconds::zero()); // Turn off async mode void set_sync_mode(); From a3dcb2b79e36d9c5d4e9a8718a1fe2cdc1f5af1c Mon Sep 17 00:00:00 2001 From: Denis Ivaykin Date: Mon, 11 May 2015 00:21:55 +0200 Subject: [PATCH 3/3] details::os::now() --- include/spdlog/details/async_log_helper.h | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index 6395567b..9f7d2517 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -43,6 +43,7 @@ #include "./mpmc_bounded_q.h" #include "./log_msg.h" #include "./format.h" +#include "os.h" namespace spdlog @@ -204,11 +205,11 @@ inline void spdlog::details::async_log_helper::log(const details::log_msg& msg) async_msg new_msg(msg); if (!_q.enqueue(std::move(new_msg)) && _overflow_policy != async_overflow_policy::discard_log_msg) { - auto last_op_time = log_clock::now(); + auto last_op_time = details::os::now(); auto now = last_op_time; do { - now = log_clock::now(); + now = details::os::now(); sleep_or_yield(now, last_op_time); } while (!_q.enqueue(std::move(new_msg))); @@ -221,7 +222,7 @@ inline void spdlog::details::async_log_helper::worker_loop() try { if (_worker_warmup_cb) _worker_warmup_cb(); - auto last_pop = log_clock::now(); + auto last_pop = details::os::now(); auto last_flush = last_pop; while(process_next_msg(last_pop, last_flush)); } @@ -245,7 +246,7 @@ inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_ if (_q.dequeue(incoming_async_msg)) { - last_pop = log_clock::now(); + last_pop = details::os::now(); if(incoming_async_msg.level == level::off) return false; @@ -257,7 +258,7 @@ inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_ } else //empty queue { - auto now = log_clock::now(); + auto now = details::os::now(); if (_flush_interval_ms > std::chrono::milliseconds::zero()) { auto time_since_flush = now - last_flush;