[ 
https://issues.apache.org/jira/browse/CAMEL-11750?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16156665#comment-16156665
 ] 

ASF GitHub Bot commented on CAMEL-11750:
----------------------------------------

GitHub user leofromgroza opened a pull request:

    https://github.com/apache/camel/pull/1922

    CAMEL-11750: Camel route with multicast (parallel) generate huge CPU …

    …load
    
    Fixed issue with huge CPU load: added 1 second delay for a task that is 2nd 
in the queue order, 2sec for 3rd task, 3sec for 4th taks, etc. That helps to 
decrease CPU load and does not broke previous logic.

You can merge this pull request into a Git repository by running:

    $ git pull https://github.com/leofromgroza/camel patch-1

Alternatively you can review and apply these changes as the patch at:

    https://github.com/apache/camel/pull/1922.patch

To close this pull request, make a commit to your master/trunk branch
with (at least) the following in the commit message:

    This closes #1922
    
----
commit 089b64ae85d76230d647eb646d806400e1df4b21
Author: leofromgroza <[email protected]>
Date:   2017-09-07T08:15:02Z

    CAMEL-11750: Camel route with multicast (parallel) generate huge CPU load
    
    Fixed issue with huge CPU load: added 1 second delay for a task that is 2nd 
in the queue order, 2sec for 3rd task, 3sec for 4th taks, etc. That helps to 
decrease CPU load and does not broke previous logic.

----


> Camel route with multicast (parallel) generate huge CPU load
> ------------------------------------------------------------
>
>                 Key: CAMEL-11750
>                 URL: https://issues.apache.org/jira/browse/CAMEL-11750
>             Project: Camel
>          Issue Type: Bug
>          Components: camel-core
>            Reporter: Nazar Vishka
>            Priority: Critical
>
> I've created simple [Spring Camel Route 
> application|https://github.com/leofromgroza/camel-long-term-route] that can 
> be used for issue reproducing. Here we have very simple route:
> {code}
>     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();
>     }{code}
> 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%):
> !https://content.screencast.com/users/NazarV/folders/Jing/media/830268f0-d184-4c57-adb1-b782ea63fa6d/2017-09-06_1241.png!
> 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):
> {code}"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){code}
> In DelayQueue#poll(long, java.util.concurrent.TimeUnit) we have a piece of 
> code:
> {code}E first = q.peek();
> if (first == null) {
>  ...
> } else {
>   long delay = first.getDelay(NANOSECONDS);
>     ...
>   long timeLeft =  available.awaitNanos(delay) {code}
> During debugging I found that E first is object of class 
> [org.apache.camel.util.concurrent.SubmitOrderedCompletionService.SubmitOrderFutureTask|https://github.com/apache/camel/blob/camel-2.19.2/camel-core/src/main/java/org/apache/camel/util/concurrent/SubmitOrderedCompletionService.java]
>  and it's very interesting [getDelay(TimeUnit) 
> method|https://github.com/apache/camel/blob/camel-2.19.2/camel-core/src/main/java/org/apache/camel/util/concurrent/SubmitOrderedCompletionService.java#L64]
>  always return 1. I thing that is a source of current issue:
> {code} public long getDelay(TimeUnit unit) {
>             // if the answer is 0 then this task is ready to be taken
>             return id - index.get();
>         }{code}
> 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|https://github.com/apache/camel/blob/camel-2.19.2/camel-core/src/main/java/org/apache/camel/util/concurrent/SubmitOrderedCompletionService.java#L64]
>  should be somehow re-implemented.



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)

Reply via email to