BatchEventProcessor.processEvents performance

[ghost]

While profiling a simple D-Bus-based application, I noticed the following:

     1764406    2.74%        1  OptoRuntime::handle_exception_C_helper(JavaThread*, nmethod*&)

The application is not in any failure scenario, so I would have expected that all messages could be processed without throwing exceptions. The exception handling is inside processEvents:

disruptor/src/main/java/com/lmax/disruptor/BatchEventProcessor.java

Line 156 in 305d737

private void processEvents()

The profile output shows:

--- 2116394 ns (3.28%), 1 sample
  [ 0] exit_to_usermode_loop_[k]
  [ 1] prepare_exit_to_usermode_[k]
  [ 2] swapgs_restore_regs_and_return_to_usermode_[k]
  [ 3] OptoRuntime::handle_exception_C_helper(JavaThread*, nmethod*&)
  [ 4] OptoRuntime::handle_exception_C(JavaThread*)
  [ 5] com.lmax.disruptor.BatchEventProcessor.processEvents
  [ 6] com.lmax.disruptor.BatchEventProcessor.run
  [ 7] java.lang.Thread.run

I don't know what particular exception is causing the exception catch clause to be invoked, if any, or if there's anything that can be changed to improve the performance. Feel free to close if nothing practical can be done.

The full async-profile log is attached.

dbus-2.log

[grumpyjames]

I also wouldn't expect exceptions to be thrown as part of 'standard' operation, although that definition of 'standard' is quite detailed.

One possibility is that you appear to be using a TimeoutBlockingWaitStrategy. That will use exceptions to get to L198-201 of BatchEventProcessor, when it sees a long enough duration where no events are available from the buffer. That's an interesting choice of wait strategy if you're after pure performance - do you do anything on timeout?

If it's not that, can you capture exactly what exception it is? We may be able to advise a little better with that information.

[ghost]

I could neither trace nor debug the raised exception. I did notice that Apache's log4j2 has re-implemented the TimeoutBlockingWaitStrategy to avoid throwing exceptions altogether:

https://github.com/apache/logging-log4j2/blob/e4e46f0667eb8473246ccc74ed6ede938cab0667/log4j-core/src/main/java/org/apache/logging/log4j/core/async/TimeoutBlockingWaitStrategy.java#L53

I don't know where in the code the disruptor classes are being called from. I suspect they're called from an indirect dependency, such as log4j2.

[grumpyjames]

That comment on L53 of the link says:

// The difference between this code and the implementation of this class in disruptor-3.4.4
// is that this class is garbage-free, because it uses a synchronized block instead of a ReentrantLock.

It still throws a TimeoutException on L88 - it has to, or it breaks the contract of how timeouts are implemented in BatchEventProcessor.

Is there anything else we can help with here? It feels like we are troubleshooting a performance issue based on an exception that's being raised (we think - we don't have any meaningful diagnostics, only a guess from me based on a profile with surprisingly few samples in it!) from a wait strategy which is deliberately not designed with throughput or latency in mind.

[grumpyjames]

Also, in case I haven't made it clear: that timeout exception is thrown when a ringbuffer consumer sees no events for a configured amount of time. We could probably rename all the timeout parts as "onTemporarilyIdle" or similar.

That rather suggests that the thread in question is probably not of that much interest to your profile anyway.

[ghost]

Closing as not applicable.