Details
-
Bug
-
Status: Resolved
-
Critical
-
Resolution: Fixed
-
2.18.4, 2.19.2
-
None
-
Unknown
Description
I've created simple Spring Camel Route application that can be used for issue reproducing. Here we have very simple route:
public void configure() throws Exception {
from("direct:start").routeId("start")
.multicast().parallelProcessing()
.to("direct:very-long-task", "direct:long-task")
.end();
from("direct:long-task").routeId("long-task")
.log("Started long-task")
.process(exchange -> Thread.sleep(5000))
.log("Finished long-task")
.end();
from("direct:very-long-task").routeId("very-long-task")
.log("Started very-long-task")
.process(exchange -> Thread.sleep(35000))
.log("Finished very-long-task")
.end();
}
From our main route 'start' we are starting in parallel two sub-routes: 'long-task' and 'very-long-task'. They are just doing something for some period of time and do not generate any load to the system.
But I found that when one task finished earlier than other one, route start to make a huge CPU load. Here you can see a CPU usage during executiong of Camel route that was mentioned earlier (after finishing of 'long-task' usage of CPU uncreased from 0 to 12.5%):
Screenshot was made when I was running route on my Windows PC with 4 physical CPU cores + 4 HT. On Unix systems we found that after end of 'long-task' it used 100% of one core till the end of work.
One more interesting thing that i've found is that the main load on the system was generated by the thread MulticastProcessor-AggregateTask that was spending a lot of time in the method java.util.concurrent.locks.AbstractQueuedSynchronizer.ConditionObject#awaitNanos that was called from java.util.concurrent.DelayQueue#poll(long, java.util.concurrent.TimeUnit):
"Camel (camel-1) thread #2 - MulticastProcessor-AggregateTask" #29 daemon prio=5 os_prio=0 tid=0x00000000215e3000 nid=0x7a0 runnable [0x0000000022eaf000] java.lang.Thread.State: RUNNABLE at java.lang.Thread.isInterrupted(Native Method) at java.lang.Thread.interrupted(Thread.java:944) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.checkInterruptWhileWaiting(AbstractQueuedSynchronizer.java:2002) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2079) at java.util.concurrent.DelayQueue.poll(DelayQueue.java:273) at org.apache.camel.util.concurrent.SubmitOrderedCompletionService.poll(SubmitOrderedCompletionService.java:127) at org.apache.camel.processor.MulticastProcessor$AggregateOnTheFlyTask.aggregateOnTheFly(MulticastProcessor.java:463) at org.apache.camel.processor.MulticastProcessor$AggregateOnTheFlyTask.run(MulticastProcessor.java:418) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at java.lang.Thread.run(Thread.java:745)
In DelayQueue#poll(long, java.util.concurrent.TimeUnit) we have a piece of code:
E first = q.peek(); if (first == null) { ... } else { long delay = first.getDelay(NANOSECONDS); ... long timeLeft = available.awaitNanos(delay)
During debugging I found that E first is object of class org.apache.camel.util.concurrent.SubmitOrderedCompletionService.SubmitOrderFutureTask and it's very interesting getDelay(TimeUnit) method always return 1. I thing that is a source of current issue:
public long getDelay(TimeUnit unit) { // if the answer is 0 then this task is ready to be taken return id - index.get(); }
So when delay is 1, AggregateTask thread is not sleeping at all and generates a huge CPU load all the time when it is waiting for the end of the last task.
I think that getDelay(TimeUnit) method should be somehow re-implemented.
