Add discard buffer to prevent unsychronized access when RingBuffer full #1410
Conversation
The ringbuffer we use is configured for multi-producer-single-consumer, where concurrent requests to add data should be safe. We added the synchronization for a slightly different reason: When the buffer is full, each time an event is processed, the background thread will notify all waiting threads. In a large web-server, this can be a lot of threads, and the system degrades into a state where most cpu time is spent notifying threads. The synchronization allows us to queue waiting threads efficiently when the buffer is full. What is the rate at which the corrupted state reproduces in your environment? I ran into a similar issue at one point which reproduced once every few months, using the SYNCHRONOUS queue-full-policy (writing logevents from the current thread rather than blocking waiting to enqueue) for non-discarded events seemed to resolve it (if it does occur, data would be logged synchronously, but my metrics indicate that the queue is never entirely filled either). |
|
We can reproduce this pretty reliably. There may be a secret ingredient in our setup (we use custom LogEventPatternConverters), but as I said before, we were not able to produce minimal reproducer that I could share. We initially confirmed that additional discard buffer proposed here mitigates the issue. We looked into SYNCHRONIZED policy, but the problem we have is that it can make the performance worse when the traffic is the highest. The service we own is latency sensitive and the tradeoff we want to make is to discard the logs if we can't keep up. As far as I understand the DISCARD and SYNCHRONIZED policies are mutually exclusive. SYNCHRONIZED_DISCARD policy may be another way to solve this, although I'm not 100% sure it will work since it still does the
Yes, that was also something I noticed while running benchmarks, although the impact was not nearly as big as it was when you initially worked on this .
From what I can tell it not always is. Ideally that's what should be fixed but, to be honest, I don't know how. |
A service that we maintain occasionally hangs when the rate of incoming logs is higher than the throughput of writing logs to a disk. We have a discard policy at ERROR level and use default
SynchronizeEnqueueWhenQueueFull. We believe that this is due to corrupted LMAX disruptor. We did some initial attempts to produce minimal reproducer (using jcstress) but were not able to succeed so far. This change also 'prioritizes' non-discarded logs, which in theory should reduce the logging back-pressure when buffer almost full.While reviewing the log4j code we noticed that there are code paths that avoid SynchronizeEnqueueWhenQueueFull and may be responsible for RingBuffer corruption, I prepared a small change that should prevent any unsynchronized access and wanted to get initial feedback from log4j maintainers. I also wanted to use this pull request to pick you brain on what else we can do to troubleshoot the issue futher.
Writer threads hang on following stack trace:
While the event processor is runnable, but is not making any progress, i.e. no logs are produced
Benchmark results
I was a bit surprised, but comparing to previous results of those benchmarks, I didn't see a significant drop in performance for the
ENQUEUE_UNSYNCHRONIZED. Benchmarks were run on m5.4xl instance (16 vCPU)Checklist
2.xbranch if you are targeting Log4j 2; usemainotherwiseDONE
./mvnw verifysucceeds (if it fails due to code formatting issues reported by Spotless, simply runspotless:applyand retry)DONE
src/changelog/.2.x.xdirectoryTBD
DONE