update and change how we build with spdlog

This commit is contained in:
Benjamin Sergeant
2019-09-29 11:13:24 -07:00
parent 0ee675e554
commit 681390f22f
156 changed files with 28175 additions and 19817 deletions

View File

@ -1,28 +1,8 @@
# *************************************************************************/
# * Copyright (c) 2015 Ruslan Baratov. */
# * */
# * Permission is hereby granted, free of charge, to any person obtaining */
# * a copy of this software and associated documentation files (the */
# * "Software"), to deal in the Software without restriction, including */
# * without limitation the rights to use, copy, modify, merge, publish, */
# * distribute, sublicense, and/or sell copies of the Software, and to */
# * permit persons to whom the Software is furnished to do so, subject to */
# * the following conditions: */
# * */
# * The above copyright notice and this permission notice shall be */
# * included in all copies or substantial portions of the Software. */
# * */
# * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, */
# * EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF */
# * MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT.*/
# * IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY */
# * CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION OF CONTRACT, */
# * TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION WITH THE */
# * SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. */
# *************************************************************************/
# Copyright(c) 2019 spdlog authors
# Distributed under the MIT License (http://opensource.org/licenses/MIT)
cmake_minimum_required(VERSION 3.1)
project(SpdlogBench CXX)
project(spdlog_bench CXX)
if(NOT TARGET spdlog)
# Stand-alone build
@ -33,16 +13,16 @@ find_package(Threads REQUIRED)
find_package(benchmark CONFIG REQUIRED)
add_executable(bench bench.cpp)
target_link_libraries(bench PRIVATE spdlog::spdlog Threads::Threads)
spdlog_enable_warnings(bench)
target_link_libraries(bench PRIVATE spdlog::spdlog)
add_executable(async_bench async_bench.cpp)
target_link_libraries(async_bench PRIVATE spdlog::spdlog Threads::Threads)
target_link_libraries(async_bench PRIVATE spdlog::spdlog)
add_executable(latency latency.cpp)
target_link_libraries(latency PRIVATE benchmark::benchmark spdlog::spdlog Threads::Threads)
target_link_libraries(latency PRIVATE benchmark::benchmark spdlog::spdlog)
add_executable(formatter-bench formatter-bench.cpp)
target_link_libraries(formatter-bench PRIVATE benchmark::benchmark spdlog::spdlog Threads::Threads)
target_link_libraries(formatter-bench PRIVATE benchmark::benchmark spdlog::spdlog)
file(MAKE_DIRECTORY "${CMAKE_CURRENT_BINARY_DIR}/logs")

View File

