You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@camel.apache.org by Martin Lichtin <li...@yahoo.com.INVALID> on 2016/09/07 19:02:27 UTC
Camel context shutdown waiting for ExecutorService
Hi All
Having an issue with Camel context shutdown taking much longer than expected.
The trace below shows it quite well.
There's 2 seconds "graceful" shutdown, but then it takes 2x10 seconds to "really" shutdown.
Any ideas why that could be? Also, how can I reduce the 10 seconds termination timeout somewhere?
Thanks!
2016-09-07 10:11:42,456 | INFO | FelixStartLevel | DefaultCamelContext | e.camel.impl.DefaultCamelContext 3025 | 133 - org.apache.camel.camel-core - 2.16.3 | Apache Camel 2.16.3 (CamelContext: ch.bbp.fmp.inuc.adapterapi.framework.transport.BtxAdapterStd) is shutting down
2016-09-07 10:11:42,456 | INFO | FelixStartLevel | DefaultShutdownStrategy | mel.impl.DefaultShutdownStrategy 195 | 133 - org.apache.camel.camel-core - 2.16.3 | Starting to graceful shutdown 2 routes (timeout 2 seconds)
2016-09-07 10:11:44,456 | WARN | hread #59 - ShutdownTask | FailoverTransport | sport.failover.FailoverTransport 280 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport (nio://inucdev5:61616?wireFormat.cacheEnabled=false&wireFormat.tightEncodingEnabled=false) failed , attempting to automatically reconnect: java.nio.channels.ClosedByInterruptException
2016-09-07 10:11:44,456 | WARN | ActiveMQ NIO Worker 8 | Transport | ivemq.broker.TransportConnection 240 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport Connection to: tcp://172.22.55.5:56989 failed: java.io.EOFException
2016-09-07 10:11:44,457 | WARN | FelixStartLevel | DefaultShutdownStrategy | mel.impl.DefaultShutdownStrategy 230 | 133 - org.apache.camel.camel-core - 2.16.3 | Timeout occurred during graceful shutdown. Forcing the routes to be shutdown now. Notice: some resources may still be running as graceful shutdown did not complete successfully.
2016-09-07 10:11:44,457 | INFO | FelixStartLevel | DefaultShutdownStrategy | mel.impl.DefaultShutdownStrategy 259 | 133 - org.apache.camel.camel-core - 2.16.3 | Graceful shutdown of 2 routes completed in 2 seconds
2016-09-07 10:11:46,459 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 2.000 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
2016-09-07 10:11:46,460 | WARN | hread #59 - ShutdownTask | FailoverTransport | sport.failover.FailoverTransport 280 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport (nio://inucdev5:61616?wireFormat.cacheEnabled=false&wireFormat.tightEncodingEnabled=false) failed , attempting to automatically reconnect: java.nio.channels.ClosedByInterruptException
2016-09-07 10:11:46,460 | WARN | ActiveMQ NIO Worker 5 | Transport | ivemq.broker.TransportConnection 240 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport Connection to: tcp://172.22.55.5:56993 failed: java.io.EOFException
2016-09-07 10:11:48,460 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 4.001 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
2016-09-07 10:11:48,463 | WARN | hread #59 - ShutdownTask | FailoverTransport | sport.failover.FailoverTransport 280 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport (nio://inucdev5:61616?wireFormat.cacheEnabled=false&wireFormat.tightEncodingEnabled=false) failed , attempting to automatically reconnect: java.nio.channels.ClosedByInterruptException
2016-09-07 10:11:48,463 | WARN | ActiveMQ NIO Worker 2 | Transport | ivemq.broker.TransportConnection 240 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport Connection to: tcp://172.22.55.5:56994 failed: java.io.EOFException
2016-09-07 10:11:50,461 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 6.002 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
2016-09-07 10:11:50,466 | WARN | ActiveMQ NIO Worker 2 | Transport | ivemq.broker.TransportConnection 240 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport Connection to: tcp://172.22.55.5:56995 failed: java.io.EOFException
2016-09-07 10:11:50,467 | WARN | ActiveMQ NIO Worker 1 | FailoverTransport | sport.failover.FailoverTransport 280 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport (nio://inucdev5:61616?wireFormat.cacheEnabled=false&wireFormat.tightEncodingEnabled=false) failed , attempting to automatically reconnect: java.nio.channels.ClosedChannelException
2016-09-07 10:11:52,462 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 8.003 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
2016-09-07 10:11:54,459 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 10.000 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
2016-09-07 10:11:54,460 | WARN | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 305 | 133 - org.apache.camel.camel-core - 2.16.3 | Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] due first await termination elapsed.
2016-09-07 10:11:56,460 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 2.000 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
2016-09-07 10:11:58,461 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 4.001 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
2016-09-07 10:12:00,462 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 6.002 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
2016-09-07 10:12:02,463 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 8.003 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
2016-09-07 10:12:04,461 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 10.000 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
2016-09-07 10:12:04,461 | WARN | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 309 | 133 - org.apache.camel.camel-core - 2.16.3 | Cannot completely force shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] due second await termination elapsed.
2016-09-07 10:12:04,462 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 322 | 133 - org.apache.camel.camel-core - 2.16.3 | Shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] is shutdown: true and terminated: false took: 20.003 seconds.
2016-09-07 10:12:04,462 | WARN | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 463 | 133 - org.apache.camel.camel-core - 2.16.3 | Forced shutdown of 1 ExecutorService's which has not been shutdown properly (acting as fail-safe)
2016-09-07 10:12:04,463 | WARN | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 465 | 133 - org.apache.camel.camel-core - 2.16.3 | forced -> java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0]
2016-09-07 10:12:04,464 | INFO | FelixStartLevel | DefaultCamelContext | e.camel.impl.DefaultCamelContext 3110 | 133 - org.apache.camel.camel-core - 2.16.3 | Apache Camel 2.16.3 (CamelContext: ch.bbp.fmp.inuc.adapterapi.framework.transport.BtxAdapterStd) uptime 2 minutes
2016-09-07 10:12:04,464 | INFO | FelixStartLevel | DefaultCamelContext | e.camel.impl.DefaultCamelContext 3111 | 133 - org.apache.camel.camel-core - 2.16.3 | Apache Camel 2.16.3 (CamelContext: ch.bbp.fmp.inuc.adapterapi.framework.transport.BtxAdapterStd) is shutdown in 22.008 seconds
Re: Camel context shutdown waiting for ExecutorService
Posted by Quinn Stevenson <qu...@pronoia-solutions.com>.
Can you share a little more information? Like the route definition and how you’ve configured the Camel Context?
> On Sep 7, 2016, at 1:02 PM, Martin Lichtin <li...@yahoo.com.INVALID> wrote:
>
> Hi All
> Having an issue with Camel context shutdown taking much longer than expected.
> The trace below shows it quite well.
> There's 2 seconds "graceful" shutdown, but then it takes 2x10 seconds to "really" shutdown.
> Any ideas why that could be? Also, how can I reduce the 10 seconds termination timeout somewhere?
>
> Thanks!
>
> 2016-09-07 10:11:42,456 | INFO | FelixStartLevel | DefaultCamelContext | e.camel.impl.DefaultCamelContext 3025 | 133 - org.apache.camel.camel-core - 2.16.3 | Apache Camel 2.16.3 (CamelContext: ch.bbp.fmp.inuc.adapterapi.framework.transport.BtxAdapterStd) is shutting down
> 2016-09-07 10:11:42,456 | INFO | FelixStartLevel | DefaultShutdownStrategy | mel.impl.DefaultShutdownStrategy 195 | 133 - org.apache.camel.camel-core - 2.16.3 | Starting to graceful shutdown 2 routes (timeout 2 seconds)
> 2016-09-07 10:11:44,456 | WARN | hread #59 - ShutdownTask | FailoverTransport | sport.failover.FailoverTransport 280 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport (nio://inucdev5:61616?wireFormat.cacheEnabled=false&wireFormat.tightEncodingEnabled=false) failed , attempting to automatically reconnect: java.nio.channels.ClosedByInterruptException
> 2016-09-07 10:11:44,456 | WARN | ActiveMQ NIO Worker 8 | Transport | ivemq.broker.TransportConnection 240 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport Connection to: tcp://172.22.55.5:56989 failed: java.io.EOFException
> 2016-09-07 10:11:44,457 | WARN | FelixStartLevel | DefaultShutdownStrategy | mel.impl.DefaultShutdownStrategy 230 | 133 - org.apache.camel.camel-core - 2.16.3 | Timeout occurred during graceful shutdown. Forcing the routes to be shutdown now. Notice: some resources may still be running as graceful shutdown did not complete successfully.
> 2016-09-07 10:11:44,457 | INFO | FelixStartLevel | DefaultShutdownStrategy | mel.impl.DefaultShutdownStrategy 259 | 133 - org.apache.camel.camel-core - 2.16.3 | Graceful shutdown of 2 routes completed in 2 seconds
> 2016-09-07 10:11:46,459 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 2.000 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
> 2016-09-07 10:11:46,460 | WARN | hread #59 - ShutdownTask | FailoverTransport | sport.failover.FailoverTransport 280 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport (nio://inucdev5:61616?wireFormat.cacheEnabled=false&wireFormat.tightEncodingEnabled=false) failed , attempting to automatically reconnect: java.nio.channels.ClosedByInterruptException
> 2016-09-07 10:11:46,460 | WARN | ActiveMQ NIO Worker 5 | Transport | ivemq.broker.TransportConnection 240 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport Connection to: tcp://172.22.55.5:56993 failed: java.io.EOFException
> 2016-09-07 10:11:48,460 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 4.001 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
> 2016-09-07 10:11:48,463 | WARN | hread #59 - ShutdownTask | FailoverTransport | sport.failover.FailoverTransport 280 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport (nio://inucdev5:61616?wireFormat.cacheEnabled=false&wireFormat.tightEncodingEnabled=false) failed , attempting to automatically reconnect: java.nio.channels.ClosedByInterruptException
> 2016-09-07 10:11:48,463 | WARN | ActiveMQ NIO Worker 2 | Transport | ivemq.broker.TransportConnection 240 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport Connection to: tcp://172.22.55.5:56994 failed: java.io.EOFException
> 2016-09-07 10:11:50,461 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 6.002 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
> 2016-09-07 10:11:50,466 | WARN | ActiveMQ NIO Worker 2 | Transport | ivemq.broker.TransportConnection 240 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport Connection to: tcp://172.22.55.5:56995 failed: java.io.EOFException
> 2016-09-07 10:11:50,467 | WARN | ActiveMQ NIO Worker 1 | FailoverTransport | sport.failover.FailoverTransport 280 | 126 - org.apache.activemq.activemq-osgi - 5.14.0 | Transport (nio://inucdev5:61616?wireFormat.cacheEnabled=false&wireFormat.tightEncodingEnabled=false) failed , attempting to automatically reconnect: java.nio.channels.ClosedChannelException
> 2016-09-07 10:11:52,462 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 8.003 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
> 2016-09-07 10:11:54,459 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 10.000 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
> 2016-09-07 10:11:54,460 | WARN | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 305 | 133 - org.apache.camel.camel-core - 2.16.3 | Forcing shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] due first await termination elapsed.
> 2016-09-07 10:11:56,460 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 2.000 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
> 2016-09-07 10:11:58,461 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 4.001 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
> 2016-09-07 10:12:00,462 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 6.002 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
> 2016-09-07 10:12:02,463 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 8.003 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
> 2016-09-07 10:12:04,461 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 405 | 133 - org.apache.camel.camel-core - 2.16.3 | Waited 10.000 seconds for ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] to terminate...
> 2016-09-07 10:12:04,461 | WARN | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 309 | 133 - org.apache.camel.camel-core - 2.16.3 | Cannot completely force shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] due second await termination elapsed.
> 2016-09-07 10:12:04,462 | INFO | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 322 | 133 - org.apache.camel.camel-core - 2.16.3 | Shutdown of ExecutorService: java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0] is shutdown: true and terminated: false took: 20.003 seconds.
> 2016-09-07 10:12:04,462 | WARN | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 463 | 133 - org.apache.camel.camel-core - 2.16.3 | Forced shutdown of 1 ExecutorService's which has not been shutdown properly (acting as fail-safe)
> 2016-09-07 10:12:04,463 | WARN | FelixStartLevel | DefaultExecutorServiceManager | pl.DefaultExecutorServiceManager 465 | 133 - org.apache.camel.camel-core - 2.16.3 | forced -> java.util.concurrent.ThreadPoolExecutor@413001bd[Shutting down, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0]
> 2016-09-07 10:12:04,464 | INFO | FelixStartLevel | DefaultCamelContext | e.camel.impl.DefaultCamelContext 3110 | 133 - org.apache.camel.camel-core - 2.16.3 | Apache Camel 2.16.3 (CamelContext: ch.bbp.fmp.inuc.adapterapi.framework.transport.BtxAdapterStd) uptime 2 minutes
> 2016-09-07 10:12:04,464 | INFO | FelixStartLevel | DefaultCamelContext | e.camel.impl.DefaultCamelContext 3111 | 133 - org.apache.camel.camel-core - 2.16.3 | Apache Camel 2.16.3 (CamelContext: ch.bbp.fmp.inuc.adapterapi.framework.transport.BtxAdapterStd) is shutdown in 22.008 seconds