Benchmarks hang

[erenon]

Hi, thanks for the comparison! I tried to reproduce the results, however, the benchmarks appear to hang:

$ git clone https://github.com/odygrd/logger_benchmarks.git
$ cd logger_benchmarks && mkdir Release && cd Release
$ cmake .. # this requires python2.7, unfortunate!
$ make -j8
$ gdb benchmarks/call_site_latency/benchmark_quill_v2_unbounded_call_site_latency_int_int_double
^C after 10 seconds
(gdb) thread apply all bt

Thread 3 (Thread 0x7ffff7183640 (LWP 1440946) "benchmark_quill"):
#0  0x00007ffff7fc16e8 in ?? ()
#1  0x00007ffff7fc180a in ?? ()
#2  0x00007ffff7c1a6dd in __GI___clock_gettime (clock_id=<optimized out>, tp=<optimized out>) at ../sysdeps/unix/sysv/linux/clock_gettime.c:42
#3  0x00007ffff7e4f195 in std::chrono::_V2::steady_clock::now() () from /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x0000555555586075 in run_log_benchmark(unsigned long, std::function<void ()>, std::function<void (unsigned long, unsigned long, double)>, std::function<void ()>, unsigned long, std::vector<unsigned long, std::allocator<unsigned long> >&, double) ()
#5  0x000055555558329e in std::thread::_State_impl<std::thread::_Invoker<std::tuple<void (*)(unsigned long, std::function<void ()>, std::function<void (unsigned long, unsigned long, double)>, std::function<void ()>, unsigned long, std::vector<unsigned long, std::allocator<unsigned long> >&, double), unsigned long, std::function<void ()>, std::function<void (unsigned long, unsigned long, double)>, std::function<void ()>, int, std::reference_wrapper<std::vector<unsigned long, std::allocator<unsigned long> > >, double> > >::_M_run() ()
#6  0x00007ffff7e592b3 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#7  0x00007ffff7bc9b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#8  0x00007ffff7c5ba00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 2 (Thread 0x7ffff7a48640 (LWP 1440945) "Quill_Backend"):
#0  0x00007ffff7fc16e8 in ?? ()
#1  0x00007ffff7fc180a in ?? ()
#2  0x00007ffff7c1a6dd in __GI___clock_gettime (clock_id=<optimized out>, tp=<optimized out>) at ../sysdeps/unix/sysv/linux/clock_gettime.c:42
#3  0x00007ffff7e4f142 in std::chrono::_V2::system_clock::now() () from /lib/x86_64-linux-gnu/libstdc++.so.6
#4  0x000055555557a655 in quill::detail::BackendWorker::_main_loop() ()
#5  0x000055555556f446 in quill::detail::BackendWorker::run()::{lambda()#1}::operator()() const ()
#6  0x00007ffff7e592b3 in ?? () from /lib/x86_64-linux-gnu/libstdc++.so.6
#7  0x00007ffff7bc9b43 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#8  0x00007ffff7c5ba00 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 1 (Thread 0x7ffff7a49780 (LWP 1440944) "benchmark_quill"):
#0  __futex_abstimed_wait_common64 (private=128, cancel=true, abstime=0x0, op=265, expected=1440946, futex_word=0x7ffff7183910) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (cancel=true, private=128, abstime=0x0, clockid=0, expected=1440946, futex_word=0x7ffff7183910) at ./nptl/futex-internal.c:87
#2  __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x7ffff7183910, expected=1440946, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=private@entry=128) at ./nptl/futex-internal.c:139
#3  0x00007ffff7bcb6a4 in __pthread_clockjoin_ex (threadid=140737338947136, thread_return=0x0, clockid=0, abstime=0x0, block=<optimized out>) at ./nptl/pthread_join_common.c:105
#4  0x00007ffff7e59327 in std::thread::join() () from /lib/x86_64-linux-gnu/libstdc++.so.6
#5  0x0000555555587ca8 in run_benchmark(char const*, int, unsigned long, std::function<void ()>, std::function<void (unsigned long, unsigned long, double)>, std::function<void ()>) ()
#6  0x000055555556eaf4 in quill_benchmark(std::vector<int, std::allocator<int> >, unsigned long) [clone .cold] ()
#7  0x0000555555578436 in main ()

When left running, it completely consumes one CPU for minutes, and does not terminate. Is this expected? The binlog test does the same.

[odygrd]

hey, yes each one takes several minutes to complete.

Currently they log a batch of messages (20 messages) and then sleep for a bit and then log again, the reason for that is that if the hot thread logs all at once they just all pushed to the unbounded spsc queues very fast and the backend logging thread can't keep up anyway.

https://github.com/odygrd/logger_benchmarks/blob/master/benchmarks/call_site_latency/call_site_latency_bench.h#LL109C6-L109C6

https://github.com/odygrd/logger_benchmarks/blob/master/benchmarks/call_site_latency/call_site_latency_bench_common.h#L24

Try to run a single one and just wait a few minutes it should complete ! Probably the sleep timers could be smaller to wait less, i usually let them all run overnight with a python script