@ -26,6 +26,11 @@ using namespace utils;
void bench_mt(int howmany, std::shared_ptr<spdlog::logger> log, int thread_count);
#ifdef _MSC_VER
#pragma warning(push)
#pragma warning(disable : 4996) // disable fopen warning under msvc
#endif // _MSC_VER
int count_lines(const char *filename)
{
int counter = 0;
@ -40,19 +45,36 @@ int count_lines(const char *filename)
return counter;
}
void verify_file(const char *filename, int expected_count)
{
spdlog::info("Verifying {} to contain {:n} line..", filename, expected_count);
auto count = count_lines(filename);
if (count != expected_count)
{
spdlog::error("Test failed. {} has {:n} lines instead of {:n}", filename, count, expected_count);
exit(1);
}
spdlog::info("Line count OK ({:n})\n", count);
}
#ifdef _MSC_VER
#pragma warning(pop)
#endif
int main(int argc, char *argv[])
{
int howmany = 1000000;
int queue_size = howmany + 2;
int queue_size = std::min(howmany + 2, 8192);
int threads = 10;
int iters = 3;
try
{
spdlog::set_pattern("[%^%l%$] %v");
if (argc == 1)
{
spdlog::set_pattern("%v");
spdlog::info("Usage: {} <message_count> <threads> <q_size> <iterations>", argv[0]);
return 0;
}
@ -62,37 +84,54 @@ int main(int argc, char *argv[])
if (argc > 2)
threads = atoi(argv[2]);
if (argc > 3)
{
queue_size = atoi(argv[3]);
if (queue_size > 500000)
{
spdlog::error("Max queue size allowed: 500,000");
exit(1);
}
}
if (argc > 4)
iters = atoi(argv[4]);
auto slot_size = sizeof(spdlog::details::async_msg);
spdlog::info("-------------------------------------------------");
spdlog::info("Messages: {:14n}", howmany);
spdlog::info("Threads : {:14n}", threads);
spdlog::info("Queue : {:14n}", queue_size);
spdlog::info("Iters : {:>14n}", iters);
spdlog::info("Messages : {:n}", howmany);
spdlog::info("Threads : {:n}", threads);
spdlog::info("Queue : {:n} slots", queue_size);
spdlog::info("Queue memory : {:n} x {} = {:n} KB ", queue_size, slot_size, (queue_size * slot_size) / 1024);
spdlog::info("Total iters : {:n}", iters);
spdlog::info("-------------------------------------------------");
const char *filename = "logs/basic_async.log";
spdlog::info("");
spdlog::info("*********************************");
spdlog::info("Queue Overflow Policy: block");
spdlog::info("*********************************");
for (int i = 0; i < iters; i++)
{
auto tp = std::make_shared<details::thread_pool>(queue_size, 1);
auto file_sink = std::make_shared<spdlog::sinks::basic_file_sink_mt>(filename, true);
auto logger = std::make_shared<async_logger>("async_logger", std::move(file_sink), std::move(tp), async_overflow_policy::block);
bench_mt(howmany, std::move(logger), threads);
auto count = count_lines(filename);
// verify_file(filename, howmany);
}
if (count != howmany)
{
spdlog::error("Test failed. {} has {:n} lines instead of {:n}", filename, count, howmany);
exit(1);
}
else
{
spdlog::info("Line count OK ({:n})\n", count);
}
spdlog::info("");
spdlog::info("*********************************");
spdlog::info("Queue Overflow Policy: overrun");
spdlog::info("*********************************");
// do same test but discard oldest if queue is full instead of blocking
filename = "logs/basic_async-overrun.log";
for (int i = 0; i < iters; i++)
{
auto tp = std::make_shared<details::thread_pool>(queue_size, 1);
auto file_sink = std::make_shared<spdlog::sinks::basic_file_sink_mt>(filename, true);
auto logger =
std::make_shared<async_logger>("async_logger", std::move(file_sink), std::move(tp), async_overflow_policy::overrun_oldest);
bench_mt(howmany, std::move(logger), threads);
}
spdlog::shutdown();
}
@ -102,7 +141,6 @@ int main(int argc, char *argv[])
perror("Last error");
return 1;
}
return 0;
}

View File

