diff --git a/README.md b/README.md index 5037e495..f3ea9fc0 100644 --- a/README.md +++ b/README.md @@ -35,10 +35,22 @@ Just copy the files to your build tree and use a C++11 compiler Below are some [benchmarks](bench) comparing the time needed to log 1,000,000 lines to file under Ubuntu 64 bit, Intel i7-4770 CPU @ 3.40GHz (the best of 3 runs for each logger): -|threads|boost log|glog|g2log async mode|spdlog|spdlog async mode| -|-------|:-------:|:-----:|------:|------:|------:| -|1|4.779s|1.109s|3.155s|0.319s|0.212s -|10|15.151ss|3.546s|3.500s|0.641s|0.199s| +### Synchronous mode +|threads|boost log|glog |easylogging |spdlog| +|-------|:-------:|:-----:|----------:|------:| +|1| 4.169s |1.066s |0.975s :|0.302s| +|10| 16.029 |3.032s |2.857 :|0.968s| +|100| 15.008 |1.139s |4.512s :|0.497s| + + +### ASynchronous mode +|threads|g2log |spdlogasync mode| +|:-------|----- :|:-------------------------:| +|1| 1.850s |0.216s +|10| 0.943s |0.173s +|100| 0.959s |0.202 + + ## Usage Example diff --git a/bench/Makefile b/bench/Makefile index 46b8b853..770c05f8 100644 --- a/bench/Makefile +++ b/bench/Makefile @@ -3,7 +3,7 @@ CXXFLAGS = -march=native -Wall -Wextra -pedantic -std=c++11 -pthread -Wl,--no-as CXX_RELEASE_FLAGS = -O3 -flto -binaries=spdlog-bench spdlog-bench-mt spdlog-bench-async spdlog-bench-mt-async boost-bench boost-bench-mt glog-bench glog-bench-mt g2log-bench g2log-bench-mt easylogging-bench easylogging-bench-mt +binaries=spdlog-bench spdlog-bench-mt spdlog-async boost-bench boost-bench-mt glog-bench glog-bench-mt g2log-async easylogging-bench easylogging-bench-mt all: $(binaries) @@ -13,11 +13,9 @@ spdlog-bench: spdlog-bench.cpp spdlog-bench-mt: spdlog-bench-mt.cpp $(CXX) spdlog-bench-mt.cpp -o spdlog-bench-mt $(CXXFLAGS) $(CXX_RELEASE_FLAGS) -spdlog-bench-async: spdlog-bench-async.cpp - $(CXX) spdlog-bench-async.cpp -o spdlog-bench-async $(CXXFLAGS) $(CXX_RELEASE_FLAGS) +spdlog-async: spdlog-async.cpp + $(CXX) spdlog-async.cpp -o spdlog-async $(CXXFLAGS) $(CXX_RELEASE_FLAGS) -spdlog-bench-mt-async: spdlog-bench-mt-async.cpp - $(CXX) spdlog-bench-mt-async.cpp -o spdlog-bench-mt-async $(CXXFLAGS) $(CXX_RELEASE_FLAGS) BOOST_FLAGS = -DBOOST_LOG_DYN_LINK -I/home/gabi/devel/boost_1_56_0/ -L/home/gabi/devel/boost_1_56_0/stage/lib -lboost_log -lboost_log_setup -lboost_filesystem -lboost_system -lboost_thread -lboost_regex -lboost_date_time -lboost_chrono @@ -37,12 +35,9 @@ glog-bench-mt: glog-bench-mt.cpp G2LOG_FLAGS = -I/home/gabi/devel/g2log/g2log/src -L/home/gabi/devel/g2log/g2log -llib_g2logger -g2log-bench: g2log-bench.cpp - $(CXX) g2log-bench.cpp -o g2log-bench $(CXXFLAGS) $(G2LOG_FLAGS) $(CXX_RELEASE_FLAGS) +g2log-async: g2log-async.cpp + $(CXX) g2log-async.cpp -o g2log-async $(CXXFLAGS) $(G2LOG_FLAGS) $(CXX_RELEASE_FLAGS) -g2log-bench-mt: g2log-bench-mt.cpp - $(CXX) g2log-bench-mt.cpp -o g2log-bench-mt $(CXXFLAGS) $(G2LOG_FLAGS) $(CXX_RELEASE_FLAGS) - diff --git a/bench/g2log-bench-mt.cpp b/bench/g2log-async.cpp similarity index 61% rename from bench/g2log-bench-mt.cpp rename to bench/g2log-async.cpp index 9e32c3f4..4af00cb0 100644 --- a/bench/g2log-bench-mt.cpp +++ b/bench/g2log-async.cpp @@ -2,19 +2,22 @@ #include #include #include +#include #include "g2logworker.h" #include "g2log.h" using namespace std; +template std::string format(const T& value); int main(int argc, char* argv[]) { - + using namespace std::chrono; + using clock=steady_clock; int thread_count = 10; + if(argc > 1) thread_count = atoi(argv[1]); - int howmany = 1000000; g2LogWorker g2log(argv[0], "logs"); @@ -23,7 +26,7 @@ int main(int argc, char* argv[]) std::atomic msg_counter {0}; vector threads; - + auto start = clock::now(); for (int t = 0; t < thread_count; ++t) { threads.push_back(std::thread([&]() @@ -41,9 +44,14 @@ int main(int argc, char* argv[]) for(auto &t:threads) { t.join(); - }; - - - - return 0; + }; + + duration delta = clock::now() - start; + float deltaf = delta.count(); + auto rate = howmany/deltaf; + + cout << "Total: " << howmany << std::endl; + cout << "Threads: " << thread_count << std::endl; + std::cout << "Delta = " << deltaf << " seconds" << std::endl; + std::cout << "Rate = " << rate << "/sec" << std::endl; } diff --git a/bench/g2log-bench.cpp b/bench/g2log-bench.cpp deleted file mode 100644 index f716940a..00000000 --- a/bench/g2log-bench.cpp +++ /dev/null @@ -1,16 +0,0 @@ -#include "g2logworker.h" -#include "g2log.h" - - -int main(int, char* argv[]) -{ - int howmany = 1000000; - - g2LogWorker g2log(argv[0], "logs"); - g2::initializeLogging(&g2log); - - for(int i = 0 ; i < howmany; ++i) - LOG(INFO) << "g2log message # " << i << ": This is some text for your pleasure"; - - return 0; -} diff --git a/bench/glog-bench-mt.cpp b/bench/glog-bench-mt.cpp index 6287633d..5418c085 100644 --- a/bench/glog-bench-mt.cpp +++ b/bench/glog-bench-mt.cpp @@ -41,7 +41,5 @@ int main(int argc, char* argv[]) t.join(); }; - - return 0; } diff --git a/bench/run_all.sh b/bench/run_all.sh index 6b6cc74c..588557e2 100755 --- a/bench/run_all.sh +++ b/bench/run_all.sh @@ -1,81 +1,80 @@ #~/bin/bash +#execute each bench 3 times and print the timing exec 2>&1 +#execute and time given exe 3 times +bench_exe () +{ + echo "**************** $1 ****************" + for i in {1..3}; do + time ./$1 $2; + rm -f logs/* + sleep 3 + done; +} -echo "Running benchmakrs (all with 1000,000 writes to the logs folder)" -echo -echo "boost-bench (single thread).." -for i in {1..3}; do time ./boost-bench; done -rm -f logs/* -echo -echo -sleep 5 +#execute given async tests 3 times (timing is already builtin) +bench_async () +{ + echo "**************** $1 ****************" + for i in {1..3}; do + ./$1 $2; + rm -f logs/* + sleep 3 + done; +} -echo "glog-bench (single thread).." -for i in {1..3}; do time ./glog-bench; done -rm -f logs/* -echo -echo -sleep 5 -echo "g2log-bench (single thread).." -for i in {1..3}; do time ./g2log-bench; done -rm -f logs/* -echo -echo -sleep 5 +echo "----------------------------------------------------------" +echo "Single threaded benchmarks.. (1 thread, 1,000,000 lines)" +echo "----------------------------------------------------------" +for exe in boost-bench glog-bench easylogging-bench spdlog-bench; +do + bench_exe $exe 1 +done; -echo "spdlog-bench (single thread)" -for i in {1..3}; do time ./spdlog-bench; done -rm -f logs/* -echo -echo -sleep 5 -echo "------------------------------------" -echo "Multithreaded benchmarks.." -echo "------------------------------------" -echo "boost-bench-mt (10 threads, single logger)".. -for i in {1..3}; do ./boost-bench-mt; done -rm -f logs/* -echo -echo -sleep 5 +echo "----------------------------------------------------------" +echo "Multi threaded benchmarks.. (10 threads, 1,000,000 lines)" +echo "----------------------------------------------------------" +for exe in boost-bench-mt glog-bench-mt easylogging-bench-mt spdlog-bench-mt; +do + bench_exe $exe 10 +done; -echo "glog-bench-mt (10 threads, single logger)".. -for i in {1..3}; do time ./glog-bench-mt; done -rm -f logs/* -echo -echo -sleep 5 +echo "----------------------------------------------------------" +echo "Multi threaded benchmarks.. (100 threads, 1,000,000 lines)" +echo "----------------------------------------------------------" +for exe in boost-bench-mt glog-bench-mt easylogging-bench-mt spdlog-bench-mt; +do + bench_exe $exe 100 +done; + -echo "g2log-bench-mt (10 threads, single logger)".. -for i in {1..3}; do time ./g2log-bench-mt; done -rm -f logs/* -echo -echo -sleep 5 +echo "---------------------------------------------------------------" +echo "Async, single threaded benchmark.. (1 thread, 1,000,000 lines)" +echo "---------------------------------------------------------------" +for exe in spdlog-async g2log-async +do + bench_async $exe 1 +done; -echo "spdlog-bench-mt (10 threads, single logger)".. -for i in {1..3}; do time ./spdlog-bench-mt; done -rm -f logs/* -echo -echo -sleep 5 +echo "---------------------------------------------------------------" +echo "Async, multi threaded benchmark.. (10 threads, 1,000,000 lines)" +echo "---------------------------------------------------------------" +for exe in spdlog-async g2log-async +do + bench_async $exe 10 +done; -echo "------------------------------------" -echo "Async benchmarks.." -echo "------------------------------------" -echo "spdlog-bench-async (single thread)".. -for i in {1..3}; do time ./spdlog-bench-async; done -rm -f logs/* -echo -echo -sleep 5 - -echo "spdlog-bench-mt-async (10 threads, single logger)".. -for i in {1..3}; do time ./spdlog-bench-mt-async; done +echo "---------------------------------------------------------------" +echo "Async, multi threaded benchmark.. (100 threads, 1,000,000 lines)" +echo "---------------------------------------------------------------" +for exe in spdlog-async g2log-async +do + bench_async $exe 100 +done; diff --git a/bench/spdlog-bench-mt-async.cpp b/bench/spdlog-async.cpp similarity index 51% rename from bench/spdlog-bench-mt-async.cpp rename to bench/spdlog-async.cpp index f7d424a1..aca38ce4 100644 --- a/bench/spdlog-bench-mt-async.cpp +++ b/bench/spdlog-async.cpp @@ -1,31 +1,34 @@ + #include #include #include +#include +#include #include "spdlog/spdlog.h" -#include using namespace std; int main(int argc, char* argv[]) { - + + using namespace std::chrono; + using clock=steady_clock; + namespace spd = spdlog; + int thread_count = 10; if(argc > 1) - thread_count = atoi(argv[1]); - - int howmany = 1048576; - - namespace spd = spdlog; - spd::set_async_mode(howmany); - ///Create a file rotating logger with 5mb size max and 3 rotated files - auto logger = spd::rotating_logger_mt("file_logger", "logs/spd-sample", 10 *1024 * 1024 , 5); - + thread_count = atoi(argv[1]); + int howmany = 1000000; + + spd::set_async_mode(1048576); + auto logger = spdlog::create("file_logger", "logs/spd-bench-async.txt", false); logger->set_pattern("[%Y-%b-%d %T.%e]: %v"); + std::atomic msg_counter {0}; vector threads; - + auto start = clock::now(); for (int t = 0; t < thread_count; ++t) { threads.push_back(std::thread([&]() @@ -39,13 +42,17 @@ int main(int argc, char* argv[]) })); } - for(auto &t:threads) { t.join(); }; - - //because spdlog async logger waits for the back thread logger to finish all messages upon destrcuting, - //and we want to measure only the time it took to push those messages to the backthread.. - abort(); + + duration delta = clock::now() - start; + float deltaf = delta.count(); + auto rate = howmany/deltaf; + + cout << "Total: " << howmany << std::endl; + cout << "Threads: " << thread_count << std::endl; + std::cout << "Delta = " << deltaf << " seconds" << std::endl; + std::cout << "Rate = " << rate << "/sec" << std::endl; } diff --git a/bench/spdlog-bench-async.cpp b/bench/spdlog-bench-async.cpp deleted file mode 100644 index d30e8677..00000000 --- a/bench/spdlog-bench-async.cpp +++ /dev/null @@ -1,22 +0,0 @@ - -#include "spdlog/spdlog.h" - - -int main(int, char* []) -{ - int howmany = 1048576; - namespace spd = spdlog; - spd::set_async_mode(howmany); - ///Create a file rotating logger with 5mb size max and 3 rotated files - auto logger = spd::rotating_logger_mt("file_logger", "logs/spd-sample", 10 *1024 * 1024 , 5); - - logger->set_pattern("[%Y-%b-%d %T.%e]: %v"); - for(int i = 0 ; i < howmany; ++i) - logger->info() << "spdlog message #" << i << ": This is some text for your pleasure"; - - - //because spdlog async logger waits for the back thread logger to finish all messages upon destrcuting, - //and we want to measure only the time it took to push those messages to the backthread.. - abort(); - return 0; -} diff --git a/bench/spdlog-bench.cpp b/bench/spdlog-bench.cpp index 8c28dac5..e0b41f35 100644 --- a/bench/spdlog-bench.cpp +++ b/bench/spdlog-bench.cpp @@ -7,7 +7,7 @@ int main(int, char* []) int howmany = 1000000; namespace spd = spdlog; ///Create a file rotating logger with 5mb size max and 3 rotated files - auto logger = spd::rotating_logger_st("file_logger", "logs/spd-sample", 10 *1024 * 1024 , 5); + auto logger = spdlog::create("file_logger", "logs/spd-bench-st.txt", false); logger->set_pattern("[%Y-%b-%d %T.%e]: %v"); for(int i = 0 ; i < howmany; ++i)