Blocking logging

[brendene]

Hello and thanks again for the library! Would you consider a logging mode where log messages are not dropped and the queue is non allocating? i.e. blocking

A use case would be stress testing a webserver that uses quill for logging. When the webserver is running in real time, logs are flushed to disk and the queue isn't growing. However, if you are stress testing the webserver with a preset load and piping the output to less eventually the pipe buffer fills up and the quill backend thread isn't able to drain so the queue gets larger and larger until the system possibly runs out of memory.

I realize this isn't in the spirit of a low latency logger but it would be nice to be able to utilize the same logging code (perhaps with a config option that enables/disables it) without adding quill::flush() everywhere.

[odygrd]

hey, i don't mind adding this to the bounded queue.

[odygrd]

@brendene this is done in #271

Also you should no longer need to recompile quill library. You will have to recompile your target tho with the appropriate flag.

See https://github.com/odygrd/quill/blob/bounded_queue/examples/CMakeLists.txt#L76 and https://github.com/odygrd/quill/blob/bounded_queue/examples/example_bounded_queue_blocking.cpp

Let me know if that works for you if you can use bounded_queue branch to try it out. Otherwise, it will be in the next release in a few weeks

[brendene]

Thank you, this is an elegant solution!

[brendene]

Hello again and thanks for the patch! I think there is a subtle interaction when the backend worker is able to write some data (i.e. not fully blocked) and simultaneously there are a lot of messages being logged. When running in blocking bounded mode I didn't expect memory allocations but I noticed there were many, I think this is because BackendWorker::_read_queue_messages_and_decode copies the entire contents of a bounded queue into an unbounded TransitEven buffer?

Here is a sample piece of code to trigger the OOM killer:

-- a/examples/example_bounded_queue_blocking.cpp
+++ b/examples/example_bounded_queue_blocking.cpp
@@ -18,15 +18,15 @@ int main()
   cfg.backend_thread_sleep_duration = std::chrono::seconds{1};
 
   // and a small queue size
-  cfg.default_queue_capacity = 4'096;
+  cfg.default_queue_capacity = 131'072;
 
   // Apply configuration and start the backend worker thread
   quill::configure(cfg);
   quill::start();
 
-  for (size_t i = 0; i < 1000; ++i)
+  for (int64_t i = 0; i < 100000000000; ++i)
   {
     LOG_INFO(quill::get_logger(), "Hello {} #{}", "world", i);
     LOG_ERROR(quill::get_logger(), "This is a log error example {} #{}", 7, i);

$ examples/example_bounded_queue_blocking > /dev/null
Killed

[odygrd]

Printing all events didn't work because the loop reads and buffers all messages for up to queue_capacity which is not always everything.

If T1 thread logs messages that are 2 x the queue capacity with timestamps e.g from t0 to t5 in half queue and t6 to t10 in second half of the queue
and a T2 thread logs 1 single message with timestamp t7
Then we read and buffer messages from all active queues each iteration, but we stop when we read queue_capacity bytes from each thread
It would lead to reading :
t0 to t5 from T1 (stopped reading as we buffered messages worth of a full queue capacity)
t7 from T2
Then print all the buffered messages (total_events)
and then in the next iteration buffer and print the remaining t6 to t10 we skipped in the above step
resulting in out of order log timestamps.

I have added a hard limit for the backend thread buffer https://github.com/odygrd/quill/blob/bounded_queue/quill/include/quill/Config.h#L75

Let me know if commit e883a05 works and thanks again for reporting !

[brendene]

Thanks for explaining that edge case! Will try out the new commit, thanks again for the fast fix.

[brendene]

The regression test failure at: https://github.com/odygrd/quill/actions/runs/4473138586/jobs/7860149594 due to 6b671b2 is interesting. I didn't expect log_from_one_thread to fail from such a small change. If you change total_events to total_events-1 then it passes.

The problem might be here:

quill/quill/include/quill/detail/LogManager.h

Line 180 in 6b671b2

thread_context->spsc_queue<QUILL_QUEUE_TYPE>().finish_write(static_cast<uint32_t>(write_buffer - write_begin));

The flush metadata event might be over writing part of the queue, resulting in the flush() being called in the middle of the 10'000 messages rather than at the end.

ex:

@@ -527,7 +528,8 @@ void BackendWorker::_process_transit_event(ThreadContextCollection::backend_thre
       transit_buffer = std::addressof(thread_context->transit_event_buffer());
     }
   }
-
+  static int64_t transitEventNumber = 0;
+  ++transitEventNumber;
   assert(transit_buffer && "transit_buffer can never be a nullptr");
 
   TransitEvent* transit_event = transit_buffer->front();
