From 0aeaf9e28e080c4cc1754571370b9e0654c7137f Mon Sep 17 00:00:00 2001 From: Alexander Zilberkant Date: Thu, 11 May 2017 23:52:42 +0300 Subject: [PATCH 1/4] add an option to warn about discarded messages when using async_logger with async_overflow_policy::discard_log_msg each discarded message will be counted and warning will be printed by the worker thread this new feature is disabled by default - as it may have a performance hit when discarding messages --- include/spdlog/details/async_log_helper.h | 42 ++++++++++++++++++----- include/spdlog/tweakme.h | 7 ++++ 2 files changed, 41 insertions(+), 8 deletions(-) diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index 1e454550..2b5e382e 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -27,6 +27,7 @@ #include #include #include +#include namespace spdlog { @@ -185,6 +186,9 @@ private: // wait until the queue is empty void wait_empty_q(); + // counter for messages discarded due to queue overflow + std::atomic _discarded_msg_count; + }; } } @@ -211,7 +215,8 @@ inline spdlog::details::async_log_helper::async_log_helper( _worker_warmup_cb(worker_warmup_cb), _flush_interval_ms(flush_interval_ms), _worker_teardown_cb(worker_teardown_cb), - _worker_thread(&async_log_helper::worker_loop, this) + _worker_thread(&async_log_helper::worker_loop, this), + _discarded_msg_count(0) {} // Send to the worker thread termination message(level=off) @@ -237,16 +242,24 @@ inline void spdlog::details::async_log_helper::log(const details::log_msg& msg) inline void spdlog::details::async_log_helper::push_msg(details::async_log_helper::async_msg&& new_msg) { - if (!_q.enqueue(std::move(new_msg)) && _overflow_policy != async_overflow_policy::discard_log_msg) + if (!_q.enqueue(std::move(new_msg))) { - auto last_op_time = details::os::now(); - auto now = last_op_time; - do + if (_overflow_policy != async_overflow_policy::discard_log_msg) { - now = details::os::now(); - sleep_or_yield(now, last_op_time); + auto last_op_time = details::os::now(); + auto now = last_op_time; + do + { + now = details::os::now(); + sleep_or_yield(now, last_op_time); + } while (!_q.enqueue(std::move(new_msg))); + } + else + { +#if defined(SPDLOG_ASYNC_COUNT_DISCARDED_MSG) + _discarded_msg_count++; +#endif } - while (!_q.enqueue(std::move(new_msg))); } } @@ -305,6 +318,19 @@ inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_ break; default: +#if defined(SPDLOG_ASYNC_COUNT_DISCARDED_MSG) + unsigned int num_of_discarded_messages = _discarded_msg_count.exchange(0); + if (num_of_discarded_messages) + { + log_msg discarded_warning_msg(&incoming_async_msg.logger_name, level::warn); + discarded_warning_msg.raw << "Dropped " << num_of_discarded_messages << " messages"; + for (auto &s : _sinks) + { + s->log(discarded_warning_msg); + } + } +#endif + log_msg incoming_log_msg; incoming_async_msg.fill_log_msg(incoming_log_msg); _formatter->format(incoming_log_msg); diff --git a/include/spdlog/tweakme.h b/include/spdlog/tweakme.h index bde27967..0f3c2763 100644 --- a/include/spdlog/tweakme.h +++ b/include/spdlog/tweakme.h @@ -114,3 +114,10 @@ // // #define SPDLOG_FINAL final /////////////////////////////////////////////////////////////////////////////// + +/////////////////////////////////////////////////////////////////////////////// +// Uncomment count in print warning message about number of dropped messages. +// Only relevant for async_logger with async_overflow_policy::discard_log_msg +// +#define SPDLOG_ASYNC_COUNT_DISCARDED_MSG +/////////////////////////////////////////////////////////////////////////////// From 42258a1059645e2c264a0caa8aa737d2e13d0c80 Mon Sep 17 00:00:00 2001 From: Alexander Zilberkant Date: Sat, 13 May 2017 00:53:57 +0300 Subject: [PATCH 2/4] move discarded message handling to a dedicated function fix - formatter new discarded message --- include/spdlog/details/async_log_helper.h | 29 ++++++++++++++--------- 1 file changed, 18 insertions(+), 11 deletions(-) diff --git a/include/spdlog/details/async_log_helper.h b/include/spdlog/details/async_log_helper.h index 2b5e382e..c5a147ec 100644 --- a/include/spdlog/details/async_log_helper.h +++ b/include/spdlog/details/async_log_helper.h @@ -189,6 +189,9 @@ private: // counter for messages discarded due to queue overflow std::atomic _discarded_msg_count; + // handle discarded messages + void handle_discarded_msg(const std::string& logger_name); + }; } } @@ -319,16 +322,7 @@ inline bool spdlog::details::async_log_helper::process_next_msg(log_clock::time_ default: #if defined(SPDLOG_ASYNC_COUNT_DISCARDED_MSG) - unsigned int num_of_discarded_messages = _discarded_msg_count.exchange(0); - if (num_of_discarded_messages) - { - log_msg discarded_warning_msg(&incoming_async_msg.logger_name, level::warn); - discarded_warning_msg.raw << "Dropped " << num_of_discarded_messages << " messages"; - for (auto &s : _sinks) - { - s->log(discarded_warning_msg); - } - } + handle_discarded_msg(incoming_async_msg.logger_name); #endif log_msg incoming_log_msg; @@ -415,5 +409,18 @@ inline void spdlog::details::async_log_helper::set_error_handler(spdlog::log_err _err_handler = err_handler; } - +inline void spdlog::details::async_log_helper::handle_discarded_msg(const std::string& logger_name) +{ + unsigned int num_of_discarded_messages = _discarded_msg_count.exchange(0); + if (num_of_discarded_messages) + { + log_msg discarded_warning_msg(&logger_name, level::warn); + discarded_warning_msg.raw << "Discarded " << num_of_discarded_messages << " messages - logger queue overflow"; + _formatter->format(discarded_warning_msg); + for (auto &s : _sinks) + { + s->log(discarded_warning_msg); + } + } +} From 0f25b25b20908a89495809b062cef71920d887e5 Mon Sep 17 00:00:00 2001 From: Alexander Zilberkant Date: Sat, 13 May 2017 01:01:28 +0300 Subject: [PATCH 3/4] add async_logger tests cover discarded messages use-case --- tests/CMakeLists.txt | 2 +- tests/async_logger.cpp | 38 ++++++++++++++++++++++++++++++++++++++ 2 files changed, 39 insertions(+), 1 deletion(-) create mode 100644 tests/async_logger.cpp diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index ce275ccb..22329b4e 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -10,7 +10,7 @@ find_package(Threads) add_library(catch INTERFACE) target_include_directories(catch INTERFACE ${CMAKE_CURRENT_SOURCE_DIR}) -file(GLOB catch_tests LIST_DIRECTORIES false RELATIVE ${CMAKE_CURRENT_SOURCE_DIR} *.cpp) +file(GLOB catch_tests LIST_DIRECTORIES false RELATIVE ${CMAKE_CURRENT_SOURCE_DIR} *.cpp *.h *.hpp) add_executable(catch_tests ${catch_tests}) target_link_libraries(catch_tests spdlog ${CMAKE_THREAD_LIBS_INIT}) diff --git a/tests/async_logger.cpp b/tests/async_logger.cpp new file mode 100644 index 00000000..bcfb1ca6 --- /dev/null +++ b/tests/async_logger.cpp @@ -0,0 +1,38 @@ + +#include + +#include "includes.h" +#include "../include/spdlog/common.h" +#include "../include/spdlog/tweakme.h" + + +TEST_CASE("async_logging_overflow ", "[async_logging]") +{ + std::string filename = "logs/async_log_overflow.txt"; + auto sink = std::make_shared(filename, true); + auto logger = std::make_shared( + "overflow_logger", + sink, + 2, // queue size + spdlog::async_overflow_policy::discard_log_msg + ); + for (int i = 0; i < 8; i++) { + logger->info("Message #{}", i); + } + logger->flush(); + logger.reset(); + std::string the_log = file_contents(filename); +#if defined(SPDLOG_ASYNC_COUNT_DISCARDED_MSG) + std::cout << the_log << std::endl; + REQUIRE(the_log.find("Dropped 6 messages") != std::string::npos); +#endif +} + + + + + + + + + From 2b008efb0696e7cdd5271f28824e9652b80a28d6 Mon Sep 17 00:00:00 2001 From: Alexander Zilberkant Date: Sat, 13 May 2017 01:10:58 +0300 Subject: [PATCH 4/4] disable SPDLOG_ASYNC_COUNT_DISCARDED_MSG --- include/spdlog/tweakme.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/include/spdlog/tweakme.h b/include/spdlog/tweakme.h index 0f3c2763..99b8f4dd 100644 --- a/include/spdlog/tweakme.h +++ b/include/spdlog/tweakme.h @@ -119,5 +119,5 @@ // Uncomment count in print warning message about number of dropped messages. // Only relevant for async_logger with async_overflow_policy::discard_log_msg // -#define SPDLOG_ASYNC_COUNT_DISCARDED_MSG +// #define SPDLOG_ASYNC_COUNT_DISCARDED_MSG ///////////////////////////////////////////////////////////////////////////////