From a96b4d75295207693ff6db070c13ddeed3378b39 Mon Sep 17 00:00:00 2001 From: gabime Date: Sat, 21 Jul 2018 23:30:26 +0300 Subject: [PATCH] Added periodic flusher support, and fixed some registry issues --- README.md | 11 ++++++ example/example.cpp | 12 +++++-- example/example.sln | 17 ++------- example/example.vcxproj | 6 ++-- include/spdlog/async.h | 10 ++++-- include/spdlog/details/registry.h | 53 ++++++++++++++++++++-------- include/spdlog/spdlog.h | 8 +++++ tests/test_async.cpp | 58 ++++++++++++++++++++----------- tests/test_misc.cpp | 17 +++++++++ tests/tests.vcxproj | 2 +- 10 files changed, 135 insertions(+), 59 deletions(-) diff --git a/README.md b/README.md index a2768f3b..7c3d21c9 100644 --- a/README.md +++ b/README.md @@ -145,6 +145,7 @@ void rotating_example() auto rotating_logger = spdlog::rotating_logger_mt("some_logger_name", "logs/rotating.txt", 1048576 * 5, 3); } ``` + --- #### Daily files ```c++ @@ -157,6 +158,16 @@ void daily_example() } ``` + +--- +#### Periodic flush +```c++ +// periodically flush all *registered* loggers every 3 seconds: +// warning: only use if all your loggers are thread safe! +spdlog::flush_every(std::chrono::seconds(3)); + +``` + --- #### Asynchronous logging ```c++ diff --git a/example/example.cpp b/example/example.cpp index 095c1a1a..786f3da7 100644 --- a/example/example.cpp +++ b/example/example.cpp @@ -45,8 +45,14 @@ int main(int, char *[]) // custom error handler err_handler_example(); + // flush all *registered* loggers using a worker thread every 3 seconds. + // note: registered loggers *must* be thread safe for this to work correctly! + spdlog::flush_every(std::chrono::seconds(3)); + // apply some function on all registered loggers - spdlog::apply_all([&](std::shared_ptr l) { l->info("End of example."); }); + spdlog::apply_all([&](std::shared_ptr l) { + l->info("End of example."); + }); // Release and close all loggers spdlog::drop_all(); @@ -172,7 +178,9 @@ void user_defined_example() void err_handler_example() { // can be set globally or per logger(logger->set_error_handler(..)) - spdlog::set_error_handler([](const std::string &msg) { spdlog::get("console")->error("*** ERROR HANDLER EXAMPLE ***: {}", msg); }); + spdlog::set_error_handler([](const std::string &msg) { + spdlog::get("console")->error("*** ERROR HANDLER EXAMPLE ***: {}", msg); + }); spdlog::get("console")->info("some invalid message to trigger an error {}{}{}{}", 3); } diff --git a/example/example.sln b/example/example.sln index 57895c9a..2e50f040 100644 --- a/example/example.sln +++ b/example/example.sln @@ -1,7 +1,7 @@  Microsoft Visual Studio Solution File, Format Version 12.00 -# Visual Studio 15 -VisualStudioVersion = 15.0.27428.2037 +# Visual Studio 2013 +VisualStudioVersion = 12.0.40629.0 MinimumVisualStudioVersion = 10.0.40219.1 Project("{8BC9CEB8-8B4A-11D0-8D11-00A0C91BC942}") = "example", "example.vcxproj", "{9E5AB93A-0CCE-4BAC-9FCB-0FC9CB5EB8D2}" EndProject @@ -29,6 +29,7 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "details", "details", "{08E9 ..\include\spdlog\details\null_mutex.h = ..\include\spdlog\details\null_mutex.h ..\include\spdlog\details\os.h = ..\include\spdlog\details\os.h ..\include\spdlog\details\pattern_formatter.h = ..\include\spdlog\details\pattern_formatter.h + ..\include\spdlog\details\periodic_worker.h = ..\include\spdlog\details\periodic_worker.h ..\include\spdlog\details\registry.h = ..\include\spdlog\details\registry.h ..\include\spdlog\details\spdlog_impl.h = ..\include\spdlog\details\spdlog_impl.h ..\include\spdlog\details\thread_pool.h = ..\include\spdlog\details\thread_pool.h @@ -101,16 +102,4 @@ Global GlobalSection(ExtensibilityGlobals) = postSolution SolutionGuid = {1BF53532-C5DC-4236-B195-9E17CBE40A48} EndGlobalSection - GlobalSection(Performance) = preSolution - HasPerformanceSessions = true - EndGlobalSection - GlobalSection(Performance) = preSolution - HasPerformanceSessions = true - EndGlobalSection - GlobalSection(Performance) = preSolution - HasPerformanceSessions = true - EndGlobalSection - GlobalSection(Performance) = preSolution - HasPerformanceSessions = true - EndGlobalSection EndGlobal diff --git a/example/example.vcxproj b/example/example.vcxproj index 0cedd620..12cbcf6b 100644 --- a/example/example.vcxproj +++ b/example/example.vcxproj @@ -31,7 +31,7 @@ Application true - v141 + v120 Unicode @@ -43,7 +43,7 @@ Application false - v141 + v120 true Unicode @@ -86,7 +86,7 @@ - Level3 + Level4 Disabled WIN32;_DEBUG;_CONSOLE;_LIB;%(PreprocessorDefinitions) ..\include;%(AdditionalIncludeDirectories) diff --git a/include/spdlog/async.h b/include/spdlog/async.h index b666b5ee..43b9f079 100644 --- a/include/spdlog/async.h +++ b/include/spdlog/async.h @@ -19,8 +19,12 @@ #include "spdlog/details/thread_pool.h" #include + namespace spdlog { +namespace details { +static const size_t default_async_q_size = 8192; +} // async logger factory - creates async loggers backed with thread pool. // if a global thread pool doesn't already exist, create it with default queue size of 8192 items and single thread. @@ -32,11 +36,11 @@ struct async_factory_impl { using details::registry; - std::lock_guard lock(registry::instance().tp_mutex()); + std::lock_guard lock(registry::instance().tp_mutex()); auto tp = registry::instance().get_thread_pool(); if (tp == nullptr) { - tp = std::make_shared(8192, 1); + tp = std::make_shared(details::default_async_q_size, 1); registry::instance().set_thread_pool(tp); } @@ -62,7 +66,7 @@ inline std::shared_ptr create_async_nb(const std::string &logger { return async_factory_nonblock::create(logger_name, std::forward(sink_args)...); } - + // set global thread pool. inline void init_thread_pool(size_t q_size, size_t thread_count) diff --git a/include/spdlog/details/registry.h b/include/spdlog/details/registry.h index e1961840..c44eef12 100644 --- a/include/spdlog/details/registry.h +++ b/include/spdlog/details/registry.h @@ -12,6 +12,7 @@ #include "spdlog/common.h" #include "spdlog/logger.h" +#include "spdlog/details/periodic_worker.h" #include #include @@ -34,7 +35,7 @@ public: void register_logger(std::shared_ptr new_logger) { - std::lock_guard lock(mutex_); + std::lock_guard lock(loggers_mutex_); auto logger_name = new_logger->name(); throw_if_exists_(logger_name); loggers_[logger_name] = new_logger; @@ -42,7 +43,7 @@ public: void register_and_init(std::shared_ptr new_logger) { - std::lock_guard lock(mutex_); + std::lock_guard lock(loggers_mutex_); auto logger_name = new_logger->name(); throw_if_exists_(logger_name); @@ -63,26 +64,26 @@ public: std::shared_ptr get(const std::string &logger_name) { - std::lock_guard lock(mutex_); + std::lock_guard lock(loggers_mutex_); auto found = loggers_.find(logger_name); return found == loggers_.end() ? nullptr : found->second; } void set_thread_pool(std::shared_ptr tp) { - std::lock_guard lock(mutex_); + std::lock_guard lock(tp_mutex_); tp_ = std::move(tp); } std::shared_ptr get_thread_pool() { - std::lock_guard lock(mutex_); + std::lock_guard lock(tp_mutex_); return tp_; } void set_pattern(const std::string &pattern, pattern_time_type time_type) { - std::lock_guard lock(mutex_); + std::lock_guard lock(loggers_mutex_); formatter_pattern_ = pattern; pattern_time_type_ = time_type; for (auto &l : loggers_) @@ -93,7 +94,7 @@ public: void set_level(level::level_enum log_level) { - std::lock_guard lock(mutex_); + std::lock_guard lock(loggers_mutex_); for (auto &l : loggers_) { l.second->set_level(log_level); @@ -103,7 +104,7 @@ public: void flush_on(level::level_enum log_level) { - std::lock_guard lock(mutex_); + std::lock_guard lock(loggers_mutex_); for (auto &l : loggers_) { l.second->flush_on(log_level); @@ -111,6 +112,13 @@ public: flush_level_ = log_level; } + void flush_every(std::chrono::seconds interval) + { + std::lock_guard lock(loggers_mutex_); + std::function clbk(std::bind(®istry_t::flush_all, this)); + periodic_flusher_.reset(new periodic_worker(clbk, interval)); + } + void set_error_handler(log_err_handler handler) { for (auto &l : loggers_) @@ -122,7 +130,7 @@ public: void apply_all(std::function)> fun) { - std::lock_guard lock(mutex_); + std::lock_guard lock(loggers_mutex_); for (auto &l : loggers_) { fun(l.second); @@ -131,24 +139,24 @@ public: void drop(const std::string &logger_name) { - std::lock_guard lock(mutex_); + std::lock_guard lock(loggers_mutex_); loggers_.erase(logger_name); } void drop_all() { { - std::lock_guard lock(mutex_); + std::lock_guard lock(loggers_mutex_); loggers_.clear(); } { - std::lock_guard lock(tp_mutex_); + std::lock_guard lock(tp_mutex_); tp_.reset(); } } - Mutex &tp_mutex() + std::recursive_mutex &tp_mutex() { return tp_mutex_; } @@ -162,6 +170,11 @@ public: private: registry_t() = default; + ~registry_t() + { + periodic_flusher_.reset(); + } + void throw_if_exists_(const std::string &logger_name) { if (loggers_.find(logger_name) != loggers_.end()) @@ -170,8 +183,17 @@ private: } } - Mutex mutex_; - Mutex tp_mutex_; + void flush_all() + { + std::lock_guard lock(loggers_mutex_); + for (auto &l : loggers_) + { + l.second->flush(); + } + } + + Mutex loggers_mutex_; + std::recursive_mutex tp_mutex_; std::unordered_map> loggers_; std::string formatter_pattern_ = "%+"; pattern_time_type pattern_time_type_ = pattern_time_type::local; @@ -179,6 +201,7 @@ private: level::level_enum flush_level_ = level::off; log_err_handler err_handler_; std::shared_ptr tp_; + std::unique_ptr periodic_flusher_; }; #ifdef SPDLOG_NO_REGISTRY_MUTEX diff --git a/include/spdlog/spdlog.h b/include/spdlog/spdlog.h index cde38ee5..49ae2729 100644 --- a/include/spdlog/spdlog.h +++ b/include/spdlog/spdlog.h @@ -71,6 +71,14 @@ inline void flush_on(level::level_enum log_level) details::registry::instance().flush_on(log_level); } +// Start/Restart a periodic flusher thread +// Warning: Use only if all your loggers are thread safe! +inline void flush_every(std::chrono::seconds interval) +{ + details::registry::instance().flush_every(interval); +} + + // Set global error handler inline void set_error_handler(log_err_handler handler) { diff --git a/tests/test_async.cpp b/tests/test_async.cpp index e149d7fd..bcfc428b 100644 --- a/tests/test_async.cpp +++ b/tests/test_async.cpp @@ -27,34 +27,34 @@ TEST_CASE("discard policy ", "[async]") using namespace spdlog; auto test_sink = std::make_shared(); size_t queue_size = 2; - size_t messages = 1024; - { - auto tp = std::make_shared(queue_size, 1); - auto logger = std::make_shared("as", test_sink, tp, async_overflow_policy::overrun_oldest); - for (size_t i = 0; i < messages; i++) - { - logger->info("Hello message #{}", i); - } - } + size_t messages = 10240; + auto tp = std::make_shared(queue_size, 1); + auto logger = std::make_shared("as", test_sink, tp, async_overflow_policy::overrun_oldest); + for (size_t i = 0; i < messages; i++) + { + logger->info("Hello message"); + } REQUIRE(test_sink->msg_counter() < messages); + } TEST_CASE("discard policy using factory ", "[async]") { using namespace spdlog; - //auto test_sink = std::make_shared(); size_t queue_size = 2; - size_t messages = 1024; - { - auto logger = spdlog::create_async_nb("as2"); - for (size_t i = 0; i < messages; i++) - { - logger->info("Hello message #{}", i); - } - auto sink = std::static_pointer_cast(logger->sinks()[0]); - REQUIRE(sink->msg_counter() < messages); - } + size_t messages = 10240; + spdlog::init_thread_pool(queue_size, 1); + + auto logger = spdlog::create_async_nb("as2"); + for (size_t i = 0; i < messages; i++) + { + logger->info("Hello message"); + } + auto sink = std::static_pointer_cast(logger->sinks()[0]); + REQUIRE(sink->msg_counter() < messages); + spdlog::drop_all(); + } TEST_CASE("flush", "[async]") @@ -73,11 +73,27 @@ TEST_CASE("flush", "[async]") logger->flush(); } - std::this_thread::sleep_for(std::chrono::milliseconds(250)); + //std::this_thread::sleep_for(std::chrono::milliseconds(250)); REQUIRE(test_sink->msg_counter() == messages); REQUIRE(test_sink->flush_counter() == 1); } + +TEST_CASE("async periodic flush", "[async]") +{ + using namespace spdlog; + + auto logger = spdlog::create_async("as"); + + auto test_sink = std::static_pointer_cast(logger->sinks()[0]); + + spdlog::flush_every(std::chrono::seconds(1)); + std::this_thread::sleep_for(std::chrono::milliseconds(1100)); + REQUIRE(test_sink->flush_counter() == 1); + spdlog::flush_every(std::chrono::seconds(0)); + spdlog::drop_all(); +} + TEST_CASE("tp->wait_empty() ", "[async]") { using namespace spdlog; diff --git a/tests/test_misc.cpp b/tests/test_misc.cpp index e546bd2a..39d4a907 100644 --- a/tests/test_misc.cpp +++ b/tests/test_misc.cpp @@ -1,4 +1,5 @@ #include "includes.h" +#include "test_sink.h" template std::string log_info(const T &what, spdlog::level::level_enum logger_level = spdlog::level::info) @@ -75,3 +76,19 @@ TEST_CASE("to_level_enum", "[convert_to_level_enum]") REQUIRE(spdlog::level::from_str("off") == spdlog::level::off); REQUIRE(spdlog::level::from_str("null") == spdlog::level::off); } + + +TEST_CASE("periodic flush", "[periodic_flush]") +{ + using namespace spdlog; + + auto logger = spdlog::create("periodic_flush"); + + auto test_sink = std::static_pointer_cast(logger->sinks()[0]); + + spdlog::flush_every(std::chrono::seconds(1)); + std::this_thread::sleep_for(std::chrono::milliseconds(1100)); + REQUIRE(test_sink->flush_counter() == 1); + spdlog::flush_every(std::chrono::seconds(0)); + spdlog::drop_all(); +} diff --git a/tests/tests.vcxproj b/tests/tests.vcxproj index 02e0365b..a246fd21 100644 --- a/tests/tests.vcxproj +++ b/tests/tests.vcxproj @@ -110,7 +110,7 @@ - Level4 + Level3 MaxSpeed true true