Skip to content

Instantly share code, notes, and snippets.

Embed
What would you like to do?
spdlog: performance test with atomics, when all threads logs in total less than the maximum queue size : 1048576; // 2 ^ 20
//// to compile: c++ bench.cpp -o bench -Wall -Wshadow -Wextra -pedantic -std=c++11 -pthread -I../include -O3 -fPIC -Ofast -m64 -march=native
// Alternative: c++ bench.cpp -o bench -Wall -Wshadow -Wextra -pedantic -std=c++11 -pthread -I../include -O3 -march=native
// the test code itself is Public domain @ref: Unlicense.org
// made by KjellKod, 2015, first published for testing of g3log at github.com/kjellkod/g3log
// Feel free to share, modify etc with no obligations but also with no guarantees from my part either
// enjoy - Kjell Hedstrom (aka KjellKod)
//
//
// spdlog follows however another license. See the bottow of this file
//
#include <thread>
#include <vector>
#include <atomic>
#include <iostream>
#include <chrono>
#include <algorithm>
#include <iomanip>
#include <iostream>
#include <sstream>
#include <fstream>
#include <cstdio>
#include <map>
#include <thread>
#include "spdlog/spdlog.h"
namespace spd = spdlog;
namespace {
const uint64_t g_iterations{1000000};
std::atomic<size_t> g_counter = {0};
void WriteToFile(std::string result_filename, std::string content) {
std::ofstream out;
std::ios_base::openmode mode = std::ios_base::out | std::ios_base::app;
;
out.open(result_filename.c_str(), mode);
if (!out.is_open()) {
std::cerr << "Error writing to " << result_filename << std::endl;
}
out << content << std::flush;
std::cout << content;
}
void MeasurePeakDuringLogWrites(std::shared_ptr<spdlog::logger> logger, const size_t id, std::vector<uint64_t>& result) {
while (true) {
const size_t value_now = ++g_counter;
if (value_now > g_iterations) {
return;
}
auto start_time = std::chrono::high_resolution_clock::now();
logger->info() << "Some text to log for thread: " << id;
auto stop_time = std::chrono::high_resolution_clock::now();
uint64_t time_us = std::chrono::duration_cast<std::chrono::microseconds>(stop_time - start_time).count();
result.push_back(time_us);
}
}
void PrintStats(const std::string& filename, const std::map<size_t, std::vector<uint64_t>>& threads_result, const uint64_t total_time_in_us) {
size_t idx = 0;
std::ostringstream oss;
for (auto t_result : threads_result) {
uint64_t worstUs = (*std::max_element(t_result.second.begin(), t_result.second.end()));
oss << idx++ << " the worst thread latency was:" << worstUs / uint64_t(1000) << " ms (" << worstUs << " us)] " << std::endl;
}
oss << "Total time :" << total_time_in_us / uint64_t(1000) << " ms (" << total_time_in_us
<< " us)" << std::endl;
oss << "Average time: " << double(total_time_in_us) / double(g_iterations) << " us" << std::endl;
WriteToFile(filename, oss.str());
}
void SaveResultToBucketFile(std::string result_filename, const std::map<size_t, std::vector<uint64_t>>& threads_result) {
// now split the result in buckets of 1ms each so that it's obvious how the peaks go
std::vector<uint64_t> all_measurements;
all_measurements.reserve(g_iterations);
for (auto& t_result : threads_result) {
all_measurements.insert(all_measurements.end(), t_result.second.begin(), t_result.second.end());
}
std::map<uint64_t, uint64_t> bucketsWithEmpty;
std::map<uint64_t, uint64_t> buckets;
// force empty buckets to appear
auto maxValueIterator = std::max_element(all_measurements.begin(), all_measurements.end());
const auto kMaxValue = *maxValueIterator;
for (uint64_t idx = 0; idx <= kMaxValue; ++idx) {
bucketsWithEmpty[idx]=0;
}
for (auto value : all_measurements) {
++bucketsWithEmpty[value];
++buckets[value];
}
std::cout << "\n\n Microsecond bucket measurement" << std::endl;
for (const auto ms_bucket : buckets) {
std::cout << ms_bucket.first << "\t, " << ms_bucket.second << std::endl;
}
std::cout << "\n\n";
std::ostringstream oss;
// Save to xcel and google doc parsable format. with empty buckets
oss << "\n\n Microsecond bucket measurement with zero buckets till max" << std::endl;
for (const auto ms_bucket : bucketsWithEmpty) {
oss << ms_bucket.first << "\t, " << ms_bucket.second << std::endl;
}
WriteToFile(result_filename, oss.str());
std::cout << "Worst Case Latency, max value: " << kMaxValue << std::endl;
std::cout << "microsecond bucket result is in file: " << result_filename << std::endl;
}
} // anonymous
// The purpose of this test is NOT to see how fast
// each thread can possibly write. It is to see what
// the worst latency is for writing a log entry
//
// In the test 1 million log entries will be written
// an atomic counter is used to give each thread what
// it is to write next. The overhead of atomic
// synchronization between the threads are not counted in the worst case latency
int main(int argc, char** argv) {
size_t number_of_threads {0};
if (argc == 2) {
number_of_threads = atoi(argv[1]);
}
if (argc != 2 || number_of_threads == 0) {
std::cerr << "USAGE is: " << argv[0] << " number_threads" << std::endl;
return 1;
}
std::vector<std::thread> threads(number_of_threads);
std::map<size_t, std::vector<uint64_t>> threads_result;
for (size_t idx = 0; idx < number_of_threads; ++idx) {
// reserve to 1 million for all the result
// it's a test so let's not care about the wasted space
threads_result[idx].reserve(g_iterations);
}
std::string filename_choice;
std::cout << "Choose filename prefix to log to" << std::endl;
std::getline(std::cin, filename_choice);
//int queue_size = 1048576; // 2 ^ 20
//int queue_size = 524288; // 2 ^ 19
//spdlog::set_async_mode(queue_size); // default size is 1048576
auto logger = spdlog::create<spd::sinks::simple_file_sink_mt>("file_logger", filename_choice + ".log", false);
auto filename_result = filename_choice + ".result.csv";
std::ostringstream oss;
oss << "Using " << number_of_threads;
oss << " to log in total " << g_iterations << " log entries to " << filename_choice << std::endl;
WriteToFile(filename_result, oss.str());
auto start_time_application_total = std::chrono::high_resolution_clock::now();
for (uint64_t idx = 0; idx < number_of_threads; ++idx) {
threads[idx] = std::thread(MeasurePeakDuringLogWrites,logger, idx, std::ref(threads_result[idx]));
}
for (size_t idx = 0; idx < number_of_threads; ++idx) {
threads[idx].join();
}
auto stop_time_application_total = std::chrono::high_resolution_clock::now();
uint64_t total_time_in_us = std::chrono::duration_cast<std::chrono::microseconds>(stop_time_application_total - start_time_application_total).count();
PrintStats(filename_result, threads_result, total_time_in_us);
SaveResultToBucketFile(filename_result, threads_result);
return 0;
}
/*************************************************************************/
/* spdlog - an extremely fast and easy to use c++11 logging library. */
/* Copyright (c) 2014 Gabi Melman. */
/* */
/* 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. */
/*************************************************************************/
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.