From b5dd703bb979a721ee822e86e73defef46f93f2e Mon Sep 17 00:00:00 2001 From: Odysseas Georgoudis Date: Fri, 12 May 2023 01:00:20 +0100 Subject: [PATCH] report messages via the notificaiton handler --- CHANGELOG.md | 16 +++- .../quill_backend_throughput.cpp | 2 +- examples/example_configure_backend.cpp | 8 +- quill/include/quill/Config.h | 16 ++-- quill/include/quill/Quill.h | 4 +- .../quill/detail/backend/BackendWorker.h | 85 +++++++++++++------ quill/include/quill/detail/misc/Common.h | 2 +- quill/include/quill/detail/misc/Utilities.h | 8 -- .../quill/detail/spsc_queue/UnboundedQueue.h | 23 ++++- quill/src/detail/backend/BackendWorker.cpp | 17 ++-- quill/src/detail/misc/Utilities.cpp | 18 ---- quill/test/LogTest.cpp | 34 ++++---- 12 files changed, 133 insertions(+), 100 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index b4ca5b76..b86585bb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,4 +1,4 @@ -- [v2.8.1](#v281) +- [v2.9.0](#v290) - [v2.8.0](#v280) - [v2.7.0](#v270) - [v2.6.0](#v260) @@ -41,11 +41,21 @@ - [v1.1.0](#v110) - [v1.0.0](#v100) -## v2.8.1 +## v2.9.0 **Fixes** -- Fixed a bug in TimeRotatingFileHandler ([#287](https://github.com/odygrd/quill/pull/287)) +- Fixed a bug in TimeRotatingFileHandler. ([#287](https://github.com/odygrd/quill/pull/287)) + +**Improvements** + +- Renamed `backend_thread_error_handler` to `backend_thread_notifications_handler` in `Config.h`. Previously this + handler was + used only to report errors from the backend worker thread to the user. This callback will also now report + info messages to the user. +- Report unbounded spsc queue reallocation via + the `backend_thread_notifications_handler`. ([#286](https://github.com/odygrd/quill/pull/286)) +- Report bounded spsc queue dropped messages via the `backend_thread_notifications_handler`. ## v2.8.0 diff --git a/benchmarks/backend_throughput/quill_backend_throughput.cpp b/benchmarks/backend_throughput/quill_backend_throughput.cpp index 8b727fa8..71e3007a 100644 --- a/benchmarks/backend_throughput/quill_backend_throughput.cpp +++ b/benchmarks/backend_throughput/quill_backend_throughput.cpp @@ -45,7 +45,7 @@ int main() auto delta_d = std::chrono::duration_cast>(delta).count(); std::cout << fmt::format( - "Throughput is {:.2f} million msgs/sec average, total time elapsed: {} ms for {} " + "Throughput is {:.2f} million msgs/sec average, total time elapsed: {} ms for {} " "log messages \n", total_iterations / delta_d / 1e6, std::chrono::duration_cast(delta).count(), total_iterations) diff --git a/examples/example_configure_backend.cpp b/examples/example_configure_backend.cpp index 50e9c16e..3f78e5d5 100644 --- a/examples/example_configure_backend.cpp +++ b/examples/example_configure_backend.cpp @@ -10,12 +10,10 @@ int main() { quill::Config cfg; -#if !defined(QUILL_NO_EXCEPTIONS) // Set a custom error handler to handler exceptions - if exceptions are enabled - cfg.backend_thread_error_handler = [](std::string const& s) - { std::cout << "Hello from error handler. Error: " << s << std::endl; }; -#endif - + cfg.backend_thread_notification_handler = [](std::string const& s) + { std::cout << "Hello from notification handler. Message: " << s << std::endl; }; + // Setting to an invalid CPU. When we call quill::start() our error handler will be invoked and an error will be logged cfg.backend_thread_cpu_affinity = static_cast(321312); diff --git a/quill/include/quill/Config.h b/quill/include/quill/Config.h index feea5be3..14d78445 100644 --- a/quill/include/quill/Config.h +++ b/quill/include/quill/Config.h @@ -142,18 +142,22 @@ struct Config */ std::string default_logger_name = "root"; -#if !defined(QUILL_NO_EXCEPTIONS) /** * The background thread in very rare occasion might thrown an exception which can not be caught * in the user threads. In that case the backend worker thread will call this callback instead. * - * Set up a custom error handler to be used if the backend thread has any error. + * Set up a custom notifications handler to be used if the backend thread has any error. * - * Set an error handler callback e.g : - * backend_thread_error_handler = [](std::string const& s) { std::cerr << s << std::endl; } + * This handler is also used to deliver messages to the user, for example when the unbounded + * queue reallocates or when the bounded queue gets full + * + * When not set here the default is: + * backend_thread_notification_handler = [](std::string const& s) { std::cerr << s << std::endl; } + * + * If you wish to disable being notified use: + * backend_thread_notification_handler = [](std::string const&) { } */ - backend_worker_error_handler_t backend_thread_error_handler; -#endif + backend_worker_notification_handler_t backend_thread_notification_handler; /** * Sets a custom clock that will be used to obtain the timestamp diff --git a/quill/include/quill/Quill.h b/quill/include/quill/Quill.h index 742a401b..3b646384 100644 --- a/quill/include/quill/Quill.h +++ b/quill/include/quill/Quill.h @@ -30,8 +30,8 @@ namespace quill /** Version Info **/ constexpr uint32_t VersionMajor{2}; -constexpr uint32_t VersionMinor{8}; -constexpr uint32_t VersionPatch{1}; +constexpr uint32_t VersionMinor{9}; +constexpr uint32_t VersionPatch{0}; constexpr uint32_t Version{VersionMajor * 10000 + VersionMinor * 100 + VersionPatch}; /** forward declarations **/ diff --git a/quill/include/quill/detail/backend/BackendWorker.h b/quill/include/quill/detail/backend/BackendWorker.h index ed2695c6..fb3c8a56 100644 --- a/quill/include/quill/detail/backend/BackendWorker.h +++ b/quill/include/quill/detail/backend/BackendWorker.h @@ -162,7 +162,8 @@ class BackendWorker * @param cached_thread_contexts loaded thread contexts */ QUILL_ATTRIBUTE_HOT static void _check_dropped_messages( - ThreadContextCollection::backend_thread_contexts_cache_t const& cached_thread_contexts) noexcept; + ThreadContextCollection::backend_thread_contexts_cache_t const& cached_thread_contexts, + backend_worker_notification_handler_t const& notification_handler) noexcept; /** * Process a structured log template message @@ -203,6 +204,8 @@ class BackendWorker std::chrono::system_clock::time_point _last_rdtsc_resync; uint32_t _backend_worker_thread_id{0}; /** cached backend worker thread id */ + backend_worker_notification_handler_t _notification_handler; /** error handler for the backend thread */ + bool _backend_thread_yield; /** backend_thread_yield from config **/ bool _has_unflushed_messages{false}; /** There are messages that are buffered by the OS, but not yet flushed */ bool _strict_log_timestamp_order{true}; @@ -210,10 +213,6 @@ class BackendWorker bool _use_transit_buffer{true}; std::atomic _is_running{false}; /** The spawned backend thread status */ -#if !defined(QUILL_NO_EXCEPTIONS) - backend_worker_error_handler_t _error_handler; /** error handler for the backend thread */ -#endif - alignas(CACHE_LINE_ALIGNED) std::mutex _wake_up_mutex; std::condition_variable _wake_up_cv; bool _wake_up{false}; @@ -254,13 +253,13 @@ void BackendWorker::run() _rdtsc_resync_interval = _config.rdtsc_resync_interval; _use_transit_buffer = _config.backend_thread_use_transit_buffer; -#if !defined(QUILL_NO_EXCEPTIONS) - if (_config.backend_thread_error_handler) + if (_config.backend_thread_notification_handler) { // set up the default error handler - _error_handler = _config.backend_thread_error_handler; + _notification_handler = _config.backend_thread_notification_handler; } -#endif + + assert(_notification_handler && "_notification_handler is always set"); std::thread worker( [this]() @@ -274,8 +273,8 @@ void BackendWorker::run() } } #if !defined(QUILL_NO_EXCEPTIONS) - QUILL_CATCH(std::exception const& e) { _error_handler(e.what()); } - QUILL_CATCH_ALL() { _error_handler(std::string{"Caught unhandled exception."}); } + QUILL_CATCH(std::exception const& e) { _notification_handler(e.what()); } + QUILL_CATCH_ALL() { _notification_handler(std::string{"Caught unhandled exception."}); } #endif QUILL_TRY @@ -284,8 +283,8 @@ void BackendWorker::run() set_thread_name(_config.backend_thread_name.data()); } #if !defined(QUILL_NO_EXCEPTIONS) - QUILL_CATCH(std::exception const& e) { _error_handler(e.what()); } - QUILL_CATCH_ALL() { _error_handler(std::string{"Caught unhandled exception."}); } + QUILL_CATCH(std::exception const& e) { _notification_handler(e.what()); } + QUILL_CATCH_ALL() { _notification_handler(std::string{"Caught unhandled exception."}); } #endif // Cache this thread's id @@ -300,10 +299,10 @@ void BackendWorker::run() // main loop QUILL_TRY { _main_loop(); } #if !defined(QUILL_NO_EXCEPTIONS) - QUILL_CATCH(std::exception const& e) { _error_handler(e.what()); } + QUILL_CATCH(std::exception const& e) { _notification_handler(e.what()); } QUILL_CATCH_ALL() { - _error_handler(std::string{"Caught unhandled exception."}); + _notification_handler(std::string{"Caught unhandled exception."}); } // clang-format on #endif } @@ -311,10 +310,10 @@ void BackendWorker::run() // exit QUILL_TRY { _exit(); } #if !defined(QUILL_NO_EXCEPTIONS) - QUILL_CATCH(std::exception const& e) { _error_handler(e.what()); } + QUILL_CATCH(std::exception const& e) { _notification_handler(e.what()); } QUILL_CATCH_ALL() { - _error_handler(std::string{"Caught unhandled exception."}); + _notification_handler(std::string{"Caught unhandled exception."}); } // clang-format on #endif }); @@ -379,7 +378,15 @@ uint32_t BackendWorker::_read_queue_messages_and_decode(QueueT& queue, ThreadCon size_t const queue_capacity = queue.capacity(); uint32_t total_bytes_read{0}; - std::byte* read_pos = queue.prepare_read(); + std::byte* read_pos; + if constexpr (std::is_same_v) + { + read_pos = queue.prepare_read(_notification_handler); + } + else + { + read_pos = queue.prepare_read(); + } // read max of one full queue and also max_transit events otherwise we can get stuck here forever // if the producer keeps producing @@ -407,7 +414,14 @@ uint32_t BackendWorker::_read_queue_messages_and_decode(QueueT& queue, ThreadCon total_bytes_read += static_cast(read_pos - read_begin); // read again - read_pos = queue.prepare_read(); + if constexpr (std::is_same_v) + { + read_pos = queue.prepare_read(_notification_handler); + } + else + { + read_pos = queue.prepare_read(); + } } if (total_bytes_read != 0) @@ -678,12 +692,10 @@ void BackendWorker::_process_transit_event(TransitEvent& transit_event) } #if !defined(QUILL_NO_EXCEPTIONS) QUILL_CATCH(std::exception const& e) - { - _error_handler(e.what()); - } + { _notification_handler(e.what()); } QUILL_CATCH_ALL() { - _error_handler(std::string{"Caught unhandled exception."}); + _notification_handler(std::string{"Caught unhandled exception."}); } // clang-format on #endif } @@ -723,13 +735,22 @@ bool BackendWorker::_process_and_write_single_message(const ThreadContextCollect for (ThreadContext* thread_context : cached_thread_contexts) { std::visit( - [&thread_context, &min_ts, &tc](auto& queue) + [&thread_context, &min_ts, &tc, this](auto& queue) { // find the minimum timestamp accross all queues using T = std::decay_t; if constexpr ((std::is_same_v) || (std::is_same_v)) { - std::byte* read_pos = queue.prepare_read(); + std::byte* read_pos; + if constexpr (std::is_same_v) + { + read_pos = queue.prepare_read(_notification_handler); + } + else + { + read_pos = queue.prepare_read(); + } + if (read_pos && (reinterpret_cast(read_pos)->timestamp < min_ts)) { min_ts = reinterpret_cast(read_pos)->timestamp; @@ -752,7 +773,15 @@ bool BackendWorker::_process_and_write_single_message(const ThreadContextCollect using T = std::decay_t; if constexpr ((std::is_same_v) || (std::is_same_v)) { - std::byte* read_pos = queue.prepare_read(); + std::byte* read_pos; + if constexpr (std::is_same_v) + { + read_pos = queue.prepare_read(_notification_handler); + } + else + { + read_pos = queue.prepare_read(); + } assert(read_pos); std::byte* const read_begin = read_pos; @@ -842,7 +871,7 @@ void BackendWorker::_main_loop() _force_flush(); // check for any dropped messages by the threads - _check_dropped_messages(cached_thread_contexts); + _check_dropped_messages(cached_thread_contexts, _notification_handler); // We can also clear any invalidated or empty thread contexts _thread_context_collection.clear_invalid_and_empty_thread_contexts(); @@ -951,7 +980,7 @@ void BackendWorker::_exit() if (all_empty) { // we are done, all queues are now empty - _check_dropped_messages(cached_thread_contexts); + _check_dropped_messages(cached_thread_contexts, _notification_handler); _force_flush(); break; } diff --git a/quill/include/quill/detail/misc/Common.h b/quill/include/quill/detail/misc/Common.h index 9472251e..5c89c22a 100644 --- a/quill/include/quill/detail/misc/Common.h +++ b/quill/include/quill/detail/misc/Common.h @@ -187,7 +187,7 @@ enum TimestampClockType : uint8_t /** * backend worker thread error handler type */ -using backend_worker_error_handler_t = std::function; +using backend_worker_notification_handler_t = std::function; } // namespace quill diff --git a/quill/include/quill/detail/misc/Utilities.h b/quill/include/quill/detail/misc/Utilities.h index 6a6480a0..e8128ff0 100644 --- a/quill/include/quill/detail/misc/Utilities.h +++ b/quill/include/quill/detail/misc/Utilities.h @@ -132,12 +132,4 @@ QUILL_NODISCARD time_t next_noon_or_midnight_timestamp(time_t timestamp, Timezon * @return the formatted string as vector of characters */ QUILL_NODISCARD std::vector safe_strftime(char const* format_string, time_t timestamp, Timezone timezone); - -/** - * Split a string into tokens - * @param s given string - * @param delimiter delimiter - * @return returns a vector of tokens - */ -QUILL_NODISCARD std::vector split(std::string const& s, char delimiter); } // namespace quill::detail \ No newline at end of file diff --git a/quill/include/quill/detail/spsc_queue/UnboundedQueue.h b/quill/include/quill/detail/spsc_queue/UnboundedQueue.h index 9bedda1c..c8629acc 100644 --- a/quill/include/quill/detail/spsc_queue/UnboundedQueue.h +++ b/quill/include/quill/detail/spsc_queue/UnboundedQueue.h @@ -11,6 +11,8 @@ #include #include "BoundedQueue.h" +#include "quill/detail/misc/Common.h" +#include "quill/detail/misc/Os.h" namespace quill::detail { @@ -153,9 +155,11 @@ class UnboundedQueue /** * Prepare to read from the buffer + * @notification_handler a callback used for notifications to the user * @return a pair of the buffer location to read and the number of available bytes */ - QUILL_NODISCARD_ALWAYS_INLINE_HOT std::byte* prepare_read() + QUILL_NODISCARD_ALWAYS_INLINE_HOT std::byte* prepare_read( + backend_worker_notification_handler_t const& notification_handler = backend_worker_notification_handler_t{}) { std::byte* read_pos = _consumer->bounded_queue.prepare_read(); @@ -177,9 +181,26 @@ class UnboundedQueue _consumer->bounded_queue.commit_read(); // switch to the new buffer, existing one is deleted + auto const previous_capacity = _consumer->bounded_queue.capacity(); delete _consumer; _consumer = next_node; read_pos = _consumer->bounded_queue.prepare_read(); + + if (notification_handler) + { + char ts[24]; + time_t t = time(nullptr); + struct tm p; + quill::detail::localtime_rs(std::addressof(t), std::addressof(p)); + strftime(ts, 24, "%X", std::addressof(p)); + + // we switched to a new here, and we also notify the user of the allocation via the + // notification_handler + notification_handler( + std::string{ts} + " Quill INFO: A new SPSC queue was allocated [new_capacity_bytes: " + + std::to_string(_consumer->bounded_queue.capacity()) + + ", previous_capacity_bytes: " + std::to_string(previous_capacity) + "]"); + } } } } diff --git a/quill/src/detail/backend/BackendWorker.cpp b/quill/src/detail/backend/BackendWorker.cpp index 1373632d..bb66b5a7 100644 --- a/quill/src/detail/backend/BackendWorker.cpp +++ b/quill/src/detail/backend/BackendWorker.cpp @@ -16,10 +16,8 @@ BackendWorker::BackendWorker(Config const& config, ThreadContextCollection& thre _logger_collection(logger_collection), _process_id(fmt::format_int(get_process_id()).str()) { -#if !defined(QUILL_NO_EXCEPTIONS) - // set up the default error handler - _error_handler = [](std::string const& s) { std::cerr << s << std::endl; }; -#endif + // set up the default error handler. This is done here to avoid including std::cerr in a header file + _notification_handler = [](std::string const& s) { std::cerr << s << std::endl; }; } /***/ @@ -62,7 +60,8 @@ void BackendWorker::wake_up() uint32_t BackendWorker::thread_id() const noexcept { return _backend_worker_thread_id; } /***/ -void BackendWorker::_check_dropped_messages(ThreadContextCollection::backend_thread_contexts_cache_t const& cached_thread_contexts) noexcept +void BackendWorker::_check_dropped_messages(ThreadContextCollection::backend_thread_contexts_cache_t const& cached_thread_contexts, + backend_worker_notification_handler_t const& notification_handler) noexcept { for (ThreadContext* thread_context : cached_thread_contexts) { @@ -76,11 +75,9 @@ void BackendWorker::_check_dropped_messages(ThreadContextCollection::backend_thr quill::detail::localtime_rs(std::addressof(t), std::addressof(p)); strftime(ts, 24, "%X", std::addressof(p)); - // Write to stderr that we dropped messages - std::string const msg = fmt::format("~ {} localtime dropped {} log messages from thread {}\n", - ts, dropped_messages_cnt, thread_context->thread_id()); - - detail::fwrite_fully(msg.data(), sizeof(char), msg.size(), stderr); + // Notify that we dropped messages + notification_handler(fmt::format("{} Quill INFO: dropped {} log messages from thread {}\n", + ts, dropped_messages_cnt, thread_context->thread_id())); } } } diff --git a/quill/src/detail/misc/Utilities.cpp b/quill/src/detail/misc/Utilities.cpp index d627ed2b..dcab9b54 100644 --- a/quill/src/detail/misc/Utilities.cpp +++ b/quill/src/detail/misc/Utilities.cpp @@ -125,22 +125,4 @@ std::vector safe_strftime(char const* format_string, time_t timestamp, Tim return buffer; } - -/***/ -std::vector split(std::string const& s, char delimiter) -{ - std::vector tokens; - std::istringstream token_stream(s); - - std::string token; - while (std::getline(token_stream, token, delimiter)) - { - if (!token.empty()) - { - tokens.push_back(token); - } - } - return tokens; -} - } // namespace quill::detail diff --git a/quill/test/LogTest.cpp b/quill/test/LogTest.cpp index 17f357a3..3c777687 100644 --- a/quill/test/LogTest.cpp +++ b/quill/test/LogTest.cpp @@ -626,18 +626,18 @@ TEST_CASE("many_loggers_multiple_threads") #if !defined(QUILL_NO_EXCEPTIONS) /***/ -TEST_CASE("backend_error_handler") +TEST_CASE("backend_notification_handler") { - fs::path const filename{"test_backend_error_handler"}; + fs::path const filename{"test_backend_notification_handler"}; { LogManager lm; // counter to check our error handler was invoked // atomic because we check this value on this thread, but the backend worker thread updates it - std::atomic error_handler_invoked{0}; + std::atomic notification_handler_invoked{0}; std::thread frontend( - [&lm, &filename, &error_handler_invoked]() + [&lm, &filename, ¬ification_handler_invoked]() { quill::Config cfg; @@ -650,8 +650,8 @@ TEST_CASE("backend_error_handler") "ut_labore_et_dolore_magna_aliqua"; // Set a custom error handler to handler exceptions - cfg.backend_thread_error_handler = [&error_handler_invoked](std::string const& s) - { ++error_handler_invoked; }; + cfg.backend_thread_notification_handler = [¬ification_handler_invoked](std::string const& s) + { ++notification_handler_invoked; }; // Set a file handler as the custom logger handler and log to it cfg.default_handlers.emplace_back(lm.handler_collection().create_handler( @@ -675,7 +675,7 @@ TEST_CASE("backend_error_handler") frontend.join(); // Check our handler was invoked since either set_backend_thread_name or set_backend_thread_cpu_affinity should have failed - REQUIRE(error_handler_invoked.load() != 0); + REQUIRE(notification_handler_invoked.load() != 0); lm.stop_backend_worker(); } @@ -684,9 +684,9 @@ TEST_CASE("backend_error_handler") } /***/ -TEST_CASE("backend_error_handler_log_from_backend_thread") +TEST_CASE("backend_notification_handler_log_from_backend_thread") { - fs::path const filename{"test_backend_error_handler_log_from_backend_thread"}; + fs::path const filename{"test_backend_notification_handler_log_from_backend_thread"}; { LogManager lm; @@ -708,7 +708,7 @@ TEST_CASE("backend_error_handler_log_from_backend_thread") filename.string(), "a", FilenameAppend::None, FileEventNotifier{}, false)); // Set a custom error handler to handler exceptions - cfg.backend_thread_error_handler = [&lm](std::string const& s) + cfg.backend_thread_notification_handler = [&lm](std::string const& s) { LOG_WARNING(lm.logger_collection().get_logger(), "error handler invoked"); lm.flush(); // this will be called by the backend but do nothing @@ -743,15 +743,15 @@ TEST_CASE("backend_error_handler_log_from_backend_thread") } /***/ -TEST_CASE("backend_error_handler_error_throw_while_in_backend_process") +TEST_CASE("backend_notification_handler_error_throw_while_in_backend_process") { - fs::path const filename{"test_backend_error_handler_error_throw_while_in_backend_process"}; + fs::path const filename{"test_backend_notification_handler_error_throw_while_in_backend_process"}; { LogManager lm; // counter to check our error handler was invoked // atomic because we check this value on this thread, but the backend worker thread updates it - std::atomic error_handler_invoked{0}; + std::atomic notification_handler_invoked{0}; quill::Config cfg; @@ -760,8 +760,8 @@ TEST_CASE("backend_error_handler_error_throw_while_in_backend_process") filename.string(), "a", FilenameAppend::None, FileEventNotifier{}, false)); // Set a custom error handler to handler exceptions - cfg.backend_thread_error_handler = [&error_handler_invoked](std::string const& s) - { ++error_handler_invoked; }; + cfg.backend_thread_notification_handler = [¬ification_handler_invoked](std::string const& s) + { ++notification_handler_invoked; }; lm.configure(cfg); lm.start_backend_worker(false, std::initializer_list{}); @@ -772,7 +772,7 @@ TEST_CASE("backend_error_handler_error_throw_while_in_backend_process") Logger* logger = lm.logger_collection().get_logger(); // Here we will call LOG_BACKTRACE(...) without calling init_backtrace(...) first - // We expect an error to be thrown and reported to our error handler backend_thread_error_handler + // We expect an error to be thrown and reported to our error handler backend_thread_notification_handler LOG_INFO(logger, "Before backtrace."); for (uint32_t i = 0; i < 4; ++i) @@ -793,7 +793,7 @@ TEST_CASE("backend_error_handler_error_throw_while_in_backend_process") frontend.join(); // Check that the backend worker thread called our error handler 4 times - the number of LOG_BACKTRACE calls - REQUIRE_EQ(error_handler_invoked.load(), 4); + REQUIRE_EQ(notification_handler_invoked.load(), 4); } quill::detail::remove_file(filename);