From bc495bbc630b6eddb895f048c02cdefd00b271ea Mon Sep 17 00:00:00 2001 From: gabime Date: Mon, 9 Jul 2018 21:06:15 +0300 Subject: [PATCH] Added latency bench --- bench/Makefile | 8 ++- bench/latency.cpp | 159 ++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 165 insertions(+), 2 deletions(-) create mode 100644 bench/latency.cpp diff --git a/bench/Makefile b/bench/Makefile index 98fcccb7..534c55c3 100644 --- a/bench/Makefile +++ b/bench/Makefile @@ -1,14 +1,18 @@ CXX = g++ -CXXFLAGS = -march=native -Wall -Wextra -pedantic -std=c++11 -pthread -I../include +CXXFLAGS = -march=native -Wall -Wextra -pedantic -std=c++11 -pthread -I../include -fmax-errors=1 CXX_RELEASE_FLAGS = -O3 -flto -binaries=bench +binaries=bench latency all: $(binaries) bench: bench.cpp $(CXX) bench.cpp -o bench $(CXXFLAGS) $(CXX_RELEASE_FLAGS) + + +latency: latency.cpp + $(CXX) latency.cpp -o latency $(CXXFLAGS) $(CXX_RELEASE_FLAGS) .PHONY: clean diff --git a/bench/latency.cpp b/bench/latency.cpp new file mode 100644 index 00000000..55ed8e49 --- /dev/null +++ b/bench/latency.cpp @@ -0,0 +1,159 @@ +// +// Copyright(c) 2018 Gabi Melman. +// Distributed under the MIT License (http://opensource.org/licenses/MIT) +// + +// +// latency.cpp : spdlog latency benchmarks +// +#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" +#include "spdlog/spdlog.h" +#include "utils.h" +#include +#include +#include +#include +#include +#include + +using namespace std; +using namespace std::chrono; +using namespace spdlog; +using namespace spdlog::sinks; +using namespace utils; + +void bench(int howmany, std::shared_ptr log); +void bench_mt(int howmany, std::shared_ptr log, int thread_count); + +int main(int , char *[]) +{ + std::srand(std::time(nullptr)); // use current time as seed for random generator + int howmany = 50; + int queue_size = howmany + 2; + int threads = 10; + int file_size = 30 * 1024 * 1024; + int rotating_files = 5; + + try + { + + cout << "*******************************************************************************\n"; + cout << "Single thread\n"; + cout << "*******************************************************************************\n"; + + auto basic_st = spdlog::basic_logger_mt("basic_st", "logs/basic_st.log", true); + bench(howmany, basic_st); + + auto rotating_st = spdlog::rotating_logger_st("rotating_st", "logs/rotating_st.log", file_size, rotating_files); + bench(howmany, rotating_st); + + auto daily_st = spdlog::daily_logger_st("daily_st", "logs/daily_st.log"); + bench(howmany, daily_st); + + bench(howmany, spdlog::create("null_st")); + + cout << "\n*******************************************************************************\n"; + cout << threads << " threads sharing same logger\n"; + cout << "*******************************************************************************\n"; + + auto basic_mt = spdlog::basic_logger_mt("basic_mt", "logs/basic_mt.log", true); + bench_mt(howmany, basic_mt, threads); + + auto rotating_mt = spdlog::rotating_logger_mt("rotating_mt", "logs/rotating_mt.log", file_size, rotating_files); + bench_mt(howmany, rotating_mt, threads); + + auto daily_mt = spdlog::daily_logger_mt("daily_mt", "logs/daily_mt.log"); + bench_mt(howmany, daily_mt, threads); + bench(howmany, spdlog::create("null_mt")); + + cout << "\n*******************************************************************************\n"; + cout << "async logging.. " << threads << " threads sharing same logger\n"; + cout << "*******************************************************************************\n"; + + for (int i = 0; i < 3; ++i) + { + spdlog::init_thread_pool(queue_size, 1); + auto as = spdlog::basic_logger_mt("async", "logs/basic_async.log", true); + bench_mt(howmany, as, threads); + spdlog::drop("async"); + } + } + catch (std::exception &ex) + { + std::cerr << "Error: " << ex.what() << std::endl; + perror("Last error"); + return EXIT_FAILURE; + } + return EXIT_SUCCESS; +} + +void rand_sleep() +{ + + auto sleep_ms= std::chrono::milliseconds(std::rand() % 50); + std::this_thread::sleep_for(sleep_ms); +} + +void bench(int howmany, std::shared_ptr log) +{ + using namespace std::chrono; + using chrono::high_resolution_clock; + using chrono::milliseconds; + using chrono::nanoseconds; + + cout << log->name() << "...\t\t" << flush; + nanoseconds total_nanos = nanoseconds::zero(); + for (auto i = 0; i < howmany; ++i) + { + auto start = high_resolution_clock::now(); + log->info("Hello logger: msg number {}", i); + auto delta_nanos = chrono::duration_cast(high_resolution_clock::now() - start); + total_nanos+= delta_nanos; + rand_sleep(); + } + + auto avg = total_nanos.count()/howmany; + cout << format(avg) << " ns/call" << endl; +} + +void bench_mt(int howmany, std::shared_ptr log, int thread_count) +{ + using namespace std::chrono; + using chrono::high_resolution_clock; + using chrono::milliseconds; + using chrono::nanoseconds; + + cout << log->name() << "...\t\t" << flush; + vector threads; + nanoseconds::rep total_nanos = 0; + for (int t = 0; t < thread_count; ++t) + { + threads.push_back(std::thread([&]() { + nanoseconds thr_total_nanos = nanoseconds::zero(); + for (int j = 0; j < howmany / thread_count; j++) + { + auto start = high_resolution_clock::now(); + log->info("Hello logger: msg number {}", j); + auto delta_nanos = chrono::duration_cast(high_resolution_clock::now() - start); + thr_total_nanos+= delta_nanos; + rand_sleep(); + } + total_nanos+= thr_total_nanos.count(); + })); + } + + for (auto &t : threads) + { + t.join(); + }; + + auto avg = total_nanos/howmany; + cout << format(avg) << " ns/call" << endl; + + + +}