spdlog/bench/latency.cpp

170 lines
7.5 KiB
C++
Raw Normal View History

2018-07-09 14:06:15 -04:00
//
// Copyright(c) 2018 Gabi Melman.
// Distributed under the MIT License (http://opensource.org/licenses/MIT)
//
//
// latency.cpp : spdlog latency benchmarks
//
2018-10-11 20:04:55 -04:00
2018-10-24 15:31:50 -04:00
#include "benchmark/benchmark.h"
2018-10-11 20:04:55 -04:00
#include "spdlog/spdlog.h"
2018-07-09 14:06:15 -04:00
#include "spdlog/async.h"
#include "spdlog/sinks/basic_file_sink.h"
#include "spdlog/sinks/daily_file_sink.h"
#include "spdlog/sinks/null_sink.h"
#include "spdlog/sinks/rotating_file_sink.h"
2018-10-26 09:34:14 -04:00
void prepare_logdir()
{
2018-10-29 18:08:49 -04:00
spdlog::info("Preparing latency_logs directory..");
2018-10-26 09:34:14 -04:00
#ifdef _WIN32
2018-10-29 18:08:49 -04:00
system("if not exist logs mkdir latency_logs");
2018-10-26 09:34:14 -04:00
system("del /F /Q logs\\*");
#else
2018-10-29 18:08:49 -04:00
auto rv = system("mkdir -p latency_logs");
2018-10-26 09:34:14 -04:00
if (rv != 0)
{
2018-10-29 18:08:49 -04:00
throw std::runtime_error("Failed to mkdir -p latency_logs");
2018-10-26 09:34:14 -04:00
}
2018-10-29 18:08:49 -04:00
rv = system("rm -f latency_logs/*");
2018-10-26 09:34:14 -04:00
if (rv != 0)
{
2018-10-29 18:08:49 -04:00
throw std::runtime_error("Failed to rm -f latency_logs/*");
2018-10-26 09:34:14 -04:00
}
#endif
}
2018-10-29 18:08:49 -04:00
void bench_c_string(benchmark::State &state, std::shared_ptr<spdlog::logger> logger)
2018-07-09 14:06:15 -04:00
{
2018-10-24 15:31:50 -04:00
const char *msg = "Lorem ipsum dolor sit amet, consectetur adipiscing elit. Vestibulum pharetra metus cursus "
"lacus placerat congue. Nulla egestas, mauris a tincidunt tempus, enim lectus volutpat mi, eu consequat sem "
"libero nec massa. In dapibus ipsum a diam rhoncus gravida. Etiam non dapibus eros. Donec fringilla dui sed "
"augue pretium, nec scelerisque est maximus. Nullam convallis, sem nec blandit maximus, nisi turpis ornare "
"nisl, sit amet volutpat neque massa eu odio. Maecenas malesuada quam ex, posuere congue nibh turpis duis.";
2018-07-09 14:06:15 -04:00
2018-10-24 15:31:50 -04:00
for (auto _ : state)
2018-07-09 14:06:15 -04:00
{
2018-10-24 15:31:50 -04:00
logger->info(msg);
2018-07-09 14:06:15 -04:00
}
}
2018-10-29 18:08:49 -04:00
void bench_logger(benchmark::State &state, std::shared_ptr<spdlog::logger> logger)
2018-07-09 14:06:15 -04:00
{
2018-10-24 15:31:50 -04:00
int i = 0;
for (auto _ : state)
2018-07-09 14:06:15 -04:00
{
2018-10-26 09:34:14 -04:00
logger->info("Hello logger: msg number {}...............", ++i);
2018-07-09 14:06:15 -04:00
}
}
2018-11-12 04:07:51 -05:00
void bench_disabled_macro(benchmark::State &state, std::shared_ptr<spdlog::logger> logger)
{
int i = 0;
2018-11-12 05:01:10 -05:00
benchmark::DoNotOptimize(i); // prevent unused warnings
benchmark::DoNotOptimize(logger); // prevent unused warnings
2018-11-12 04:07:51 -05:00
for (auto _ : state)
{
SPDLOG_LOGGER_DEBUG(logger, "Hello logger: msg number {}...............", i++);
SPDLOG_DEBUG("Hello logger: msg number {}...............", i++);
}
}
2018-10-24 15:31:50 -04:00
int main(int argc, char *argv[])
2018-07-09 14:06:15 -04:00
{
2019-01-10 09:31:06 -05:00
2018-10-26 09:34:14 -04:00
using spdlog::sinks::basic_file_sink_mt;
2018-10-29 18:08:49 -04:00
using spdlog::sinks::basic_file_sink_st;
using spdlog::sinks::null_sink_mt;
using spdlog::sinks::null_sink_st;
2018-10-24 15:31:50 -04:00
2018-10-26 09:34:14 -04:00
size_t file_size = 30 * 1024 * 1024;
size_t rotating_files = 5;
2018-10-29 18:08:49 -04:00
int n_threads = benchmark::CPUInfo::Get().num_cpus;
2018-10-26 09:34:14 -04:00
prepare_logdir();
2018-11-12 04:07:51 -05:00
// disabled loggers
2018-10-29 18:08:49 -04:00
auto disabled_logger = std::make_shared<spdlog::logger>("bench", std::make_shared<null_sink_mt>());
disabled_logger->set_level(spdlog::level::off);
2018-11-12 04:07:51 -05:00
benchmark::RegisterBenchmark("disabled-at-compile-time", bench_disabled_macro, disabled_logger);
benchmark::RegisterBenchmark("disabled-at-runtime", bench_logger, disabled_logger);
2019-08-25 16:55:35 -04:00
// with backtrace of 64
auto tracing_disabled_logger = std::make_shared<spdlog::logger>("bench", std::make_shared<null_sink_mt>());
tracing_disabled_logger->enable_backtrace(64);
benchmark::RegisterBenchmark("disabled-at-runtime/backtrace", bench_logger, tracing_disabled_logger);
2018-10-29 18:08:49 -04:00
auto null_logger_st = std::make_shared<spdlog::logger>("bench", std::make_shared<null_sink_st>());
2018-11-12 04:07:51 -05:00
benchmark::RegisterBenchmark("null_sink_st (500_bytes c_str)", bench_c_string, std::move(null_logger_st));
2018-10-29 18:08:49 -04:00
benchmark::RegisterBenchmark("null_sink_st", bench_logger, null_logger_st);
2019-08-25 16:55:35 -04:00
// with backtrace of 64
auto tracing_null_logger_st = std::make_shared<spdlog::logger>("bench", std::make_shared<null_sink_st>());
tracing_null_logger_st->enable_backtrace(64);
benchmark::RegisterBenchmark("null_sink_st/backtrace", bench_logger, tracing_null_logger_st);
2018-10-26 09:34:14 -04:00
// basic_st
2018-10-29 18:08:49 -04:00
auto basic_st = spdlog::basic_logger_st("basic_st", "latency_logs/basic_st.log", true);
benchmark::RegisterBenchmark("basic_st", bench_logger, std::move(basic_st))->UseRealTime();
2018-10-26 09:34:14 -04:00
spdlog::drop("basic_st");
2019-08-25 16:55:35 -04:00
// with backtrace of 64
auto tracing_basic_st = spdlog::basic_logger_st("tracing_basic_st", "latency_logs/tracing_basic_st.log", true);
tracing_basic_st->enable_backtrace(64);
benchmark::RegisterBenchmark("basic_st/backtrace", bench_logger, std::move(tracing_basic_st))->UseRealTime();
spdlog::drop("tracing_basic_st");
2018-10-26 09:34:14 -04:00
// rotating st
2018-10-29 18:08:49 -04:00
auto rotating_st = spdlog::rotating_logger_st("rotating_st", "latency_logs/rotating_st.log", file_size, rotating_files);
benchmark::RegisterBenchmark("rotating_st", bench_logger, std::move(rotating_st))->UseRealTime();
2018-10-26 09:34:14 -04:00
spdlog::drop("rotating_st");
2019-08-25 16:55:35 -04:00
// with backtrace of 64
auto tracing_rotating_st =
spdlog::rotating_logger_st("tracing_rotating_st", "latency_logs/tracing_rotating_st.log", file_size, rotating_files);
2019-08-26 19:35:00 -04:00
benchmark::RegisterBenchmark("rotating_st/backtrace", bench_logger, std::move(tracing_rotating_st))->UseRealTime();
2019-08-25 16:55:35 -04:00
spdlog::drop("tracing_rotating_st");
2018-10-26 09:34:14 -04:00
// daily st
2018-10-29 18:08:49 -04:00
auto daily_st = spdlog::daily_logger_mt("daily_st", "latency_logs/daily_st.log");
benchmark::RegisterBenchmark("daily_st", bench_logger, std::move(daily_st))->UseRealTime();
2018-10-26 09:34:14 -04:00
spdlog::drop("daily_st");
2019-08-25 16:55:35 -04:00
auto tracing_daily_st = spdlog::daily_logger_mt("tracing_daily_st", "latency_logs/daily_st.log");
2019-08-26 19:35:00 -04:00
benchmark::RegisterBenchmark("daily_st/backtrace", bench_logger, std::move(tracing_daily_st))->UseRealTime();
2019-08-25 16:55:35 -04:00
spdlog::drop("tracing_daily_st");
2018-10-26 09:34:14 -04:00
2019-08-25 16:55:35 -04:00
//
// Multi threaded bench, 10 loggers using same logger concurrently
//
2018-10-26 09:34:14 -04:00
auto null_logger_mt = std::make_shared<spdlog::logger>("bench", std::make_shared<null_sink_mt>());
2018-10-29 18:08:49 -04:00
benchmark::RegisterBenchmark("null_sink_mt", bench_logger, null_logger_mt)->Threads(n_threads)->UseRealTime();
2018-10-26 09:34:14 -04:00
// basic_mt
2018-10-29 18:08:49 -04:00
auto basic_mt = spdlog::basic_logger_mt("basic_mt", "latency_logs/basic_mt.log", true);
benchmark::RegisterBenchmark("basic_mt", bench_logger, std::move(basic_mt))->Threads(n_threads)->UseRealTime();
2018-10-26 09:34:14 -04:00
spdlog::drop("basic_mt");
// rotating mt
2018-10-29 18:08:49 -04:00
auto rotating_mt = spdlog::rotating_logger_mt("rotating_mt", "latency_logs/rotating_mt.log", file_size, rotating_files);
benchmark::RegisterBenchmark("rotating_mt", bench_logger, std::move(rotating_mt))->Threads(n_threads)->UseRealTime();
2018-10-26 09:34:14 -04:00
spdlog::drop("rotating_mt");
// daily mt
2018-10-29 18:08:49 -04:00
auto daily_mt = spdlog::daily_logger_mt("daily_mt", "latency_logs/daily_mt.log");
benchmark::RegisterBenchmark("daily_mt", bench_logger, std::move(daily_mt))->Threads(n_threads)->UseRealTime();
2018-10-26 09:34:14 -04:00
spdlog::drop("daily_mt");
2018-10-24 15:31:50 -04:00
2018-10-29 18:08:49 -04:00
// async
auto queue_size = 1024 * 1024 * 3;
auto tp = std::make_shared<spdlog::details::thread_pool>(queue_size, 1);
auto async_logger = std::make_shared<spdlog::async_logger>(
"async_logger", std::make_shared<null_sink_mt>(), std::move(tp), spdlog::async_overflow_policy::overrun_oldest);
benchmark::RegisterBenchmark("async_logger", bench_logger, async_logger)->Threads(n_threads)->UseRealTime();
2019-08-26 19:35:00 -04:00
auto async_logger_tracing = std::make_shared<spdlog::async_logger>(
2019-08-27 13:22:07 -04:00
"async_logger_tracing", std::make_shared<null_sink_mt>(), std::move(tp), spdlog::async_overflow_policy::overrun_oldest);
2019-08-26 19:35:00 -04:00
async_logger_tracing->enable_backtrace(32);
benchmark::RegisterBenchmark("async_logger/tracing", bench_logger, async_logger_tracing)->Threads(n_threads)->UseRealTime();
2018-10-24 15:31:50 -04:00
benchmark::Initialize(&argc, argv);
benchmark::RunSpecifiedBenchmarks();
2018-07-09 14:06:15 -04:00
}