Springboot gets stuck shutting down metricsExecutor bean, type ExecutorService

2
votes

I'm using Springboot 1.2.6-RELEASE on Java 8, trying to shutdown using the /shutdown endpoint, but the shutdown sequence gets stuck here (last log entry):

2015-12-09 13:27:56,607 INFO  ThreadPoolTaskExecutor - Shutting down ExecutorService 'metricsExecutor'

metricsExecutor appears to be a springboot administered object, so I'd expect its shutdown to be handled implicitly without me getting involved.

"bean": "metricsExecutor",
"scope": "singleton",
"type": "org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor",
"resource": "class path resource [org/springframework/boot/actuate/autoconfigure/MetricRepositoryAutoConfiguration$MetricsChannelConfiguration.class]",
"dependencies": []

Do I need to shutdown this component explicitly with a shutdown hook?

Update

A bit more background info, I'm using Apache Camel with ActiveMQ. To shutdown a running process, I first stop my Camel routes from JMX; that part works. The last step uses Springboot's http://../shutdown to stop the JVM, and that's where it gets stuck, but I can reproduce the error based on my observations:

If I configure ActiveMQ with "pooled" connections, Springboot hangs and does not shutdown:

spring.activemq.broker-url=tcp://mqserver:61101
spring.activemq.user=admin
spring.activemq.password=password
spring.activemq.pooled=true

Set pooling to false, and now the JVM shuts down cleanly:

spring.activemq.pooled=false

Full Thread Dump

2015-12-10 10:53:29
Full thread dump Java HotSpot(TM) Client VM (25.51-b03 mixed mode):

