Uploaded image for project: 'Camel'
  1. Camel
  2. CAMEL-11750

Camel route with multicast (parallel) generate huge CPU load

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Resolved
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 2.18.4, 2.19.2
    • Fix Version/s: 2.18.5, 2.19.3, 2.20.0
    • Component/s: camel-core
    • Labels:
      None
    • Estimated Complexity:
      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.

        Attachments

          Activity

            People

            • Assignee:
              davsclaus Claus Ibsen
              Reporter:
              Nazar Vishka Nazar Vishka
            • Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Time Tracking

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - 0h
                0h
                Logged:
                Time Spent - 40m
                40m