From 243dc61e5888baa708e91e973662df5a6d4ae840 Mon Sep 17 00:00:00 2001 From: gabi Date: Tue, 2 Dec 2014 16:41:12 +0200 Subject: [PATCH 1/8] async using lockfree queue and bug fixes regarding usage of cppformat --- include/spdlog/async_logger.h | 6 +- .../async_log_helper.h} | 139 +++++++++++------- include/spdlog/details/async_logger_impl.h | 25 ++-- include/spdlog/details/file_helper.h | 2 +- include/spdlog/details/format.cc | 1 - include/spdlog/details/format.h | 4 +- include/spdlog/details/log_msg.h | 8 +- include/spdlog/details/mpcs_q.h | 78 +++++++--- .../spdlog/details/pattern_formatter_impl.h | 8 +- 9 files changed, 171 insertions(+), 100 deletions(-) rename include/spdlog/{sinks/async_sink.h => details/async_log_helper.h} (56%) diff --git a/include/spdlog/async_logger.h b/include/spdlog/async_logger.h index d2302c23..943a868a 100644 --- a/include/spdlog/async_logger.h +++ b/include/spdlog/async_logger.h @@ -37,9 +37,9 @@ namespace spdlog { -namespace sinks +namespace details { -class async_sink; +class async_log_helper; } class async_logger :public logger @@ -59,7 +59,7 @@ protected: private: log_clock::duration _shutdown_duration; - std::unique_ptr _as; + std::unique_ptr _async_log_helper; }; } diff --git a/include/spdlog/sinks/async_sink.h b/include/spdlog/details/async_log_helper.h similarity index 56% rename from include/spdlog/sinks/async_sink.h rename to include/spdlog/details/async_log_helper.h index 153d50b7..d9e19dce 100644 --- a/include/spdlog/sinks/async_sink.h +++ b/include/spdlog/details/async_log_helper.h @@ -22,7 +22,7 @@ /* SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ /*************************************************************************/ -// async sink: +// async log helper : // Process logs asynchronously using a back thread. // // If the internal queue of log messages reaches its max size, @@ -30,36 +30,69 @@ // // If the back thread throws during logging, a spdlog::spdlog_ex exception // will be thrown in client's thread when tries to log the next message + #pragma once #include #include #include -#include "./base_sink.h" +#include "../sinks/sink.h" #include "../logger.h" -#include "../details/blocking_queue.h" -#include "../details/null_mutex.h" +#include "../details/mpcs_q.h" #include "../details/log_msg.h" #include "../details/format.h" namespace spdlog { -namespace sinks +namespace details { - -class async_sink : public base_sink < details::null_mutex > //single worker thread so null_mutex +class async_log_helper { + struct async_msg + { + std::string logger_name; + level::level_enum level; + log_clock::time_point time; + std::tm tm_time; + std::string raw_msg_str; + + async_msg() = default; + + async_msg(const details::log_msg& m) : + logger_name(m.logger_name), + level(m.level), + time(m.time), + tm_time(m.tm_time), + raw_msg_str(m.raw.data(), m.raw.size()) + { + + } + + + log_msg to_log_msg() + { + log_msg msg; + msg.logger_name = logger_name; + msg.level = level; + msg.time = time; + msg.tm_time = tm_time; + msg.raw << raw_msg_str; + return msg; + } + }; + public: - using q_type = details::blocking_queue < details::log_msg > ; + using q_type = details::mpsc_q < std::unique_ptr >; - explicit async_sink(const q_type::size_type max_queue_size); + explicit async_log_helper(size_t max_queue_size); + void log(const details::log_msg& msg); //Stop logging and join the back thread - ~async_sink(); + ~async_log_helper(); void add_sink(sink_ptr sink); void remove_sink(sink_ptr sink_ptr); void set_formatter(formatter_ptr); @@ -68,25 +101,28 @@ public: -protected: - void _sink_it(const details::log_msg& msg) override; - void _thread_loop(); + private: - std::vector> _sinks; + std::vector> _sinks; std::atomic _active; q_type _q; - std::thread _back_thread; + std::thread _worker_thread; std::mutex _mutex; - //Last exception thrown from the back thread - std::shared_ptr _last_backthread_ex; + // last exception thrown from the worker thread + std::shared_ptr _last_workerthread_ex; + + // worker thread formatter formatter_ptr _formatter; - //will throw last back thread exception or if backthread no active + // will throw last back thread exception or if worker hread no active void _push_sentry(); - //Clear all remaining messages(if any), stop the _back_thread and join it + // worker thread loop + void _thread_loop(); + + // clear all remaining messages(if any), stop the _worker_thread and join it void _join(); }; @@ -96,85 +132,87 @@ private: /////////////////////////////////////////////////////////////////////////////// // async_sink class implementation /////////////////////////////////////////////////////////////////////////////// -inline spdlog::sinks::async_sink::async_sink(const q_type::size_type max_queue_size) +inline spdlog::details::async_log_helper::async_log_helper(size_t max_queue_size) :_sinks(), _active(true), _q(max_queue_size), - _back_thread(&async_sink::_thread_loop, this) + _worker_thread(&async_log_helper::_thread_loop, this) {} -inline spdlog::sinks::async_sink::~async_sink() +inline spdlog::details::async_log_helper::~async_log_helper() { _join(); } -inline void spdlog::sinks::async_sink::_sink_it(const details::log_msg& msg) +inline void spdlog::details::async_log_helper::log(const details::log_msg& msg) { _push_sentry(); - _q.push(std::move(msg)); + _q.push(std::unique_ptr(new async_msg(msg))); } -inline void spdlog::sinks::async_sink::_thread_loop() +inline void spdlog::details::async_log_helper::_thread_loop() { - std::chrono::seconds pop_timeout { 1 }; while (_active) { - q_type::item_type msg; - if (_q.pop(msg, pop_timeout)) - { - if (!_active) - return; + q_type::item_type async_msg; + if (_q.pop(async_msg)) + { try { - _formatter->format(msg); + details::log_msg log_msg = async_msg->to_log_msg(); + + _formatter->format(log_msg); for (auto &s : _sinks) - s->log(msg); + s->log(log_msg); } catch (const std::exception& ex) { - _last_backthread_ex = std::make_shared(ex.what()); + _last_workerthread_ex = std::make_shared(ex.what()); } catch (...) { - _last_backthread_ex = std::make_shared("Unknown exception"); + _last_workerthread_ex = std::make_shared("Unknown exception"); } - + } + else //Sleep and retry if empty + { + std::this_thread::sleep_for(std::chrono::microseconds(100)); } } } -inline void spdlog::sinks::async_sink::add_sink(spdlog::sink_ptr s) +inline void spdlog::details::async_log_helper::add_sink(spdlog::sink_ptr s) { std::lock_guard guard(_mutex); _sinks.push_back(s); } -inline void spdlog::sinks::async_sink::remove_sink(spdlog::sink_ptr s) +inline void spdlog::details::async_log_helper::remove_sink(spdlog::sink_ptr s) { std::lock_guard guard(_mutex); _sinks.erase(std::remove(_sinks.begin(), _sinks.end(), s), _sinks.end()); } -inline void spdlog::sinks::async_sink::set_formatter(formatter_ptr msg_formatter) +inline void spdlog::details::async_log_helper::set_formatter(formatter_ptr msg_formatter) { _formatter = msg_formatter; } -inline void spdlog::sinks::async_sink::shutdown(const log_clock::duration& timeout) +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.size() > 0 && log_clock::now() < until) + while (_q.approx_size() > 0 && log_clock::now() < until) { std::this_thread::sleep_for(std::chrono::milliseconds(5)); } @@ -182,13 +220,13 @@ inline void spdlog::sinks::async_sink::shutdown(const log_clock::duration& timeo _join(); } -#include -inline void spdlog::sinks::async_sink::_push_sentry() + +inline void spdlog::details::async_log_helper::_push_sentry() { - if (_last_backthread_ex) + if (_last_workerthread_ex) { - auto ex = std::move(_last_backthread_ex); - _last_backthread_ex.reset(); + auto ex = std::move(_last_workerthread_ex); + _last_workerthread_ex.reset(); throw *ex; } if (!_active) @@ -196,17 +234,18 @@ inline void spdlog::sinks::async_sink::_push_sentry() } -inline void spdlog::sinks::async_sink::_join() +inline void spdlog::details::async_log_helper::_join() { _active = false; - if (_back_thread.joinable()) + if (_worker_thread.joinable()) { try { - _back_thread.join(); + _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 e84f897d..963135d3 100644 --- a/include/spdlog/details/async_logger_impl.h +++ b/include/spdlog/details/async_logger_impl.h @@ -25,8 +25,7 @@ #pragma once -#include -#include "../sinks/async_sink.h" +#include "./async_log_helper.h" // // Async Logger implementation @@ -38,11 +37,11 @@ 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) : logger(logger_name, begin, end), _shutdown_duration(shutdown_duration), - _as(std::unique_ptr(new sinks::async_sink(queue_size))) + _async_log_helper(new details::async_log_helper(queue_size)) { - _as->set_formatter(_formatter); + _async_log_helper->set_formatter(_formatter); for (auto &s : _sinks) - _as->add_sink(s); + _async_log_helper->add_sink(s); } 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) : @@ -52,21 +51,16 @@ inline spdlog::async_logger::async_logger(const std::string& logger_name, sink_p async_logger(logger_name, { single_sink }, queue_size, shutdown_duration) {} -inline void spdlog::async_logger::_log_msg(details::log_msg& msg) -{ - _as->log(msg); -} - inline void spdlog::async_logger::_set_formatter(spdlog::formatter_ptr msg_formatter) { _formatter = msg_formatter; - _as->set_formatter(_formatter); + _async_log_helper->set_formatter(_formatter); } inline void spdlog::async_logger::_set_pattern(const std::string& pattern) { _formatter = std::make_shared(pattern); - _as->set_formatter(_formatter); + _async_log_helper->set_formatter(_formatter); } @@ -74,5 +68,10 @@ inline void spdlog::async_logger::_set_pattern(const std::string& pattern) inline void spdlog::async_logger::_stop() { set_level(level::OFF); - _as->shutdown(_shutdown_duration); + _async_log_helper->shutdown(_shutdown_duration); +} + +inline void spdlog::async_logger::_log_msg(details::log_msg& msg) +{ + _async_log_helper->log(msg); } diff --git a/include/spdlog/details/file_helper.h b/include/spdlog/details/file_helper.h index 7932a45b..ac0ef948 100644 --- a/include/spdlog/details/file_helper.h +++ b/include/spdlog/details/file_helper.h @@ -102,7 +102,7 @@ public: size_t size = msg.formatted.size(); auto data = msg.formatted.data(); - if(std::fwrite(data, sizeof(char), size, _fd) != size) + if(std::fwrite(data, 1, size, _fd) != size) throw spdlog_ex("Failed writing to file " + _filename); if(_auto_flush) diff --git a/include/spdlog/details/format.cc b/include/spdlog/details/format.cc index 06b8c846..76ef84eb 100644 --- a/include/spdlog/details/format.cc +++ b/include/spdlog/details/format.cc @@ -31,7 +31,6 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. #undef _SCL_SECURE_NO_WARNINGS #define _SCL_SECURE_NO_WARNINGS -#include "format.h" #include diff --git a/include/spdlog/details/format.h b/include/spdlog/details/format.h index a9b51c21..c90e9212 100644 --- a/include/spdlog/details/format.h +++ b/include/spdlog/details/format.h @@ -1050,7 +1050,7 @@ public: { default: assert(false); - // Fall through. + // Fall through. case Arg::INT: return FMT_DISPATCH(visit_int(arg.int_value)); case Arg::UINT: @@ -2219,7 +2219,7 @@ void BasicWriter::write_double( // MSVC's printf doesn't support 'F'. type = 'f'; #endif - // Fall through. + // Fall through. case 'E': case 'G': case 'A': diff --git a/include/spdlog/details/log_msg.h b/include/spdlog/details/log_msg.h index 3764e6cf..00870bb2 100644 --- a/include/spdlog/details/log_msg.h +++ b/include/spdlog/details/log_msg.h @@ -48,9 +48,13 @@ struct log_msg level(other.level), time(other.time), tm_time(other.tm_time) + { - raw.write(other.raw.data(), other.raw.size()); - formatted.write(other.formatted.data(), other.formatted.size()); + if (other.raw.size()) + raw << fmt::BasicStringRef(other.raw.data(), other.raw.size()); + if (other.formatted.size()) + formatted << fmt::BasicStringRef(other.formatted.data(), other.formatted.size()); + } log_msg(log_msg&& other) : diff --git a/include/spdlog/details/mpcs_q.h b/include/spdlog/details/mpcs_q.h index 058d6ee4..d62d1775 100644 --- a/include/spdlog/details/mpcs_q.h +++ b/include/spdlog/details/mpcs_q.h @@ -1,7 +1,5 @@ -#pragma once -/*************************************************************************/ /* -Modified version of Intrusive MPSC node-based queue +A modified version of Intrusive MPSC node-based queue Original code from http://www.1024cores.net/home/lock-free-algorithms/queues/intrusive-mpsc-node-based-queue @@ -32,9 +30,10 @@ ADVISED OF THE POSSIBILITY OF SUCH DAMAGE. The views and conclusions contained in the software and documentation are those of the authors and should not be interpreted as representing official policies, either expressed or implied, of Dmitry Vyukov. +*/ /*************************************************************************/ -/* The code in its current form adds the license below: */ +/********* The code in its current form adds the license below: **********/ /*************************************************************************/ /* spdlog - an extremely fast and easy to use c++11 logging library. */ /* Copyright (c) 2014 Gabi Melman. */ @@ -59,6 +58,7 @@ should not be interpreted as representing official policies, either expressed or /* SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */ /*************************************************************************/ +#pragma once #include namespace spdlog @@ -70,35 +70,40 @@ class mpsc_q { public: - mpsc_q(size_t size) :_stub(T()), _head(&_stub), _tail(&_stub) + using item_type = T; + mpsc_q(size_t max_size) : + _max_size(max_size), + _size(0), + _stub(), + _head(&_stub), + _tail(&_stub) { - _stub.next = nullptr; } ~mpsc_q() { - reset(); + clear(); } - void reset() + template + bool push(TT&& value) { - T dummy_val; - while (pop(dummy_val)); - } - - bool push(const T& value) - { - mpscq_node_t* new_node = new mpscq_node_t(value); + if (_size >= _max_size) + return false; + mpscq_node_t* new_node = new mpscq_node_t(std::forward(value)); push_node(new_node); + ++_size; return true; } + // Try to pop or return false immediatly is queue is empty bool pop(T& value) { mpscq_node_t* node = pop_node(); if (node != nullptr) { - value = node->value; + --_size; + value = std::move(node->value); delete(node); return true; } @@ -108,23 +113,48 @@ public: } } + // Empty the queue by popping all its elements + void clear() + { + + while (mpscq_node_t* node = pop_node()) + { + --_size; + delete(node); + + } + + } + + // Return approx size + size_t approx_size() const + { + return _size.load(); + } + private: struct mpscq_node_t { std::atomic next; T value; - explicit mpscq_node_t(const T& value) :next(nullptr), value(value) - { - } + mpscq_node_t() :next(nullptr) {} + explicit mpscq_node_t(const T& value): + next(nullptr), + value(value) {} + + explicit mpscq_node_t(T&& value) : + next(nullptr), + value(std::move(value)) {} }; + size_t _max_size; + std::atomic _size; mpscq_node_t _stub; std::atomic _head; mpscq_node_t* _tail; - - + // Lockfree push void push_node(mpscq_node_t* n) { n->next = nullptr; @@ -132,6 +162,8 @@ private: prev->next = n; } + // Clever lockfree pop algorithm by Dmitry Vyukov using single xchng instruction.. + // Return pointer to the poppdc node or nullptr if no items left in the queue mpscq_node_t* pop_node() { mpscq_node_t* tail = _tail; @@ -151,7 +183,7 @@ private: } mpscq_node_t* head = _head; if (tail != head) - return 0; + return nullptr; push_node(&_stub); next = tail->next; @@ -163,8 +195,6 @@ private: return nullptr; } - - }; } } \ No newline at end of file diff --git a/include/spdlog/details/pattern_formatter_impl.h b/include/spdlog/details/pattern_formatter_impl.h index 6a0c4ee9..8ee826a1 100644 --- a/include/spdlog/details/pattern_formatter_impl.h +++ b/include/spdlog/details/pattern_formatter_impl.h @@ -345,7 +345,7 @@ class v_formatter :public flag_formatter { void format(details::log_msg& msg) override { - msg.formatted.write(msg.raw.data(), msg.raw.size()); + msg.formatted << fmt::BasicStringRef(msg.raw.data(), msg.raw.size()); } }; @@ -413,7 +413,7 @@ class full_formatter :public flag_formatter << fmt::pad(static_cast(millis), 3, '0') << "] "; msg.formatted << '[' << msg.logger_name << "] [" << level::to_str(msg.level) << "] "; - msg.formatted.write(msg.raw.data(), msg.raw.size()); + msg.formatted << fmt::BasicStringRef(msg.raw.data(), msg.raw.size()); } }; @@ -460,7 +460,7 @@ inline void spdlog::pattern_formatter::handle_flag(char flag) { switch (flag) { - // logger name + // logger name case 'n': _formatters.push_back(std::unique_ptr(new details::name_formatter())); break; @@ -581,7 +581,7 @@ inline void spdlog::pattern_formatter::format(details::log_msg& msg) f->format(msg); } //write eol - msg.formatted.write(details::os::eol(), details::os::eol_size()); + msg.formatted << details::os::eol(); } catch(const fmt::FormatError& e) { From b943265b946fed349344a6e600e63450328be454 Mon Sep 17 00:00:00 2001 From: gabi Date: Tue, 2 Dec 2014 19:14:21 +0200 Subject: [PATCH 2/8] Better handling of empty queue --- include/spdlog/details/async_log_helper.h | 34 +++++++++++++++++++++-- 1 file changed, 31 insertions(+), 3 deletions(-) diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index d9e19dce..7ea0ac04 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -87,6 +87,8 @@ class async_log_helper public: using q_type = details::mpsc_q < std::unique_ptr >; + using clock = std::chrono::monotonic_clock; + explicit async_log_helper(size_t max_queue_size); void log(const details::log_msg& msg); @@ -116,12 +118,17 @@ private: // worker thread formatter formatter_ptr _formatter; + // will throw last back thread exception or if worker hread no active void _push_sentry(); // worker thread loop void _thread_loop(); + // guess how much to sleep if queue is empty + static clock::duration spdlog::details::async_log_helper::_calc_pop_sleep(const clock::time_point& last_pop); + + // clear all remaining messages(if any), stop the _worker_thread and join it void _join(); @@ -154,15 +161,18 @@ inline void spdlog::details::async_log_helper::log(const details::log_msg& msg) inline void spdlog::details::async_log_helper::_thread_loop() { + clock::time_point last_pop = clock::now(); while (_active) { q_type::item_type async_msg; if (_q.pop(async_msg)) { + + last_pop = clock::now(); + try { - details::log_msg log_msg = async_msg->to_log_msg(); _formatter->format(log_msg); @@ -179,13 +189,31 @@ inline void spdlog::details::async_log_helper::_thread_loop() _last_workerthread_ex = std::make_shared("Unknown exception"); } } - else //Sleep and retry if empty + //Sleep for a while if empty. + else { - std::this_thread::sleep_for(std::chrono::microseconds(100)); + std::this_thread::sleep_for(_calc_pop_sleep(last_pop)); } } } +//Try to guess sleep duration according to the time passed since last message +inline spdlog::details::async_log_helper::clock::duration spdlog::details::async_log_helper::_calc_pop_sleep(const clock::time_point& last_pop) +{ + using std::chrono::milliseconds; + using std::chrono::microseconds; + auto time_since_pop = clock::now() - last_pop; + + + if (time_since_pop > milliseconds(1000)) + return milliseconds(500); + if (time_since_pop > microseconds(0)) + return(time_since_pop / 2); + return microseconds(0); + + +} + inline void spdlog::details::async_log_helper::add_sink(spdlog::sink_ptr s) { std::lock_guard guard(_mutex); From 01344b6c8b0e9df182194b866281debde80f9506 Mon Sep 17 00:00:00 2001 From: gabi Date: Wed, 3 Dec 2014 00:27:25 +0200 Subject: [PATCH 3/8] mpcs_q removed default copy ctor and assignment --- include/spdlog/details/mpcs_q.h | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/include/spdlog/details/mpcs_q.h b/include/spdlog/details/mpcs_q.h index d62d1775..77511db3 100644 --- a/include/spdlog/details/mpcs_q.h +++ b/include/spdlog/details/mpcs_q.h @@ -71,7 +71,7 @@ class mpsc_q public: using item_type = T; - mpsc_q(size_t max_size) : + explicit mpsc_q(size_t max_size) : _max_size(max_size), _size(0), _stub(), @@ -80,6 +80,9 @@ public: { } + mpsc_q(const mpsc_q&) = delete; + mpsc_q& operator=(const mpsc_q&) = delete; + ~mpsc_q() { clear(); @@ -116,12 +119,10 @@ public: // Empty the queue by popping all its elements void clear() { - while (mpscq_node_t* node = pop_node()) { --_size; delete(node); - } } @@ -139,6 +140,9 @@ private: T value; mpscq_node_t() :next(nullptr) {} + mpscq_node_t(const mpscq_node_t&) = delete; + mpscq_node_t& operator=(const mpscq_node_t&) = delete; + explicit mpscq_node_t(const T& value): next(nullptr), value(value) {} From 80d09d8309330b5754683839ec4d3859145cd89a Mon Sep 17 00:00:00 2001 From: gabi Date: Wed, 3 Dec 2014 00:28:33 +0200 Subject: [PATCH 4/8] async_helper sleep_or_yield or full/empty queue --- include/spdlog/details/async_log_helper.h | 54 ++++++++++++++--------- 1 file changed, 34 insertions(+), 20 deletions(-) diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index 7ea0ac04..f84b693f 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -125,8 +125,8 @@ private: // worker thread loop void _thread_loop(); - // guess how much to sleep if queue is empty - static clock::duration spdlog::details::async_log_helper::_calc_pop_sleep(const 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); // clear all remaining messages(if any), stop the _worker_thread and join it @@ -151,11 +151,21 @@ inline spdlog::details::async_log_helper::~async_log_helper() _join(); } + +//Try to push and block until succeeded inline void spdlog::details::async_log_helper::log(const details::log_msg& msg) { _push_sentry(); - _q.push(std::unique_ptr(new async_msg(msg))); + //Only if queue is full, enter wait loop + if (!_q.push(std::unique_ptr < async_msg >(new async_msg(msg)))) + { + auto last_op_time = clock::now(); + while (!_q.push(std::unique_ptr < async_msg >(new async_msg(msg)))) + { + _sleep_or_yield(last_op_time); + } + } } inline void spdlog::details::async_log_helper::_thread_loop() @@ -192,27 +202,11 @@ inline void spdlog::details::async_log_helper::_thread_loop() //Sleep for a while if empty. else { - std::this_thread::sleep_for(_calc_pop_sleep(last_pop)); + _sleep_or_yield(last_pop); } } } -//Try to guess sleep duration according to the time passed since last message -inline spdlog::details::async_log_helper::clock::duration spdlog::details::async_log_helper::_calc_pop_sleep(const clock::time_point& last_pop) -{ - using std::chrono::milliseconds; - using std::chrono::microseconds; - auto time_since_pop = clock::now() - last_pop; - - - if (time_since_pop > milliseconds(1000)) - return milliseconds(500); - if (time_since_pop > microseconds(0)) - return(time_since_pop / 2); - return microseconds(0); - - -} inline void spdlog::details::async_log_helper::add_sink(spdlog::sink_ptr s) { @@ -249,6 +243,23 @@ inline void spdlog::details::async_log_helper::shutdown(const log_clock::duratio } +// Sleep or yield 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; + + 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(); +} + inline void spdlog::details::async_log_helper::_push_sentry() { if (_last_workerthread_ex) @@ -278,3 +289,6 @@ inline void spdlog::details::async_log_helper::_join() } + + + From 3916674bc5d0bc2ed58f3a699014b37f560a7010 Mon Sep 17 00:00:00 2001 From: gabi Date: Wed, 3 Dec 2014 00:28:33 +0200 Subject: [PATCH 5/8] async_helper sleep_or_yield or full/empty queue --- include/spdlog/details/async_log_helper.h | 57 ++++++++++++++--------- 1 file changed, 36 insertions(+), 21 deletions(-) diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index 7ea0ac04..92c2f18d 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -125,8 +125,8 @@ private: // worker thread loop void _thread_loop(); - // guess how much to sleep if queue is empty - static clock::duration spdlog::details::async_log_helper::_calc_pop_sleep(const 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); // clear all remaining messages(if any), stop the _worker_thread and join it @@ -151,11 +151,22 @@ inline spdlog::details::async_log_helper::~async_log_helper() _join(); } + +//Try to push and block until succeeded inline void spdlog::details::async_log_helper::log(const details::log_msg& msg) { _push_sentry(); - _q.push(std::unique_ptr(new async_msg(msg))); + //Only if queue is full, enter wait loop + if (!_q.push(std::unique_ptr < async_msg >(new async_msg(msg)))) + { + auto last_op_time = clock::now(); + do + { + _sleep_or_yield(last_op_time); + } + while (!_q.push(std::unique_ptr < async_msg >(new async_msg(msg)))); + } } inline void spdlog::details::async_log_helper::_thread_loop() @@ -189,30 +200,14 @@ inline void spdlog::details::async_log_helper::_thread_loop() _last_workerthread_ex = std::make_shared("Unknown exception"); } } - //Sleep for a while if empty. + // sleep or yield if queue is empty. else { - std::this_thread::sleep_for(_calc_pop_sleep(last_pop)); + _sleep_or_yield(last_pop); } } } -//Try to guess sleep duration according to the time passed since last message -inline spdlog::details::async_log_helper::clock::duration spdlog::details::async_log_helper::_calc_pop_sleep(const clock::time_point& last_pop) -{ - using std::chrono::milliseconds; - using std::chrono::microseconds; - auto time_since_pop = clock::now() - last_pop; - - - if (time_since_pop > milliseconds(1000)) - return milliseconds(500); - if (time_since_pop > microseconds(0)) - return(time_since_pop / 2); - return microseconds(0); - - -} inline void spdlog::details::async_log_helper::add_sink(spdlog::sink_ptr s) { @@ -249,6 +244,23 @@ inline void spdlog::details::async_log_helper::shutdown(const log_clock::duratio } +// Sleep or yield 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; + + 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(); +} + inline void spdlog::details::async_log_helper::_push_sentry() { if (_last_workerthread_ex) @@ -278,3 +290,6 @@ inline void spdlog::details::async_log_helper::_join() } + + + From 33b976a4c9d2a7913fe78f635db25966972acfc3 Mon Sep 17 00:00:00 2001 From: gabi Date: Wed, 3 Dec 2014 00:40:13 +0200 Subject: [PATCH 6/8] fix --- include/spdlog/details/async_log_helper.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index 92c2f18d..ddd16ecf 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -163,7 +163,7 @@ inline void spdlog::details::async_log_helper::log(const details::log_msg& msg) auto last_op_time = clock::now(); do { - _sleep_or_yield(last_op_time); + _sleep_or_yield(last_op_time ; } while (!_q.push(std::unique_ptr < async_msg >(new async_msg(msg)))); } From 9e882c4dd228a481302a68414ac90e9a75a300f9 Mon Sep 17 00:00:00 2001 From: gabi Date: Wed, 3 Dec 2014 00:50:12 +0200 Subject: [PATCH 7/8] fix --- include/spdlog/details/async_log_helper.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index ddd16ecf..92c2f18d 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -163,7 +163,7 @@ inline void spdlog::details::async_log_helper::log(const details::log_msg& msg) auto last_op_time = clock::now(); do { - _sleep_or_yield(last_op_time ; + _sleep_or_yield(last_op_time); } while (!_q.push(std::unique_ptr < async_msg >(new async_msg(msg)))); } From 98e4eb98f9fd88f206070cea9076239c2cf882d4 Mon Sep 17 00:00:00 2001 From: gabi Date: Wed, 3 Dec 2014 00:50:49 +0200 Subject: [PATCH 8/8] small optimization in default formatting (unsigned ints) --- .../spdlog/details/pattern_formatter_impl.h | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/include/spdlog/details/pattern_formatter_impl.h b/include/spdlog/details/pattern_formatter_impl.h index 8ee826a1..bc2cc6f0 100644 --- a/include/spdlog/details/pattern_formatter_impl.h +++ b/include/spdlog/details/pattern_formatter_impl.h @@ -345,7 +345,7 @@ class v_formatter :public flag_formatter { void format(details::log_msg& msg) override { - msg.formatted << fmt::BasicStringRef(msg.raw.data(), msg.raw.size()); + msg.formatted << fmt::StringRef(msg.raw.data(), msg.raw.size()); } }; @@ -404,16 +404,16 @@ class full_formatter :public flag_formatter msg.raw.str());*/ // Faster (albeit uglier) way to format the line (5.6 million lines/sec under 10 threads) - msg.formatted << '[' << msg.tm_time.tm_year + 1900 << '-' - << fmt::pad(msg.tm_time.tm_mon + 1, 2, '0') << '-' - << fmt::pad(msg.tm_time.tm_mday, 2, '0') << ' ' - << fmt::pad(msg.tm_time.tm_hour, 2, '0') << ':' - << fmt::pad(msg.tm_time.tm_min, 2, '0') << ':' - << fmt::pad(msg.tm_time.tm_sec, 2, '0') << '.' - << fmt::pad(static_cast(millis), 3, '0') << "] "; + msg.formatted << '[' << static_cast(msg.tm_time.tm_year + 1900) << '-' + << fmt::pad(static_cast(msg.tm_time.tm_mon + 1), 2, '0') << '-' + << fmt::pad(static_cast(msg.tm_time.tm_mday), 2, '0') << ' ' + << fmt::pad(static_cast(msg.tm_time.tm_hour), 2, '0') << ':' + << fmt::pad(static_cast(msg.tm_time.tm_min), 2, '0') << ':' + << fmt::pad(static_cast(msg.tm_time.tm_sec), 2, '0') << '.' + << fmt::pad(static_cast(millis), 3, '0') << "] "; msg.formatted << '[' << msg.logger_name << "] [" << level::to_str(msg.level) << "] "; - msg.formatted << fmt::BasicStringRef(msg.raw.data(), msg.raw.size()); + msg.formatted << fmt::StringRef(msg.raw.data(), msg.raw.size()); } };