From 567e85e6d493720b9824df3e1ac021506a7f91cc Mon Sep 17 00:00:00 2001 From: gabi Date: Sat, 1 Nov 2014 02:12:12 +0200 Subject: [PATCH] bench --- example/bench.cpp | 167 ++++++++++-------- example/example.cpp | 7 +- include/spdlog/details/blocking_queue.h | 8 +- include/spdlog/details/logger_impl.h | 8 +- .../spdlog/details/pattern_formatter_impl.h | 18 +- include/spdlog/details/registry.h | 4 +- include/spdlog/details/spdlog_impl.h | 4 +- include/spdlog/logger.h | 3 +- include/spdlog/sinks/async_sink.h | 11 ++ include/spdlog/sinks/file_sinks.h | 14 ++ include/spdlog/sinks/null_sink.h | 3 + include/spdlog/sinks/ostream_sink.h | 3 + include/spdlog/sinks/sink.h | 1 + include/spdlog/sinks/stdout_sinks.h | 1 + include/spdlog/spdlog.h | 6 +- 15 files changed, 169 insertions(+), 89 deletions(-) diff --git a/example/bench.cpp b/example/bench.cpp index 7428dfbd..bcdc74bc 100644 --- a/example/bench.cpp +++ b/example/bench.cpp @@ -8,7 +8,7 @@ #include #include "spdlog/spdlog.h" #include "spdlog/sinks/file_sinks.h" -#include "spdlog/sinks/stdout_sinks.h" +#include "spdlog/sinks/async_sink.h" #include "spdlog/sinks/null_sink.h" #include "utils.h" @@ -20,82 +20,57 @@ using namespace spdlog::sinks; using namespace utils; -void bench(int howmany, std::shared_ptr log) -{ - cout << log->name() << "...\t\t" << flush; - auto start = system_clock::now(); - for (auto i = 0; i < howmany; ++i) - { - log->info("Hello logger: msg number ") << i; - } - - auto delta = system_clock::now() - start; - auto delta_d = duration_cast> (delta).count(); - cout << format(int(howmany / delta_d)) << "/sec" << endl; -} - - -void bench_mt(int howmany, std::shared_ptr log, int thread_count) -{ - - cout << log->name() << "...\t\t" << flush; - std::atomic msg_counter{0}; - vector threads; - auto start = system_clock::now(); - for (int t = 0; t < thread_count; ++t) - { - threads.push_back(std::thread([&]() { - while(msg_counter++ < howmany) - log->info("Hello logger: msg number ") << msg_counter; - - })); - } - - for(auto &t:threads) - { - t.join(); - }; - - auto delta = system_clock::now() - start; - auto delta_d = duration_cast> (delta).count(); - cout << format(int(howmany / delta_d)) << "/sec" << endl; - } - +void bench(int howmany, std::shared_ptr log); +void bench_mt(int howmany, std::shared_ptr log, int thread_count); int main(int argc, char* argv[]) { - + + int howmany = 123456; + int threads = 4; + int flush_interval = 1000; + int file_size = 30 * 1024 * 1024; + int rotating_files = 5; try { - - int howmany = argc <= 1 ? 250000 : atoi(argv[1]); - int threads = argc <= 2 ? 4 : atoi(argv[2]); - int flush_interval = 100; - - cout << "*******************************************************************************\n"; - cout << "Single thread, " << format(howmany) << " iterations, flush every " << flush_interval << " lines"<< endl; - cout << "*******************************************************************************\n"; - - auto rotating_st = spdlog::rotating_logger_st("rotating_st", "logs/rotating_st", 1024 * 1024 * 5, 5, flush_interval); - bench(howmany, rotating_st); - - auto daily_st = spdlog::daily_logger_st("daily_st", "logs/daily_st", flush_interval); - bench(howmany, daily_st); - - bench(howmany, spdlog::create("null_st")); - - cout << "\n*******************************************************************************\n"; - cout << threads << " threads, " << format(howmany) << " iterations, flush every " << flush_interval << " lines" << endl; - cout << "*******************************************************************************\n"; - - auto rotating_mt = spdlog::rotating_logger_mt("rotating_mt", "logs/rotating_mt", 1024 * 1024 * 5, 5, flush_interval); - bench_mt(howmany, rotating_mt, threads); - - auto daily_mt = spdlog::daily_logger_mt("daily_mt", "logs/daily_mt", flush_interval); - bench_mt(howmany, daily_mt, threads); - - bench_mt(howmany, spdlog::create("null_mt"), threads); + if(argc > 1) + howmany = atoi(argv[1]); + if (argc > 2) + threads = atoi(argv[2]); + + cout << "*******************************************************************************\n"; + cout << "Single thread, " << format(howmany) << " iterations, flush every " << flush_interval << " lines"<< endl; + cout << "*******************************************************************************\n"; + + auto rotating_st = spdlog::rotating_logger_st("rotating_st", "logs/rotating_st", file_size, rotating_files, flush_interval); + bench(howmany, rotating_st); + + + auto daily_st = spdlog::daily_logger_st("daily_st", "logs/daily_st", flush_interval); + bench(howmany, daily_st); + + bench(howmany, spdlog::create("null_st")); + + cout << "\n*******************************************************************************\n"; + cout << threads << " threads sharing same logger, " << format(howmany) << " iterations, flush every " << flush_interval << " lines" << endl; + cout << "*******************************************************************************\n"; + + auto rotating_mt = spdlog::rotating_logger_mt("rotating_mt", "logs/rotating_mt", file_size, rotating_files, flush_interval); + bench_mt(howmany, rotating_mt, threads); + + + auto daily_mt = spdlog::daily_logger_mt("daily_mt", "logs/daily_mt", flush_interval); + bench_mt(howmany, daily_mt, threads); + + + auto async_sink = std::make_shared(1000); + auto file_sink = std::make_shared("logs/async_logger", "txt", file_size, rotating_files, flush_interval); + async_sink->add_sink(file_sink); + auto async_logger = std::make_shared("async_logger", async_sink ); + bench_mt(howmany, async_logger, threads); + + bench_mt(howmany, spdlog::create("null_mt"), threads); } catch (std::exception &ex) { @@ -105,3 +80,53 @@ int main(int argc, char* argv[]) return 0; } + +void bench(int howmany, std::shared_ptr log) +{ + cout << log->name() << "...\t\t" << flush; + auto start = system_clock::now(); + for (auto i = 0; i < howmany; ++i) + { + log->info("Hello logger: msg number ") << i << "**************************" << i + 1 << "," << 1 + 2;; + } + + + auto delta = system_clock::now() - start; + auto delta_d = duration_cast> (delta).count(); + cout << format(int(howmany / delta_d)) << "/sec" << endl; + log->close(); +} + + +void bench_mt(int howmany, std::shared_ptr log, int thread_count) +{ + + cout << log->name() << "...\t\t" << flush; + std::atomic msg_counter {0}; + vector threads; + auto start = system_clock::now(); + for (int t = 0; t < thread_count; ++t) + { + threads.push_back(std::thread([&]() { + while (true) + { + int counter = ++msg_counter; + if (counter > howmany) break; + log->info("Hello logger: msg number ") << counter; + } + })); + } + + + for(auto &t:threads) + { + t.join(); + }; + + + auto delta = system_clock::now() - start; + auto delta_d = duration_cast> (delta).count(); + cout << format(int(howmany / delta_d)) << "/sec" << endl; + log->close(); +} + diff --git a/example/example.cpp b/example/example.cpp index 9e94496e..45052395 100644 --- a/example/example.cpp +++ b/example/example.cpp @@ -6,11 +6,11 @@ #include "spdlog/spdlog.h" -int main(int, char* []) +int main_(int, char* []) { namespace spd = spdlog; - + try { std::string filename = "spdlog_example"; @@ -33,12 +33,13 @@ int main(int, char* []) console->warn("This should!"); // Change format pattern to all loggers - spd::set_pattern(" **** %Y-%m-%d %H:%M:%S.%e %l **** %t"); + spd::set_pattern(" **** %Y-%m-%d %H:%M:%S.%e %l **** %v"); spd::get("console")->warn("This is another message with different format"); } catch (const spd::spdlog_ex& ex) { std::cout << "Log failed: " << ex.what() << std::endl; } + return 0; } diff --git a/include/spdlog/details/blocking_queue.h b/include/spdlog/details/blocking_queue.h index 574a5530..78d102cc 100644 --- a/include/spdlog/details/blocking_queue.h +++ b/include/spdlog/details/blocking_queue.h @@ -49,7 +49,7 @@ public: std::unique_lock ul(_mutex); if (_q.size() >= _max_size) { - if (!_item_popped_cond.wait_until(ul, clock::now() + timeout, [this]() + if (!_item_popped_cond.wait_until(ul, clock::now() + timeout,[this]() { return this->_q.size() < this->_max_size; })) @@ -59,7 +59,7 @@ public: if (_q.size() <= 1) { ul.unlock(); //So the notified thread will have better chance to accuire the lock immediatly.. - _item_pushed_cond.notify_one(); + _item_pushed_cond.notify_all(); } return true; } @@ -69,7 +69,7 @@ public: template void push(TT&& item) { - while (!push(std::forward(item), std::chrono::hours(1))); + while (!push(std::forward(item), std::chrono::seconds(10))); } // Pop a copy of the front item in the queue into the given item ref. @@ -92,7 +92,7 @@ public: if (_q.size() >= _max_size - 1) { ul.unlock(); //So the notified thread will have better chance to accuire the lock immediatly.. - _item_popped_cond.notify_one(); + _item_popped_cond.notify_all(); } return true; } diff --git a/include/spdlog/details/logger_impl.h b/include/spdlog/details/logger_impl.h index 53e7d59f..2deadd3a 100644 --- a/include/spdlog/details/logger_impl.h +++ b/include/spdlog/details/logger_impl.h @@ -22,6 +22,10 @@ inline spdlog::logger::logger(const std::string& logger_name, const It& begin, c {} +inline spdlog::logger::logger(const std::string& logger_name, spdlog::sink_ptr single_sink) :logger(logger_name, { single_sink }) +{} + + inline void spdlog::logger::set_formatter(spdlog::formatter_ptr msg_formatter) { _formatter = msg_formatter; @@ -108,9 +112,11 @@ inline bool spdlog::logger::should_log(spdlog::level::level_enum msg_level) cons return msg_level >= _level.load(); } -inline void spdlog::logger::stop_logging() +inline void spdlog::logger::close() { set_level(level::OFF); + for (auto &sink : _sinks) + sink->close(); } diff --git a/include/spdlog/details/pattern_formatter_impl.h b/include/spdlog/details/pattern_formatter_impl.h index 949ecbfe..3ae6a307 100644 --- a/include/spdlog/details/pattern_formatter_impl.h +++ b/include/spdlog/details/pattern_formatter_impl.h @@ -4,6 +4,7 @@ #include #include #include +#include #include "../formatter.h" #include "./log_msg.h" @@ -301,8 +302,17 @@ private: }; - +//Thread id class t_formatter :public flag_formatter +{ + void format(details::log_msg& msg) override + { + msg.formatted << std::this_thread::get_id(); + } +}; + + +class v_formatter :public flag_formatter { void format(details::log_msg& msg) override { @@ -343,7 +353,7 @@ private: }; // Full info formatter -// pattern: [%Y-%m-%d %H:%M:%S.%e] [%n] [%l] %t +// pattern: [%Y-%m-%d %H:%M:%S.%e] [%n] [%l] %v class full_formatter :public flag_formatter { void format(details::log_msg& msg) override @@ -428,6 +438,10 @@ inline void spdlog::pattern_formatter::handle_flag(char flag) _formatters.push_back(std::unique_ptr(new details::t_formatter())); break; + case('v') : + _formatters.push_back(std::unique_ptr(new details::v_formatter())); + break; + case('a') : _formatters.push_back(std::unique_ptr(new details::a_formatter())); break; diff --git a/include/spdlog/details/registry.h b/include/spdlog/details/registry.h index ffdffff9..c99f52d6 100644 --- a/include/spdlog/details/registry.h +++ b/include/spdlog/details/registry.h @@ -77,12 +77,12 @@ public: } - void stop_all() + void close_all() { std::lock_guard lock(_mutex); _level = level::OFF; for (auto& l : _loggers) - l.second->stop_logging(); + l.second->close(); } diff --git a/include/spdlog/details/spdlog_impl.h b/include/spdlog/details/spdlog_impl.h index 3a088ba4..84264465 100644 --- a/include/spdlog/details/spdlog_impl.h +++ b/include/spdlog/details/spdlog_impl.h @@ -95,7 +95,7 @@ inline void spdlog::set_level(level::level_enum log_level) return details::registry::instance().set_level(log_level); } -inline void spdlog::stop() +inline void spdlog::close() { - return details::registry::instance().stop_all(); + return details::registry::instance().close_all(); } diff --git a/include/spdlog/logger.h b/include/spdlog/logger.h index 2d54457b..bda7651f 100644 --- a/include/spdlog/logger.h +++ b/include/spdlog/logger.h @@ -24,6 +24,7 @@ class logger { public: + logger(const std::string& logger_name, sink_ptr single_sink); logger(const std::string& name, sinks_init_list); template logger(const std::string& name, const It& begin, const It& end); @@ -42,7 +43,7 @@ public: const std::string& name() const; bool should_log(level::level_enum) const; - void stop_logging(); + void close(); template details::line_logger log(level::level_enum lvl, const Args&... args); template details::line_logger log(const Args&... args); diff --git a/include/spdlog/sinks/async_sink.h b/include/spdlog/sinks/async_sink.h index 35a8b6e0..7af9d75a 100644 --- a/include/spdlog/sinks/async_sink.h +++ b/include/spdlog/sinks/async_sink.h @@ -33,6 +33,9 @@ public: //Wait to remaining items (if any) in the queue to be written and shutdown void shutdown(const std::chrono::milliseconds& timeout); + void close() override; + + protected: void _sink_it(const details::log_msg& msg) override; @@ -123,6 +126,11 @@ inline void spdlog::sinks::async_sink::shutdown(const std::chrono::milliseconds& _shutdown(); } +inline void spdlog::sinks::async_sink::close() +{ + _shutdown(); +} + inline void spdlog::sinks::async_sink::_shutdown() { @@ -133,5 +141,8 @@ inline void spdlog::sinks::async_sink::_shutdown() if (_back_thread.joinable()) _back_thread.join(); } + + for (auto &s : _sinks) + s->close(); } diff --git a/include/spdlog/sinks/file_sinks.h b/include/spdlog/sinks/file_sinks.h index 49b0ea44..2d631d45 100644 --- a/include/spdlog/sinks/file_sinks.h +++ b/include/spdlog/sinks/file_sinks.h @@ -28,6 +28,10 @@ public: { _file_helper.open(filename); } + void close() override + { + _file_helper.close(); + } protected: void _sink_it(const details::log_msg& msg) override { @@ -60,6 +64,11 @@ public: _file_helper.open(calc_filename(_base_filename, 0, _extension)); } + void close() override + { + _file_helper.close(); + } + protected: void _sink_it(const details::log_msg& msg) override { @@ -140,6 +149,11 @@ public: _file_helper.open(calc_filename(_base_filename, _extension)); } + void close() override + { + _file_helper.close(); + } + protected: void _sink_it(const details::log_msg& msg) override { diff --git a/include/spdlog/sinks/null_sink.h b/include/spdlog/sinks/null_sink.h index 776425e6..c75c3884 100644 --- a/include/spdlog/sinks/null_sink.h +++ b/include/spdlog/sinks/null_sink.h @@ -13,6 +13,9 @@ class null_sink : public base_sink protected: void _sink_it(const details::log_msg&) override {} + + void close() override + {} }; typedef null_sink null_sink_st; diff --git a/include/spdlog/sinks/ostream_sink.h b/include/spdlog/sinks/ostream_sink.h index 5fa62683..4445316b 100644 --- a/include/spdlog/sinks/ostream_sink.h +++ b/include/spdlog/sinks/ostream_sink.h @@ -21,6 +21,9 @@ public: virtual ~ostream_sink() = default; + void close() override + {} + protected: virtual void _sink_it(const details::log_msg& msg) override { diff --git a/include/spdlog/sinks/sink.h b/include/spdlog/sinks/sink.h index 9d4a2cc5..36107398 100644 --- a/include/spdlog/sinks/sink.h +++ b/include/spdlog/sinks/sink.h @@ -11,6 +11,7 @@ class sink public: virtual ~sink() {} virtual void log(const details::log_msg& msg) = 0; + virtual void close() = 0; }; } } diff --git a/include/spdlog/sinks/stdout_sinks.h b/include/spdlog/sinks/stdout_sinks.h index 19b0f908..29e38ec6 100644 --- a/include/spdlog/sinks/stdout_sinks.h +++ b/include/spdlog/sinks/stdout_sinks.h @@ -15,6 +15,7 @@ class stdout_sink : public ostream_sink { public: stdout_sink() : ostream_sink(std::cout) {} + }; typedef stdout_sink stdout_sink_st; diff --git a/include/spdlog/spdlog.h b/include/spdlog/spdlog.h index 401a6e04..2680a703 100644 --- a/include/spdlog/spdlog.h +++ b/include/spdlog/spdlog.h @@ -30,7 +30,7 @@ std::shared_ptr get(const std::string& name); // Set global formatting -// spdlog::set_pattern("%Y-%m-%d %H:%M:%S.%e %l : %t"); +// spdlog::set_pattern("%Y-%m-%d %H:%M:%S.%e %l : %v"); void set_pattern(const std::string& format_string); @@ -74,8 +74,8 @@ std::shared_ptr create(const std::string& logger_name, const Arg // Set global formatter object void set_formatter(formatter_ptr f); -//Stop all loggers -void stop(); +// Close all loggers and stop logging +void close(); //