It's possible I'm missing some other aspect that insulates the application thread from the disruptor, but from your message it seems to me that you fall into the all-too-common category of people who do not fully understand the semantics of the disruptor. Application threads (i.e. disruptor producers) very much *are* affected by the wait strategy. Under normal use, *if the disruptor consumer thread is employing a blocking strategy, there will be futex call to unblock it when work is provided*. i.e. whenever the queue transitions from empty to non-empty, i.e. for most messages with low-to-medium logging rates.
In this situation the enqueueing of a message is also* not lock free*, as while futexes can in theory be lock-free, the JVM uses a lock to synchronise access to the semaphore that controls its runnable state, so all threads attempting to wake it up concurrently will compete for this lock. On 22 May 2016 at 14:42, Remko Popma <remko.po...@gmail.com> wrote: > > > On Sunday, May 22, 2016 at 6:34:13 PM UTC+9, Benedict Elliott Smith wrote: >> >> Hi Remko, >> >> I realise that I was looking at the old log4j code without realising it, >> in which there is always a futex involved. >> > Which class is this? Async Loggers in Log4j 2 have always been lock-free. > What may be confusing is that Log4j 2 also has an Async*Appender*, which > does not use the Disruptor but uses a JDK BlockingArrayQueue. This appender > is very similar to how Logback and Log4j 1 do asynchronous logging. Async > *Appender* (in Log4j 2, Log4j 1 and Logback, they all use a blocking > queue) is sensitive to lock contention and does not scale with more threads. > > >> >> However the behaviour of the disruptor that backs the new code will >> depend on the wait strategy employed (and I'll note your default is a >> blocking strategy, for which my prior statement holds*). >> > Perhaps the key misunderstanding is here. I think I did not explain it > well in my previous message. Let me try again. > > Async Loggers use the Disruptor and are lock-free. This means that > multiple application threads can log concurrently and are not blocked by > each other. This is true for very low workloads, medium workloads and high > workloads. > > Only if an application logs messages at a very high rate for a long period > of time, or uses a slow appender, the Disruptor ringbuffer can fill up and > application threads will have to wait until a slot in the ringbuffer > becomes available. For the 2.6 release I have added text to the > Trade-offs section > <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Trade-offs> > to explain this last point, based on your feedback. > > Note that the Disruptor wait strategy is irrelevant to all this. > Application threads are *not *impacted by the wait strategy. > > >> Here we obviously get into the territory of people needing to understand >> the disruptor as well as your logging framework, but since you have a whole >> section labelled "Trade-offs" in which you draw attention to the improved >> throughput and latency profile under "Benefits," under "Drawbacks" it might >> be nice to mention these possible confounders. Or at least raise a bat >> signal to go and understand the tradeoffs for the disruptor (which is also >> regrettably poorly understood). >> >> It might also be helpful to explicitly call out the configuration used >> for your benchmarks, >> > Tests on the 2.6 performance page > <http://home.apache.org/~rpopma/log4j/2.6/performance.html> are mostly > done with JMH benchmarks where parameters are in the javadoc. > Tests on the Async Loggers page are partly with the new ResponseTimeTest > <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/ResponseTimeTest.java>class > (params in the doc > <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html#Latency>) and > partly still shows results from the older PerfTestDriver > <https://github.com/apache/logging-log4j2/blob/6ddc0250cb6ebbf5f05d3026a976bc8ca0a8f162/log4j-core/src/test/java/org/apache/logging/log4j/core/async/perftest/PerfTestDriver.java> > class. This last one has parameters in the code. You'll need to spend some > time to get familiar with it if you want to run it. > > and perhaps to run a comparison against some real software - github does >> not lack for applications using log4j! Unfortunately I bet this would >> result in a much less sexy graph. >> > Log4j 2 has had lock-free Async Loggers from its 2.0-beta5 release > <http://logging.apache.org/log4j/2.x/changes-report.html#a2.0-beta5>, > three years ago. If there are any serious performance drawbacks like you > seem to think there are I hope I would have heard of them. Fortunately the > opposite is true. People report very positive experiences > <http://tech.finn.no/2014/07/01/log4j2-in-production-making-it-fly/>. > People who did their own measurements reported it makes their logging as > fast as if it was switched off > <http://blogs.mulesoft.com/dev/mule-dev/mule-3-6-asynchronous-logging/>. > > >> Finally, I really think people should (in your wiki page) explicitly be >> *discouraged* from using this part of your framework *unless they know >> they need it*. It's a fantastic piece of work for people who *do* need >> it. >> > Again, I think you are laboring under a misapprehension. I cannot imagine > a scenario where lock-free logging would be a bad thing. If you think there > is, please show evidence. > > >> But 99.99% of people would be better off with a logger that just avoids >> blocking threads when one is already in the process of logging. >> > Avoiding blocking is exactly what the Async Loggers are for. (So I really > think there is some misunderstanding somewhere.) > Based on your feedback, I've updated > <http://home.apache.org/~rpopma/log4j/2.6/manual/async.html> the side nav > menu and page title for the 2.6 release to clarify that Async Loggers are > lock-free. I hope this will help avoid misunderstandings. > > >> >> (*It looks like you silently ignore misconfiguration, and default to >> timeout wait strategy also, which is probably going to surprise some people) >> >> >> >> >> >> On 19 May 2016 at 00:34, Remko Popma <remko...@gmail.com> wrote: >> >>> Benedict, thanks for your feedback! >>> >>> With regards to filtering, global filters are already considered before >>> the event is enqueued. Filters configured on the Logger and AppenderRef are >>> applied prior to enqueueing with mixed Sync/Async >>> <http://logging.apache.org/log4j/2.x/manual/async.html#MixedSync-Async> >>> Loggers but when all loggers are async >>> <http://logging.apache.org/log4j/2.x/manual/async.html#AllAsync> these >>> filters are applied by the background thread. We can probably improve this, >>> thanks for the suggestion! >>> >>> Your suggestion to run performance tests under lower loads is reasonable >>> and we will look at this for a future release. >>> I did experiment with this a little a while back and did see larger >>> response time pauses. Perhaps others with more experience can chime in. >>> >>> My understanding of how the Disruptor works is that enqueueing the event >>> is lock-free, so applications threads doing the logging should not >>> experience any context switches or suffer latency from Futex calls caused >>> by logging (regardless of the workload). The background thread is another >>> story. Under moderate to low workloads the background thread may (depending >>> on the wait policy) fall asleep and experience delays before waking up when >>> work arrives. However, if there are enough cores to serve all threads I >>> don't see how such background thread delays can impact (cause response time >>> pauses for) the application that is doing the logging. Please correct me if >>> my understanding is incorrect. >>> >>> My thinking is that using async loggers is good for reactive >>> applications that need to respond quickly to external events. It is >>> especially useful if the application needs to deal with occasional bursts >>> of work (and accompanied bursts of logging). This is where async loggers >>> can deliver value even if the normal workload is low. >>> >>> Remko >>> >>> On Wednesday, May 18, 2016 at 2:56:18 AM UTC+9, Benedict Elliott Smith >>> wrote: >>>> >>>> Regrettably it seems impossible (or at least very annoying) to send to >>>> both lists simultaneously... >>>> >>>> On 17 May 2016 at 18:55, Benedict Elliott Smith <bene...@apache.org> >>>> wrote: >>>> >>>>> Could I suggest that you run tests for latency and throughput effects >>>>> of using this in systems with only moderate-to-low numbers of logging >>>>> calls? (i.e. the vast majority of systems!) >>>>> >>>> >>>>> It's very likely that in such systems messages will not reach a >>>>> velocity to keep the Dispatcher running, and so logging calls may often >>>>> (or >>>>> always) involve a Futex call - which is not a trivial cost. There will >>>>> almost certainly be systems out there with anti-ideal characteristics - >>>>> logging just often enough that these costs materially impact throughput, >>>>> but not often enough that they suddenly disappear. >>>>> >>>>> Even though a majority of systems *do not need this*, because it >>>>> "async" and the new hotness, and there are no advertised downsides, >>>>> everyone will try to use it. It's up to those who know better to make >>>>> sure >>>>> these people are informed it isn't a free lunch. Making sure all of the >>>>> caveats are reported on the advertising page would be a great start IMO. >>>>> >>>>> Might I also separately suggest you consider filtering events prior to >>>>> placing them on the queue for processing by the dispatcher? I've only >>>>> briefly glanced at the code, but it seems not to be the case currently. >>>>> >>>>>> >>>>>> On 17 May 2016 at 18:33, Martin Thompson <mjp...@gmail.com> wrote: >>>>>> >>>>>>> Hi Remko, >>>>>>> >>>>>>> I'd just like to say that it is a great service to the community as >>>>>>> a whole that someone is seriously looking at improving logging. >>>>>>> >>>>>>> If you keep it up you'll be putting folks like me out of a job :) >>>>>>> >>>>>>> Martin... >>>>>>> >>>>>>> >>>>>>> On 17 May 2016 at 18:13, Remko Popma <remko...@gmail.com> wrote: >>>>>>> >>>>>>>> Hi all, >>>>>>>> >>>>>>>> First, my thanks to the many people who gave helpful advice and >>>>>>>> feedback on how to measure Log4j response time on this list some time >>>>>>>> ago. >>>>>>>> >>>>>>>> We're about to start the Log4j 2.6 release. >>>>>>>> If anyone is interested, a preview of the garbage-free logging >>>>>>>> manual page is here: >>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/manual/garbagefree.html >>>>>>>> and a preview of the updated performance page is here: >>>>>>>> http://home.apache.org/~rpopma/log4j/2.6/performance.html >>>>>>>> >>>>>>>> Feedback welcome! >>>>>>>> >>>>>>>> Remko >>>>>>>> >>>>>>>> -- >>>>>>>> You received this message because you are subscribed to the Google >>>>>>>> Groups "mechanical-sympathy" group. >>>>>>>> To unsubscribe from this group and stop receiving emails from it, >>>>>>>> send an email to mechanical-sympathy+unsubscr...@googlegroups.com. >>>>>>>> For more options, visit https://groups.google.com/d/optout. >>>>>>>> >>>>>>> >>>>>>> -- >>>>>>> You received this message because you are subscribed to the Google >>>>>>> Groups "mechanical-sympathy" group. >>>>>>> To unsubscribe from this group and stop receiving emails from it, >>>>>>> send an email to mechanical-sympathy+unsubscr...@googlegroups.com. >>>>>>> For more options, visit https://groups.google.com/d/optout. >>>>>>> >>>>>> >>>>>> >>>>> >>>> >> -- > You received this message because you are subscribed to the Google Groups > "mechanical-sympathy" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to mechanical-sympathy+unsubscr...@googlegroups.com. > For more options, visit https://groups.google.com/d/optout. >