"RMI TCP Connection(7)-10.8.218.91" #38 daemon prio=5 os_prio=0 tid=0x17bc2400 nid=0x1970 runnable [0x1b4bf000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(Unknown Source)
    at java.net.SocketInputStream.read(Unknown Source)
    at java.net.SocketInputStream.read(Unknown Source)
    at java.io.BufferedInputStream.fill(Unknown Source)
    at java.io.BufferedInputStream.read(Unknown Source)
    - locked <0x05989770> (a java.io.BufferedInputStream)
    at java.io.FilterInputStream.read(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$255(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$8/8397388.run(Unknown Source)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)

"RMI TCP Connection(6)-10.8.218.91" #37 daemon prio=5 os_prio=0 tid=0x17bc1c00 nid=0xa80 waiting on condition [0x1b2be000]
   java.lang.Thread.State: RUNNABLE
    at sun.management.DiagnosticCommandImpl.executeDiagnosticCommand(Native Method)
    at sun.management.DiagnosticCommandImpl.access$000(Unknown Source)
    at sun.management.DiagnosticCommandImpl$Wrapper.execute(Unknown Source)
    at sun.management.DiagnosticCommandImpl.invoke(Unknown Source)
    at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(Unknown Source)
    at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(Unknown Source)
    at javax.management.remote.rmi.RMIConnectionImpl.doOperation(Unknown Source)
    at javax.management.remote.rmi.RMIConnectionImpl.access$300(Unknown Source)
    at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(Unknown Source)
    at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(Unknown Source)
    at javax.management.remote.rmi.RMIConnectionImpl.invoke(Unknown Source)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at sun.rmi.server.UnicastServerRef.dispatch(Unknown Source)
    at sun.rmi.transport.Transport$1.run(Unknown Source)
    at sun.rmi.transport.Transport$1.run(Unknown Source)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.Transport.serviceCall(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$255(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$8/8397388.run(Unknown Source)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)

"ActiveMQ InactivityMonitor Worker" #36 daemon prio=5 os_prio=0 tid=0x17bc1800 nid=0x1870 waiting on condition [0x1b50f000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x0cd2ebc8> (a java.util.concurrent.SynchronousQueue$TransferStack)
    at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
    at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(Unknown Source)
    at java.util.concurrent.SynchronousQueue$TransferStack.transfer(Unknown Source)
    at java.util.concurrent.SynchronousQueue.poll(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)

"RMI TCP Connection(3)-10.8.218.91" #35 daemon prio=5 os_prio=0 tid=0x17bc1000 nid=0x25ac in Object.wait() [0x1a41e000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x0ceeff38> (a com.sun.jmx.remote.internal.ArrayNotificationBuffer)
    at com.sun.jmx.remote.internal.ArrayNotificationBuffer.fetchNotifications(Unknown Source)
    - locked <0x0ceeff38> (a com.sun.jmx.remote.internal.ArrayNotificationBuffer)
    at com.sun.jmx.remote.internal.ArrayNotificationBuffer$ShareBuffer.fetchNotifications(Unknown Source)
    at com.sun.jmx.remote.internal.ServerNotifForwarder.fetchNotifs(Unknown Source)
    at javax.management.remote.rmi.RMIConnectionImpl$4.run(Unknown Source)
    at javax.management.remote.rmi.RMIConnectionImpl$4.run(Unknown Source)
    at javax.management.remote.rmi.RMIConnectionImpl.fetchNotifications(Unknown Source)
    at sun.reflect.GeneratedMethodAccessor127.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at sun.rmi.server.UnicastServerRef.dispatch(Unknown Source)
    at sun.rmi.transport.Transport$1.run(Unknown Source)
    at sun.rmi.transport.Transport$1.run(Unknown Source)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.Transport.serviceCall(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$255(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$8/8397388.run(Unknown Source)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)

"JMX server connection timeout 34" #34 daemon prio=5 os_prio=0 tid=0x17bc0c00 nid=0x1dbc in Object.wait() [0x1a7df000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x0cef0448> (a [I)
    at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(Unknown Source)
    - locked <0x0cef0448> (a [I)
    at java.lang.Thread.run(Unknown Source)

"RMI Scheduler(0)" #32 daemon prio=5 os_prio=0 tid=0x17bbfc00 nid=0x1cb0 waiting on condition [0x19fff000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x09d787e0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
    at java.util.concurrent.locks.LockSupport.parkNanos(Unknown Source)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(Unknown Source)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.getTask(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)

"ActiveMQ InactivityMonitor WriteCheckTimer" #24 daemon prio=5 os_prio=0 tid=0x17bbd000 nid=0x25bc in Object.wait() [0x18eaf000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x0cd320a8> (a java.util.TaskQueue)
    at java.util.TimerThread.mainLoop(Unknown Source)
    - locked <0x0cd320a8> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Unknown Source)

"ActiveMQ Transport: tcp://dvdrmq1.den.ofi.com/172.17.40.179:61101@37723" #22 prio=5 os_prio=0 tid=0x17bbc400 nid=0x163c runnable [0x19daf000]
   java.lang.Thread.State: RUNNABLE
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.socketRead(Unknown Source)
    at java.net.SocketInputStream.read(Unknown Source)
    at java.net.SocketInputStream.read(Unknown Source)
    at org.apache.activemq.transport.tcp.TcpBufferedInputStream.fill(TcpBufferedInputStream.java:50)
    at org.apache.activemq.transport.tcp.TcpTransport$2.fill(TcpTransport.java:609)
    at org.apache.activemq.transport.tcp.TcpBufferedInputStream.read(TcpBufferedInputStream.java:58)
    at org.apache.activemq.transport.tcp.TcpTransport$2.read(TcpTransport.java:594)
    at java.io.DataInputStream.readInt(Unknown Source)
    at org.apache.activemq.openwire.OpenWireFormat.unmarshal(OpenWireFormat.java:258)
    at org.apache.activemq.transport.tcp.TcpTransport.readCommand(TcpTransport.java:221)
    at org.apache.activemq.transport.tcp.TcpTransport.doRun(TcpTransport.java:213)
    at org.apache.activemq.transport.tcp.TcpTransport.run(TcpTransport.java:196)
    at java.lang.Thread.run(Unknown Source)

"ActiveMQ InactivityMonitor ReadCheckTimer" #21 daemon prio=5 os_prio=0 tid=0x17bbc000 nid=0x2234 in Object.wait() [0x15c9f000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x0cd34910> (a java.util.TaskQueue)
    at java.util.TimerThread.mainLoop(Unknown Source)
    - locked <0x0cd34910> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Unknown Source)

"DestroyJavaVM" #14 prio=5 os_prio=0 tid=0x0048d000 nid=0x13b4 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"RMI TCP Accept-0" #11 daemon prio=5 os_prio=0 tid=0x150a9000 nid=0x598 runnable [0x1551f000]
   java.lang.Thread.State: RUNNABLE
    at java.net.DualStackPlainSocketImpl.accept0(Native Method)
    at java.net.DualStackPlainSocketImpl.socketAccept(Unknown Source)
    at java.net.AbstractPlainSocketImpl.accept(Unknown Source)
    at java.net.PlainSocketImpl.accept(Unknown Source)
    - locked <0x09ef7858> (a java.net.SocksSocketImpl)
    at java.net.ServerSocket.implAccept(Unknown Source)
    at java.net.ServerSocket.accept(Unknown Source)
    at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)

"RMI TCP Accept-1099" #10 daemon prio=5 os_prio=0 tid=0x15098000 nid=0x1f50 runnable [0x15a6f000]
   java.lang.Thread.State: RUNNABLE
    at java.net.DualStackPlainSocketImpl.accept0(Native Method)
    at java.net.DualStackPlainSocketImpl.socketAccept(Unknown Source)
    at java.net.AbstractPlainSocketImpl.accept(Unknown Source)
    at java.net.PlainSocketImpl.accept(Unknown Source)
    - locked <0x09ef7bc0> (a java.net.SocksSocketImpl)
    at java.net.ServerSocket.implAccept(Unknown Source)
    at java.net.ServerSocket.accept(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)

"RMI TCP Accept-0" #9 daemon prio=5 os_prio=0 tid=0x1509c800 nid=0x1cd8 runnable [0x1569f000]
   java.lang.Thread.State: RUNNABLE
    at java.net.DualStackPlainSocketImpl.accept0(Native Method)
    at java.net.DualStackPlainSocketImpl.socketAccept(Unknown Source)
    at java.net.AbstractPlainSocketImpl.accept(Unknown Source)
    at java.net.PlainSocketImpl.accept(Unknown Source)
    - locked <0x09ef7f28> (a java.net.SocksSocketImpl)
    at java.net.ServerSocket.implAccept(Unknown Source)
    at java.net.ServerSocket.accept(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(Unknown Source)
    at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)

"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x14f38800 nid=0x2900 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x14f32000 nid=0x2574 waiting on condition [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x020bf800 nid=0x1c6c runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x020be800 nid=0x1aa0 runnable [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x020aec00 nid=0x2514 in Object.wait() [0x14dcf000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x09ef87f8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(Unknown Source)
    - locked <0x09ef87f8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(Unknown Source)
    at java.lang.ref.Finalizer$FinalizerThread.run(Unknown Source)

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x020a9000 nid=0x1184 in Object.wait() [0x14e2f000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x09ef8998> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Unknown Source)
    at java.lang.ref.Reference$ReferenceHandler.run(Unknown Source)
    - locked <0x09ef8998> (a java.lang.ref.Reference$Lock)

"VM Thread" os_prio=2 tid=0x020a5400 nid=0x2508 runnable 

"VM Periodic Task Thread" os_prio=2 tid=0x150ab000 nid=0x29d8 waiting on condition 

JNI global references: 255
1
javaspringspring-bootspring-boot-actuator
Can you take a thread dump when it's stuck and share the output? – Andy Wilkinson
Added stack trace and how to reproduce – raffian

1 Answers

1
votes

This looks like a bug in Spring Boot. I've opened an issue.

In the meantime you can work around the problem by declaring your own bean for the connection factory and annotating it so that the pool is stopped when the application context is shutting down:

@Bean(destroyMethod = "stop")
public PooledConnectionFactory pooledJmsConnectionFactory() {
    PooledConnectionFactory pooledConnectionFactory = new PooledConnectionFactory();
    pooledConnectionFactory.setConnectionFactory(…);
    return pooledConnectionFactory;
}