Can the support for Intel TSX in Java 8u20 be relevant here? https://bugs.openjdk.java.net/browse/JDK-8031320
On Sun, May 22, 2016 at 5:40 PM, Remko Popma <[email protected]> wrote: > > > On Sunday, May 22, 2016 at 11:08:37 PM UTC+9, Benedict Elliott Smith wrote: >> >> 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. >> > > Well... Looks like you were right and I was wrong. > > Interesting. Apart from the dent in my pride here, this is actually good > news. It means we can do better! > > So in the worst-case scenario Async Loggers/Disruptor with the blocking > wait strategy give performance equivalent to AsyncAppender with a > BlockingArrayQueue. We can expect Async Loggers with Disruptor to > outperform AsyncAppender with BlockingArrayQueue when workloads are high or > bursts of work keep the background thread busy for some time. At least this > is my understanding now. Or did I miss something and are there cases where > Async Loggers with Disruptor will perform worse than AsyncAppender with > BlockingArrayQueue? > > In terms of how to improve, short-term we should probably look at using > the PhasedBackoffWaitStrategy as the default, although there will always be > workloads that "miss the window". The trade-off is increased CPU. We need > to tread carefully here because users reporting high CPU is why we changed > from the sleeping wait strategy to blocking. (The default in Log4j 2.6 will > be timeout blocking wait to deal with a deadlock issue in Solaris.) > > Long-term we should probably explore other data structures. > > Exciting times. Thanks for correcting me! > > >> >> On 22 May 2016 at 15:07, Benedict Elliott Smith <[email protected]> >> wrote: >> >>> 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 <[email protected]> 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 <[email protected]> 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 <[email protected]> >>>>>>> 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 <[email protected]> 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 <[email protected]> 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 >>>>>>>>>>> [email protected]. >>>>>>>>>>> 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 [email protected] >>>>>>>>>> . >>>>>>>>>> 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 [email protected]. >>>> For more options, visit https://groups.google.com/d/optout. >>>> >>> >>> >> > > --------------------------------------------------------------------- > To unsubscribe, e-mail: [email protected] > For additional commands, e-mail: [email protected] > -- [image: MagineTV] *Mikael Ståldal* Senior software developer *Magine TV* [email protected] Grev Turegatan 3 | 114 46 Stockholm, Sweden | www.magine.com Privileged and/or Confidential Information may be contained in this message. If you are not the addressee indicated in this message (or responsible for delivery of the message to such a person), you may not copy or deliver this message to anyone. In such case, you should destroy this message and kindly notify the sender by reply email.