@ -7,7 +7,6 @@
// bench.cpp : spdlog benchmarks
//
#include "spdlog/spdlog.h"
#include "spdlog/async.h"
#include "spdlog/sinks/basic_file_sink.h"
#include "spdlog/sinks/daily_file_sink.h"
#include "spdlog/sinks/null_sink.h"
@ -31,81 +30,99 @@ void bench_mt(int howmany, std::shared_ptr<spdlog::logger> log, int thread_count
void bench_default_api(int howmany, std::shared_ptr<spdlog::logger> log);
void bench_c_string(int howmany, std::shared_ptr<spdlog::logger> log);
static size_t file_size = 30 * 1024 * 1024;
static size_t rotating_files = 5;
void bench_threaded_logging(int threads, int iters)
{
spdlog::info("**************************************************************");
spdlog::info("Multi threaded: {:n} threads, {:n} messages", threads, iters);
spdlog::info("**************************************************************");
auto basic_mt = spdlog::basic_logger_mt("basic_mt", "logs/basic_mt.log", true);
bench_mt(iters, std::move(basic_mt), threads);
auto basic_mt_tracing = spdlog::basic_logger_mt("basic_mt/backtrace-on", "logs/basic_mt.log", true);
basic_mt_tracing->enable_backtrace(32);
bench_mt(iters, std::move(basic_mt_tracing), threads);
spdlog::info("");
auto rotating_mt = spdlog::rotating_logger_mt("rotating_mt", "logs/rotating_mt.log", file_size, rotating_files);
bench_mt(iters, std::move(rotating_mt), threads);
auto rotating_mt_tracing = spdlog::rotating_logger_mt("rotating_mt/backtrace-on", "logs/rotating_mt.log", file_size, rotating_files);
rotating_mt_tracing->enable_backtrace(32);
bench_mt(iters, std::move(rotating_mt_tracing), threads);
spdlog::info("");
auto daily_mt = spdlog::daily_logger_mt("daily_mt", "logs/daily_mt.log");
bench_mt(iters, std::move(daily_mt), threads);
auto daily_mt_tracing = spdlog::daily_logger_mt("daily_mt/backtrace-on", "logs/daily_mt.log");
daily_mt_tracing->enable_backtrace(32);
bench_mt(iters, std::move(daily_mt_tracing), threads);
spdlog::info("");
auto empty_logger = std::make_shared<spdlog::logger>("level-off");
empty_logger->set_level(spdlog::level::off);
bench(iters, empty_logger);
auto empty_logger_tracing = std::make_shared<spdlog::logger>("level-off/backtrace-on");
empty_logger_tracing->set_level(spdlog::level::off);
empty_logger_tracing->enable_backtrace(32);
bench(iters, empty_logger_tracing);
}
void bench_single_threaded(int iters)
{
spdlog::info("**************************************************************");
spdlog::info("Single threaded: {:n} messages", iters);
spdlog::info("**************************************************************");
auto basic_st = spdlog::basic_logger_st("basic_st", "logs/basic_st.log", true);
bench(iters, std::move(basic_st));
auto basic_st_tracing = spdlog::basic_logger_st("basic_st/backtrace-on", "logs/basic_st.log", true);
bench(iters, std::move(basic_st_tracing));
spdlog::info("");
auto rotating_st = spdlog::rotating_logger_st("rotating_st", "logs/rotating_st.log", file_size, rotating_files);
bench(iters, std::move(rotating_st));
auto rotating_st_tracing = spdlog::rotating_logger_st("rotating_st/backtrace-on", "logs/rotating_st.log", file_size, rotating_files);
rotating_st_tracing->enable_backtrace(32);
bench(iters, std::move(rotating_st_tracing));
spdlog::info("");
auto daily_st = spdlog::daily_logger_st("daily_st", "logs/daily_st.log");
bench(iters, std::move(daily_st));
auto daily_st_tracing = spdlog::daily_logger_st("daily_st/backtrace-on", "logs/daily_st.log");
daily_st_tracing->enable_backtrace(32);
bench(iters, std::move(daily_st_tracing));
spdlog::info("");
auto empty_logger = std::make_shared<spdlog::logger>("level-off");
empty_logger->set_level(spdlog::level::off);
bench(iters, empty_logger);
auto empty_logger_tracing = std::make_shared<spdlog::logger>("level-off/backtrace-on");
empty_logger_tracing->set_level(spdlog::level::off);
empty_logger_tracing->enable_backtrace(32);
bench(iters, empty_logger_tracing);
}
int main(int argc, char *argv[])
{
spdlog::set_automatic_registration(false);
spdlog::default_logger()->set_pattern("[%^%l%$] %v");
int howmany = 1000000;
int queue_size = howmany + 2;
int threads = 10;
size_t file_size = 30 * 1024 * 1024;
size_t rotating_files = 5;
int iters = 250000;
int threads = 4;
try
{
if (argc > 1)
howmany = atoi(argv[1]);
iters = atoi(argv[1]);
if (argc > 2)
threads = atoi(argv[2]);
if (argc > 3)
queue_size = atoi(argv[3]);
spdlog::info("**************************************************************");
spdlog::info("Single thread, {:n} iterations", howmany);
spdlog::info("**************************************************************");
auto basic_st = spdlog::basic_logger_st("basic_st", "logs/basic_st.log", true);
bench(howmany, std::move(basic_st));
basic_st.reset();
auto rotating_st = spdlog::rotating_logger_st("rotating_st", "logs/rotating_st.log", file_size, rotating_files);
bench(howmany, std::move(rotating_st));
auto daily_st = spdlog::daily_logger_st("daily_st", "logs/daily_st.log");
bench(howmany, std::move(daily_st));
bench(howmany, spdlog::create<null_sink_st>("null_st"));
spdlog::info("**************************************************************");
spdlog::info("C-string (400 bytes). Single thread, {:n} iterations", howmany);
spdlog::info("**************************************************************");
basic_st = spdlog::basic_logger_st("basic_st", "logs/basic_cs.log", true);
bench_c_string(howmany, std::move(basic_st));
rotating_st = spdlog::rotating_logger_st("rotating_st", "logs/rotating_cs.log", file_size, rotating_files);
bench_c_string(howmany, std::move(rotating_st));
daily_st = spdlog::daily_logger_st("daily_st", "logs/daily_cs.log");
bench_c_string(howmany, std::move(daily_st));
bench_c_string(howmany, spdlog::create<null_sink_st>("null_st"));
spdlog::info("**************************************************************");
spdlog::info("{:n} threads sharing same logger, {:n} iterations", threads, howmany);
spdlog::info("**************************************************************");
auto basic_mt = spdlog::basic_logger_mt("basic_mt", "logs/basic_mt.log", true);
bench_mt(howmany, std::move(basic_mt), threads);
auto rotating_mt = spdlog::rotating_logger_mt("rotating_mt", "logs/rotating_mt.log", file_size, rotating_files);
bench_mt(howmany, std::move(rotating_mt), threads);
auto daily_mt = spdlog::daily_logger_mt("daily_mt", "logs/daily_mt.log");
bench_mt(howmany, std::move(daily_mt), threads);
bench_mt(howmany, spdlog::create<null_sink_mt>("null_mt"), threads);
spdlog::info("**************************************************************");
spdlog::info("Asyncronous.. {:n} threads sharing same logger, {:n} iterations", threads, howmany);
spdlog::info("**************************************************************");
for (int i = 0; i < 3; ++i)
{
spdlog::init_thread_pool(static_cast<size_t>(queue_size), 1);
auto as = spdlog::basic_logger_mt<spdlog::async_factory>("async", "logs/basic_async.log", true);
bench_mt(howmany, std::move(as), threads);
}
bench_single_threaded(iters);
bench_threaded_logging(1, iters);
bench_threaded_logging(threads, iters);
}
catch (std::exception &ex)
{
@ -127,7 +144,7 @@ void bench(int howmany, std::shared_ptr<spdlog::logger> log)
auto delta = high_resolution_clock::now() - start;
auto delta_d = duration_cast<duration<double>>(delta).count();
spdlog::info("{:<16} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
spdlog::info("{:<30} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
spdlog::drop(log->name());
}
@ -153,7 +170,7 @@ void bench_mt(int howmany, std::shared_ptr<spdlog::logger> log, int thread_count
auto delta = high_resolution_clock::now() - start;
auto delta_d = duration_cast<duration<double>>(delta).count();
spdlog::info("{:<16} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
spdlog::info("{:<30} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
spdlog::drop(log->name());
}
@ -172,7 +189,7 @@ void bench_default_api(int howmany, std::shared_ptr<spdlog::logger> log)
auto delta_d = duration_cast<duration<double>>(delta).count();
spdlog::drop(log->name());
spdlog::set_default_logger(std::move(orig_default));
spdlog::info("{:<16} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
spdlog::info("{:<30} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
}
void bench_c_string(int howmany, std::shared_ptr<spdlog::logger> log)
@ -195,5 +212,5 @@ void bench_c_string(int howmany, std::shared_ptr<spdlog::logger> log)
auto delta_d = duration_cast<duration<double>>(delta).count();
spdlog::drop(log->name());
spdlog::set_default_logger(std::move(orig_default));
spdlog::info("{:<16} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
spdlog::info("{:<30} Elapsed: {:0.2f} secs {:>16n}/sec", log->name(), delta_d, int(howmany / delta_d));
}

View File

@ -8,27 +8,15 @@
#include "spdlog/spdlog.h"
#include "spdlog/details/pattern_formatter.h"
void bench_scoped_pad(benchmark::State &state, size_t wrapped_size, spdlog::details::padding_info padinfo)
{
fmt::memory_buffer dest;
for (auto _ : state)
{
{
spdlog::details::scoped_pad p(wrapped_size, padinfo, dest);
benchmark::DoNotOptimize(p);
dest.clear();
}
}
}
void bench_formatter(benchmark::State &state, std::string pattern)
{
auto formatter = spdlog::details::make_unique<spdlog::pattern_formatter>(pattern);
fmt::memory_buffer dest;
spdlog::memory_buf_t dest;
std::string logger_name = "logger-name";
const char *text = "Hello. This is some message with length of 80 ";
spdlog::details::log_msg msg(&logger_name, spdlog::level::info, text);
spdlog::source_loc source_loc{"a/b/c/d/myfile.cpp", 123, "some_func()"};
spdlog::details::log_msg msg(source_loc, logger_name, spdlog::level::info, text);
for (auto _ : state)
{
@ -41,7 +29,7 @@ void bench_formatter(benchmark::State &state, std::string pattern)
void bench_formatters()
{
// basic patterns(single flag)
std::string all_flags = "+vtPnlLaAbBcCYDmdHIMSefFprRTXzEi%";
std::string all_flags = "+vtPnlLaAbBcCYDmdHIMSefFprRTXzEisg@luioO%";
std::vector<std::string> basic_patterns;
for (auto &flag : all_flags)
{

View File

@ -90,29 +90,50 @@ int main(int argc, char *argv[])
disabled_logger->set_level(spdlog::level::off);
benchmark::RegisterBenchmark("disabled-at-compile-time", bench_disabled_macro, disabled_logger);
benchmark::RegisterBenchmark("disabled-at-runtime", bench_logger, disabled_logger);
// 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);
auto null_logger_st = std::make_shared<spdlog::logger>("bench", std::make_shared<null_sink_st>());
benchmark::RegisterBenchmark("null_sink_st (500_bytes c_str)", bench_c_string, std::move(null_logger_st));
benchmark::RegisterBenchmark("null_sink_st", bench_logger, null_logger_st);
// 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);
// basic_st
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();
spdlog::drop("basic_st");
// 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");
// rotating st
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();
spdlog::drop("rotating_st");
// 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);
benchmark::RegisterBenchmark("rotating_st/backtrace", bench_logger, std::move(tracing_rotating_st))->UseRealTime();
spdlog::drop("tracing_rotating_st");
// daily st
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();
spdlog::drop("daily_st");
auto tracing_daily_st = spdlog::daily_logger_mt("tracing_daily_st", "latency_logs/daily_st.log");
benchmark::RegisterBenchmark("daily_st/backtrace", bench_logger, std::move(tracing_daily_st))->UseRealTime();
spdlog::drop("tracing_daily_st");
// //
// // Multi threaded bench, 10 loggers using same logger concurrently
// //
//
// Multi threaded bench, 10 loggers using same logger concurrently
//
auto null_logger_mt = std::make_shared<spdlog::logger>("bench", std::make_shared<null_sink_mt>());
benchmark::RegisterBenchmark("null_sink_mt", bench_logger, null_logger_mt)->Threads(n_threads)->UseRealTime();
@ -138,6 +159,11 @@ int main(int argc, char *argv[])
"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();
auto async_logger_tracing = std::make_shared<spdlog::async_logger>(
"async_logger_tracing", std::make_shared<null_sink_mt>(), std::move(tp), spdlog::async_overflow_policy::overrun_oldest);
async_logger_tracing->enable_backtrace(32);
benchmark::RegisterBenchmark("async_logger/tracing", bench_logger, async_logger_tracing)->Threads(n_threads)->UseRealTime();
benchmark::Initialize(&argc, argv);
benchmark::RunSpecifiedBenchmarks();
}

View File

@ -1,4 +0,0 @@
# Ignore everything in this directory
*
# Except this file
!.gitignore

View File

@ -1,19 +0,0 @@
#!/bin/sh
if [ $# -lt 1 ]; then
echo "usage: $0 <program>"
fi
PROG=$1
if [ ! -x "$PROG" ]; then
echo $PROG not found or not executable.
exit 1
fi
$* &
PID=$!
while `kill -0 $PID 2>/dev/null`; do
ps -eo size,pid,user,pcpu,command --sort -size | awk '{ line=1 ; hr=$1/1024 ; printf("%13.2f Mb ",hr); } { for ( x=4 ; x<=NF ; x++ ) { printf("%s ",$x) } print "" }' | grep -v grep | grep -v $0 | grep $PROG
done

15
third_party/spdlog/bench/meson.build vendored Normal file
View File

@ -0,0 +1,15 @@
benchmark = dependency('benchmark')
bench_matrix = [
['bench', [spdlog_dep], []],
['async_bench', [spdlog_dep], []],
['formatter-bench', [spdlog_dep, benchmark], ['all']],
['latency', [spdlog_dep, benchmark], []],
]
foreach i : bench_matrix
bench_exe = executable(i[0], i[0] + '.cpp', dependencies: i[1])
benchmark('bench_' + i[0], bench_exe, args: i[2])
endforeach
run_command(find_program('mkdir'), meson.current_build_dir() + '/logs')