@@ -580,6 +582,7 @@ void BackendWorker::_process_transit_event(ThreadContextCollection::backend_thre
     }
     else if (macro_metadata.event() == MacroMetadata::Event::Flush)
     {
+       std::cerr << "flush! transitEventNumber:" << transitEventNumber << std::endl;
       _force_flush();

printed: flush! transitEventNumber:4113

[odygrd]

log_from_one_thread fails for the reason I’ve explained above! T1 logs more than the max messages we read per queue.

[odygrd]

Thinking of that you can still see out of order messages in the log when the hard_limit i added is reached. I think the easiest way to make this work for the bounded blocking queue case is to add a new mode that just pops a message from the queue each time without buffering with the transit buffer at all. It’s a bit more work to do so if you’re okay with the hard limit for now i can add this later

[brendene]

Ah, now I understand, log_from_one_thread logs from another thread besides the main thread, I was confused by the name and thought it meant single threaded! The flush() is being called from the main thread and not the one generating the logs.

I see what you mean by messages can still be out of order, here is a simple repro that still is under the backend_thread_transit_events_hard_limit. I am not using the logger in a multi-threaded way so it does not affect me now. This example is using an unbounded queue so it looks like it affects not only the bounded queue?

+++ b/quill/test/QuillLogTest.cpp
@@ -19,6 +19,9 @@ void test_quill_log(char const* test_id, std::string const& filename, uint16_t n
                     uint32_t number_of_messages)
 {
   // Start the logging backend thread
+  quill::Config cfg;
+  cfg.backend_thread_transit_events_soft_limit = 4097;
+  quill::configure(cfg);
   quill::start();

ctest -R log_from_one_thread --verbose
Note that its non-deterministic, so you my have to run several times before getting the error:

60: ===============================================================================
60: <...>/quill/quill/test/QuillLogTest.cpp:81:
60: TEST SUITE: QuillLog
60: TEST CASE:  log_from_one_thread
60: 
60: <...>/quill/quill/test/QuillLogTest.cpp:61: FATAL ERROR: REQUIRE_EQ( file_contents.size(), number_of_messages * number_of_threads ) is NOT correct!
60:   values: REQUIRE_EQ( 4096, 10000 )
60: 
60: ===============================================================================
60: [doctest] test cases: 1 | 0 passed | 1 failed | 11 skipped
60: [doctest] assertions: 1 | 0 passed | 1 failed |
60: [doctest] Status: FAILURE!
1/1 Test #60: log_from_one_thread ..............***Failed    0.14 sec

0% tests passed, 1 tests failed out of 1

Total Test time (real) =   0.14 sec

[odygrd]

i think it would work if we do something like

max_events_per_thread = transit_event_soft_limit / total_threads_spsc_queues

drain up to max_events_per_thread from all hot threads and keep the max number of events drained per thread and also total_events that  has the total of events

if total_events > soft_limit then flush up to max_events_per_thread

for example for a soft limit of 10, if you have
queue_1 : 1,2,3,4,5
queue_2: 7

you would only log queue_1.
But if we do that then the problem is that we are limiting how quickly the unbounded hot thread queues are drained increasing the possibility for a reallocation

[brendene]

what if the last line is modified to flush up to max_events_per_thread-1 per thread?

it would better handle cases like:
queue_1: 2, 4, 6, 8, 10
queue_2: 1, 3, 5, 7, 9

[odygrd]

I have fixed the failing test by just flushing up to max_events - 1

I have also added a flag that disables the message buffering (https://github.com/odygrd/quill/blob/bounded_queue/quill/include/quill/Config.h#L49), using that flag with the bounded blocking queue should result in fewer memory usage on the backend thread
in a705a6b

let me know if you see anything else!

[brendene]

Thank you! If my understanding is correct, messages should always be in order now. I think just https://github.com/odygrd/quill/blob/bounded_queue/quill/include/quill/Config.h#L58 needs updating now that it drains max_events - 1 events

Using the new throughput benchmark you committed I am getting ~ 3.59million msgs/sec for BENCHMARK_quill_backend_throughput and ~ 3.49million msgs/sec for BENCHMARK_quill_backend_throughput_no_buffering A loss of only ~3% in throughput in return for much less complexity

[odygrd]

Thanks i will update that :)

The main reason for the buffering is not the logging thread performance but keeping the queues of the hot threads empty. When the unbounded queue has to reallocate then the hot thread gets that penalty

[brendene]

Hello! Thanks again for the great library. Would it be possible to prevent a busy loop if a user tries to log to a full bounded queue? (i.e a configurable sleep in https://github.com/odygrd/quill/blob/master/quill/include/quill/Logger.h#L205)

Use case is that the program output is piped to less, the less buffer is full and then a full CPU core is spinning while waiting for the user to scroll through more lines of output.

[odygrd]

Hey, yes I think we can add this. It might take a few days to make this change because I need to finish and push first some local changes I have

[odygrd]

I have added this to the latest master, if you need anything else let me know :)

[brendene]

This is perfect, thank you!