spdlog: performance test with atomics, when all threads logs in total less than the maximum queue size : 1048576; // 2 ^ 20

main_spdlog_worst_case_latency.cpp

//// 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.                */
/*************************************************************************/