From 6a93f98a1f479affc26784c84234139e3d5e58f3 Mon Sep 17 00:00:00 2001 From: gabime Date: Sun, 20 May 2018 18:01:27 +0300 Subject: [PATCH] async test --- README.md | 2 +- bench/spdlog-async.cpp | 4 +- example/bench.cpp | 2 +- example/example.cpp | 2 +- tests/test_async.cpp | 140 +++++++++++++++++++++++++++++++++++++++++ 5 files changed, 145 insertions(+), 5 deletions(-) create mode 100644 tests/test_async.cpp diff --git a/README.md b/README.md index 6625b561..e6ef00af 100644 --- a/README.md +++ b/README.md @@ -170,7 +170,7 @@ int main(int, char*[]) void async_example() { - size_t q_size = 4096; //queue size must be power of 2 + size_t q_size = 4096; spd::set_async_mode(q_size); auto async_file = spd::daily_logger_st("async_file_logger", "logs/async_log.txt"); for (int i = 0; i < 100; ++i) diff --git a/bench/spdlog-async.cpp b/bench/spdlog-async.cpp index e8b70009..0215c376 100644 --- a/bench/spdlog-async.cpp +++ b/bench/spdlog-async.cpp @@ -25,8 +25,8 @@ int main(int argc, char *argv[]) int howmany = 1000000; - spdlog::set_async_mode(1048576); - auto logger = spdlog::create("file_logger", "logs/spdlog-bench-async.log", false); + spdlog::set_async_mode(1000000); + auto logger = spdlog::create("file_logger", "logs/spdlog-bench-async.log", true); logger->set_pattern("[%Y-%m-%d %T.%F]: %L %t %v"); std::cout << "To stop, press " << std::endl; diff --git a/example/bench.cpp b/example/bench.cpp index 64095378..ebb70db0 100644 --- a/example/bench.cpp +++ b/example/bench.cpp @@ -45,7 +45,7 @@ int main(int argc, char *argv[]) threads = atoi(argv[2]); if (argc > 3) queue_size = atoi(argv[3]); - + cout << "*******************************************************************************\n"; cout << "Single thread, " << format(howmany) << " iterations" << endl; cout << "*******************************************************************************\n"; diff --git a/example/example.cpp b/example/example.cpp index 6144c065..227eac75 100644 --- a/example/example.cpp +++ b/example/example.cpp @@ -105,7 +105,7 @@ int main(int, char *[]) void async_example() { - size_t q_size = 4096; // queue size must be power of 2 + size_t q_size = 4096; spdlog::set_async_mode(q_size); auto async_file = spd::daily_logger_st("async_file_logger", "logs/async_log.txt"); for (int i = 0; i < 100; ++i) diff --git a/tests/test_async.cpp b/tests/test_async.cpp new file mode 100644 index 00000000..2bb2305b --- /dev/null +++ b/tests/test_async.cpp @@ -0,0 +1,140 @@ +#include "includes.h" +#include "test_sink.h" + +template +std::string log_info(const T &what, spdlog::level::level_enum logger_level = spdlog::level::info) +{ + + std::ostringstream oss; + auto oss_sink = std::make_shared(oss); + + spdlog::logger oss_logger("oss", oss_sink); + oss_logger.set_level(logger_level); + oss_logger.set_pattern("%v"); + oss_logger.info(what); + + return oss.str().substr(0, oss.str().length() - strlen(spdlog::details::os::default_eol)); +} + +TEST_CASE("basic async test ", "[async]") +{ + auto test_sink = std::make_shared(); + size_t queue_size = 128; + size_t messages = 256; + auto logger = spdlog::create_async("as", test_sink, 128, spdlog::async_overflow_policy::block_retry); + for (size_t i = 0; i < messages; i++) + { + logger->info("Hello message #{}", i); + } + + // the dtor wait for all messages in the queue to get processed + logger.reset(); + spdlog::drop("as"); + REQUIRE(test_sink->msg_counter() == messages); + REQUIRE(test_sink->flushed_msg_counter() == messages); +} + +TEST_CASE("discard policy ", "[async]") +{ + auto test_sink = std::make_shared(); + size_t queue_size = 2; + size_t messages = 1024; + spdlog::drop("as"); + auto logger = spdlog::create_async("as", test_sink, queue_size, spdlog::async_overflow_policy::discard_log_msg); + for (size_t i = 0; i < messages; i++) + { + logger->info("Hello message #{}", i); + } + + // the dtor wait for all messages in the queue to get processed + logger.reset(); + spdlog::drop("as"); + REQUIRE(test_sink->msg_counter() < messages); + REQUIRE(test_sink->flushed_msg_counter() < messages); +} + + +TEST_CASE("flush", "[async]") +{ + auto test_sink = std::make_shared(); + size_t queue_size = 256; + size_t messages = 256; + spdlog::drop("as"); + auto logger = std::make_shared("as", test_sink, queue_size); + for (size_t i = 0; i < messages; i++) + { + logger->info("Hello message #{}", i); + } + + // the dtor wait for all messages in the queue to get processed + logger->flush(); + std::this_thread::sleep_for(std::chrono::milliseconds(250)); + REQUIRE(test_sink->msg_counter() == messages); + REQUIRE(test_sink->flushed_msg_counter() == messages); + + + REQUIRE(test_sink->flushed_msg_counter() == messages); + +} + +TEST_CASE("multi threads", "[async]") +{ + auto test_sink = std::make_shared(); + size_t queue_size = 128; + size_t messages = 256; + size_t n_threads = 10; + auto logger = std::make_shared("as", test_sink, queue_size); + + std::vector threads; + for (size_t i = 0; i < n_threads; i++) + { + threads.emplace_back([logger, messages] { + for (size_t j = 0; j < messages; j++) + { + logger->info("Hello message #{}", j); + } + }); + } + + for (auto &t : threads) + { + t.join(); + } + + // the dtor wait for all messages in the queue to get processed + logger.reset(); + REQUIRE(test_sink->msg_counter() == messages * n_threads); + REQUIRE(test_sink->flushed_msg_counter() == messages * n_threads); +} + + +TEST_CASE("to_file", "[async]") +{ + + prepare_logdir(); + size_t queue_size = 512; + size_t messages = 512; + size_t n_threads = 4; + auto file_sink = std::make_shared("logs/async_test.log", true); + auto logger = spdlog::create_async("as", file_sink, queue_size); + std::vector threads; + for (size_t i = 0; i < n_threads; i++) + { + threads.emplace_back([logger, messages] { + for (size_t j = 0; j < messages; j++) + { + logger->info("Hello message #{}", j); + } + }); + } + + for (auto &t : threads) + { + t.join(); + } + logger.reset(); + spdlog::drop("as"); + REQUIRE(count_lines("logs/async_test.log") == messages * n_threads); +} + +