Processing of event listener yielded

Hi,

When we run our application under a heavy load, sometimes we see this being logged out over and over again in our application log by each one of our event bus threads:

2015-07-28 14:55:48,050 INFO [eventBusExecutor-10] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:55:50,281 INFO [eventBusExecutor-8] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:55:51,757 INFO [eventBusExecutor-5] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:55:53,869 INFO [eventBusExecutor-7] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:55:55,980 INFO [eventBusExecutor-9] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:55:58,706 INFO [eventBusExecutor-4] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:00,773 INFO [eventBusExecutor-3] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:00,870 INFO [eventBusExecutor-1] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:02,222 INFO [eventBusExecutor-10] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:04,408 INFO [eventBusExecutor-8] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:06,520 INFO [eventBusExecutor-8] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:08,614 INFO [eventBusExecutor-7] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:08,912 INFO [eventBusExecutor-2] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:10,754 INFO [eventBusExecutor-9] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:12,841 INFO [eventBusExecutor-3] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:14,252 INFO [eventBusExecutor-1] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:16,383 INFO [eventBusExecutor-10] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:18,458 INFO [eventBusExecutor-5] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:20,573 INFO [eventBusExecutor-8] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:22,648 INFO [eventBusExecutor-7] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:24,131 INFO [eventBusExecutor-4] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:25,280 INFO [eventBusExecutor-6] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:26,163 INFO [eventBusExecutor-9] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:28,306 INFO [eventBusExecutor-1] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 14:56:30,428 INFO [eventBusExecutor-10] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded.

And while this is happening, the process our application is trying to perform stops.

The process we are running involves dispatching a number of commands which then result in a number of events being applied. When we see this in the error logs, nothing at all seems to be happening in that process, i.e. no commands are being handled and no events seem to be being handled. It is even stranger by the fact that the dispatching of the commands is done via a different thread to any of the event bus threads.

We’ve analysed the performance profile of the application and there are no issues with memory or disk usage - we are nowhere near utilising the capacity of the machines this is running on.

My questions are:

  1. What does this ‘yielding’ mean in this context?
  2. What could be causing this?
  3. What can we do to help us identify what is causing this because at the moment we are struggling.
    Thanks for your help in advance.

Chris

Hi Chris,

in this case, yielding means that the EventProcessor put itself back on the queue of the Executor, so that the thread can be used to process another batch of events. It’s a very harmless message, just indicating that a batch of events was completed, but new events have been put on that section of the queue for processing. These new events will be picked up in the next batch, after the thread has been given the opportunity to process other batches.

What do you mean with “Nothing else seems to be happening in that process?”.

Just wondering, what version of Axon do you use? The EventProcessingScheduler was renamed in Axon 2 to EventProcessor.

Cheers,

Allard

Hi Allard,

We have a system which is bringing a large volume of objects into it. We dispatch a command which is then handled, the handling creates an aggregate root and stores that aggregate root in a repository. The creation of that aggregate root applies a number of events which are handled to update views.

This process happens as expected for a period of time and we can see this in the logs:

2015-07-28 13:53:10,245 INFO [quartzSchedulerStaticPollers_Worker-4] command.handler.ObjectCommandHandler: In ObjectManagementHandler.handle(AddUploadedObjectCommand command) 2015-07-28 13:53:10,245 INFO [quartzSchedulerStaticPollers_Worker-4] command.handler.ObjectCommandHandler: objectId: 77067361-cb65-44fe-bb58-28b96d0b6986 2015-07-28 13:53:10,255 INFO [quartzSchedulerStaticPollers_Worker-4] command.handler.ObjectCommandHandler: Adding new Object with ID: 77067361-cb65-44fe-bb58-28b96d0b6986

The final line is as a result of the handling of the event and shows that the view is updated. We can verify that the object is created by looking at the UI which accesses the view.

Then, in the logs this stops and we see:

2015-07-28 13:53:32,511 INFO [eventBusExecutor-6] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 13:53:34,157 INFO [eventBusExecutor-8] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 13:53:35,878 INFO [eventBusExecutor-3] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 13:53:37,499 INFO [eventBusExecutor-9] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 13:53:38,709 INFO [eventBusExecutor-5] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 13:53:40,448 INFO [eventBusExecutor-4] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 13:53:42,123 INFO [eventBusExecutor-10] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded. 2015-07-28 13:53:42,450 INFO [eventBusExecutor-7] axonframework.eventhandling.EventProcessingScheduler: Processing of event listener yielded.

And this goes on for about half an hour. During this time, we see no commands being handled and nothing in the view being updated.

Is it normal to see this yielding going on for so long? If we are saying that it is done to allow the thread to process another batch of events why do they yield for so long without actually doing any processing?

We are currently using Axon 1.3.2.

Cheers,

Chris

Hi Chris,

as mentioned in another thread, I strongly suggest updating to a more recent version of Axon. Many improvements have been made in the Asynchronous handling of events, so it’s likely that this issue will disappear when upgrading.

Cheers,

Allard