Hi Chris,
Thank you for the quick reply.
Simon,
On 11/30/21 08:21, Simon Matter wrote:
I'm running an application on Tomcat 9.0.55 on x86_64 Linux with OpenJDK
JRE-11.0.13+8 and have problems shutting down Tomcat in certain ways.
When I shutdown Tomcat via 'catalina.sh stop', it shuts down mostly
(most
threads are gone) but send a thread dump to catalina.out and is later
killer by an OS signal.
This should only happen if you have CATALINA_PID defined. Are you indeed
defining that environment variable?
catalina.sh has this code in it, which is probably what you are seeing:
echo "To aid diagnostics a thread dump has been written to
standard out."
kill -3 `cat "$CATALINA_PID"`
That's true, I have CATALINA_PID defined when the call of "catalina.sh
start" is done. So yes, the script will kill the java process if it
doesn't terminate.
When shutting down Tomcat via the shutdown listener on port 8005, it
also
shuts down mostly but without the thread dump in catalina.out. Sending
SIGTERM later to the still running java process terminates it.
Right: when you manually connect to the shutdown port and send
"SHUTDOWN" (or whatever), it asks Tomcat to shut down but doesn't send a
signal. You have to do that manually, too.
On a test host, when I send "SHUTDOWN" to the shutdown listener, Tomcat
shuts down and the Java VM terminates.
Only on this host with the application, when I send "SHUTDOWN" to the
shutdown listener, Tomcat shuts down but the Java VM doesn't terminate.
So both methods somehow terminate Tomcat partly but not completely.
You have one or two of the following issues:
1. You have a non-daemon thread running
2. You have an unusually long shutdown process that just takes "too long"
The good news is that the thread-dup can answer that question: what's in
the thread dump that is generated when you run "catalina.sh stop"?
When simply sending SIGTERM on the OS level, Tomcat shuts down cleanly
and
terminates without issues.
One thing in common is that I always see these messages while shutting
down:
30-Nov-2021 13:59:36.985 SEVERE [main]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesRmiTargets
Found RMI Target with stub class class
[sun.rmi.registry.RegistryImpl_Stub] and value
[RegistryImpl_Stub[UnicastRef [liveRef:
[endpoint:[157.161.91.47:2071](local),objID:[0:0:0, 0]]]]]. This RMI
Target has been forcibly removed to prevent a memory leak.
30-Nov-2021 13:59:36.987 SEVERE [main]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesRmiTargets
Found RMI Target with stub class class [com.sun.proxy.$Proxy51] and
value
[Proxy[ShopdbCacheSynchronizer,RemoteObjectInvocationHandler[UnicastRef
[liveRef:
[endpoint:[157.161.91.47:1096](local),objID:[-6f4b2f9d:17d70eb1ef4:-7ffd,
-4005526521234186948]]]]]]. This RMI Target has been forcibly removed to
prevent a memory leak.
30-Nov-2021 13:59:36.987 SEVERE [main]
org.apache.catalina.loader.WebappClassLoaderBase.clearReferencesRmiTargets
Found RMI Target with stub class class
[sun.rmi.registry.RegistryImpl_Stub] and value
[RegistryImpl_Stub[UnicastRef [liveRef:
[endpoint:[157.161.91.47:1096](local),objID:[0:0:0, 0]]]]]. This RMI
Target has been forcibly removed to prevent a memory leak.
Why do the three methods to shutdown Tomcat differ and how can I make
'catalina.sh stop' or the shutdown listener work the same way like
sending
the OS signal.
What's the difference? You don't want the thread dump in your
catalina.out? That's supposed to be helpful in debugging why your
shutdown isn't clean. It sounds like you are saying "help me with my
unclean shutdown; please get rid of the debugging information that is
trying to help me!".
I've tried, beside a lot of other things, to set
skipMemoryLeakChecksOnJvmShutdown="true" in context.xml but it seems to
change nothing at all.
Tomcat will never kill your non-daemon thread(s) from inside the VM.
Since you are using a CATALINA_PID environment variable (and, therefore,
a pid-file), the shutdown process is sending the TERM signal. It's also
possibly sending a KILL signal, depending on whether or not the TERM
worked and if -force was supplied on the command-line.
Unfortunately I am not an insider when it comes to Java, so I'm not sure
what a non-daemon thread means here? Can these be threads started by our
application which are non-daemon threads? So they will be terminated with
SIGTERM to the Java VM but not using the shutdown listener?
I'll paste a thread dump below.
Thanks,
Simon
Full thread dump OpenJDK 64-Bit Server VM (11.0.13+8 mixed mode):
Threads class SMR info:
_java_thread_list=0x000055a49ac4ba60, length=18, elements={
0x00007f1ac0148800, 0x00007f1ac014a800, 0x00007f1ac015f800,
0x00007f1ac0161800,
0x00007f1ac0164000, 0x00007f1ac0168800, 0x00007f1ac016a000,
0x00007f1ac01ad800,
0x00007f1ac0258000, 0x00007f1ac0311000, 0x00007f1ac0318000,
0x00007f1ac031a000,
0x00007f1ac25d6800, 0x00007f1ac25fe800, 0x00007f1ac2600000,
0x00007f1ac1dd9000,
0x00007f1a68809000, 0x00007f1ac2111800
}
"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=15.74ms
elapsed=565.65s tid=0x00007f1ac0148800 nid=0x7509 waiting on condition
[0x00007f1aa81f4000]
java.lang.Thread.State: RUNNABLE
at
java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.13/Native
Method)
at
java.lang.ref.Reference.processPendingReferences(java.base@11.0.13/Unknown
Source)
at
java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.13/Unknown
Source)
"Finalizer" #3 daemon prio=8 os_prio=0 cpu=17.20ms elapsed=565.65s
tid=0x00007f1ac014a800 nid=0x750a in Object.wait() [0x00007f1aa17b5000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.13/Native Method)
- waiting on <no object reference available>
at java.lang.ref.ReferenceQueue.remove(java.base@11.0.13/Unknown
Source)
- waiting to re-lock in wait() <0x0000000082f45e68> (a
java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@11.0.13/Unknown
Source)
at
java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.13/Unknown
Source)
"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.18ms elapsed=565.63s
tid=0x00007f1ac015f800 nid=0x750b waiting on condition
[0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Service Thread" #5 daemon prio=9 os_prio=0 cpu=0.06ms elapsed=565.63s
tid=0x00007f1ac0161800 nid=0x750c runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #6 daemon prio=9 os_prio=0 cpu=55607.79ms
elapsed=565.63s tid=0x00007f1ac0164000 nid=0x750d waiting on condition
[0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"C1 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=8101.56ms
elapsed=565.63s tid=0x00007f1ac0168800 nid=0x750e waiting on condition
[0x0000000000000000]
java.lang.Thread.State: RUNNABLE
No compile task
"Sweeper thread" #8 daemon prio=9 os_prio=0 cpu=149.89ms elapsed=565.63s
tid=0x00007f1ac016a000 nid=0x750f runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Common-Cleaner" #9 daemon prio=8 os_prio=0 cpu=10.97ms elapsed=565.56s
tid=0x00007f1ac01ad800 nid=0x7510 in Object.wait() [0x00007f1aa11af000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.13/Native Method)
- waiting on <no object reference available>
at java.lang.ref.ReferenceQueue.remove(java.base@11.0.13/Unknown
Source)
- waiting to re-lock in wait() <0x0000000082f55120> (a
java.lang.ref.ReferenceQueue$Lock)
at jdk.internal.ref.CleanerImpl.run(java.base@11.0.13/Unknown Source)
at java.lang.Thread.run(java.base@11.0.13/Unknown Source)
at jdk.internal.misc.InnocuousThread.run(java.base@11.0.13/Unknown
Source)
"AsyncFileHandlerWriter-1419810764" #12 daemon prio=5 os_prio=0
cpu=61.46ms elapsed=565.37s tid=0x00007f1ac0258000 nid=0x7511 waiting on
condition [0x00007f1aa0c86000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.13/Native Method)
- parking to wait for <0x0000000083033b90> (a
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at
java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.13/Unknown
Source)
at
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.13/Unknown
Source)
at
java.util.concurrent.LinkedBlockingDeque.pollFirst(java.base@11.0.13/Unknown
Source)
at
java.util.concurrent.LinkedBlockingDeque.poll(java.base@11.0.13/Unknown
Source)
at
org.apache.juli.AsyncFileHandler$LoggerThread.run(AsyncFileHandler.java:159)
"RMI TCP Accept-1198" #13 daemon prio=5 os_prio=0 cpu=0.62ms
elapsed=564.60s tid=0x00007f1ac0311000 nid=0x7517 runnable
[0x00007f1aa0174000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(java.base@11.0.13/Native
Method)
at
java.net.AbstractPlainSocketImpl.accept(java.base@11.0.13/Unknown
Source)
at java.net.ServerSocket.implAccept(java.base@11.0.13/Unknown Source)
at java.net.ServerSocket.accept(java.base@11.0.13/Unknown Source)
at
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(java.rmi@11.0.13/Unknown
Source)
at
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@11.0.13/Unknown
Source)
at java.lang.Thread.run(java.base@11.0.13/Unknown Source)
"RMI TCP Accept-1199" #14 daemon prio=5 os_prio=0 cpu=0.20ms
elapsed=564.59s tid=0x00007f1ac0318000 nid=0x7518 runnable
[0x00007f1a99dfe000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(java.base@11.0.13/Native
Method)
at
java.net.AbstractPlainSocketImpl.accept(java.base@11.0.13/Unknown
Source)
at java.net.ServerSocket.implAccept(java.base@11.0.13/Unknown Source)
at java.net.ServerSocket.accept(java.base@11.0.13/Unknown Source)
at
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(java.rmi@11.0.13/Unknown
Source)
at
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@11.0.13/Unknown
Source)
at java.lang.Thread.run(java.base@11.0.13/Unknown Source)
"RMI TCP Accept-0" #15 daemon prio=5 os_prio=0 cpu=0.16ms elapsed=564.53s
tid=0x00007f1ac031a000 nid=0x7519 runnable [0x00007f1a99cfd000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(java.base@11.0.13/Native
Method)
at
java.net.AbstractPlainSocketImpl.accept(java.base@11.0.13/Unknown
Source)
at java.net.ServerSocket.implAccept(java.base@11.0.13/Unknown Source)
at java.net.ServerSocket.accept(java.base@11.0.13/Unknown Source)
at
sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(jdk.management.agent@11.0.13/Unknown
Source)
at
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(java.rmi@11.0.13/Unknown
Source)
at
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@11.0.13/Unknown
Source)
at java.lang.Thread.run(java.base@11.0.13/Unknown Source)
"RMI TCP Accept-1096" #20 daemon prio=5 os_prio=0 cpu=0.45ms
elapsed=524.39s tid=0x00007f1ac25d6800 nid=0x75a2 runnable
[0x00007f1a7964d000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(java.base@11.0.13/Native
Method)
at
java.net.AbstractPlainSocketImpl.accept(java.base@11.0.13/Unknown
Source)
at java.net.ServerSocket.implAccept(java.base@11.0.13/Unknown Source)
at java.net.ServerSocket.accept(java.base@11.0.13/Unknown Source)
at
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(java.rmi@11.0.13/Unknown
Source)
at
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@11.0.13/Unknown
Source)
at java.lang.Thread.run(java.base@11.0.13/Unknown Source)
"RMI Reaper" #21 prio=5 os_prio=0 cpu=0.40ms elapsed=524.33s
tid=0x00007f1ac25fe800 nid=0x75a3 in Object.wait() [0x00007f1a7954c000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.13/Native Method)
- waiting on <0x000000008308a268> (a
java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@11.0.13/Unknown
Source)
- waiting to re-lock in wait() <0x000000008308a268> (a
java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(java.base@11.0.13/Unknown
Source)
at
sun.rmi.transport.ObjectTable$Reaper.run(java.rmi@11.0.13/Unknown
Source)
at java.lang.Thread.run(java.base@11.0.13/Unknown Source)
"RMI GC Daemon" #22 daemon prio=2 os_prio=0 cpu=0.56ms elapsed=524.33s
tid=0x00007f1ac2600000 nid=0x75a4 in Object.wait() [0x00007f1a79249000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.13/Native Method)
- waiting on <0x0000000083f674b8> (a
sun.rmi.transport.GC$LatencyLock)
at sun.rmi.transport.GC$Daemon.run(java.rmi@11.0.13/Unknown Source)
- waiting to re-lock in wait() <0x0000000083f674b8> (a
sun.rmi.transport.GC$LatencyLock)
at java.lang.Thread.run(java.base@11.0.13/Unknown Source)
at jdk.internal.misc.InnocuousThread.run(java.base@11.0.13/Unknown
Source)
"RMI TCP Accept-2071" #24 daemon prio=5 os_prio=0 cpu=0.50ms
elapsed=516.66s tid=0x00007f1ac1dd9000 nid=0x75b4 runnable
[0x00007f1a7994e000]
java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.socketAccept(java.base@11.0.13/Native
Method)
at
java.net.AbstractPlainSocketImpl.accept(java.base@11.0.13/Unknown
Source)
at java.net.ServerSocket.implAccept(java.base@11.0.13/Unknown Source)
at java.net.ServerSocket.accept(java.base@11.0.13/Unknown Source)
at
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(java.rmi@11.0.13/Unknown
Source)
at
sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@11.0.13/Unknown
Source)
at java.lang.Thread.run(java.base@11.0.13/Unknown Source)
"process reaper" #154 daemon prio=10 os_prio=0 cpu=1.19ms elapsed=7.35s
tid=0x00007f1a68809000 nid=0x7b02 waiting on condition
[0x00007f1aa80f3000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.13/Native Method)
- parking to wait for <0x000000008d084b78> (a
java.util.concurrent.SynchronousQueue$TransferStack)
at
java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.13/Unknown
Source)
at
java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.13/Unknown
Source)
at
java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.13/Unknown
Source)
at
java.util.concurrent.SynchronousQueue.poll(java.base@11.0.13/Unknown
Source)
at
java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.13/Unknown
Source)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.13/Unknown
Source)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.13/Unknown
Source)
at java.lang.Thread.run(java.base@11.0.13/Unknown Source)
"DestroyJavaVM" #162 prio=5 os_prio=0 cpu=38702.67ms elapsed=3.50s
tid=0x00007f1ac2111800 nid=0x74fd waiting on condition
[0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"VM Thread" os_prio=0 cpu=410.18ms elapsed=565.66s tid=0x00007f1ac0140000
nid=0x7508 runnable
"GC Thread#0" os_prio=0 cpu=3200.32ms elapsed=565.68s
tid=0x00007f1ac0040000 nid=0x74ff runnable
"GC Thread#1" os_prio=0 cpu=3191.55ms elapsed=564.64s
tid=0x00007f1a8c001000 nid=0x7515 runnable
"G1 Main Marker" os_prio=0 cpu=5.91ms elapsed=565.68s
tid=0x00007f1ac0071800 nid=0x7500 runnable
"G1 Conc#0" os_prio=0 cpu=3307.29ms elapsed=565.68s tid=0x00007f1ac0073800
nid=0x7501 runnable
"G1 Refine#0" os_prio=0 cpu=304.37ms elapsed=565.68s
tid=0x00007f1ac00e5800 nid=0x7502 runnable
"G1 Refine#1" os_prio=0 cpu=0.11ms elapsed=564.63s tid=0x00007f1a90001000
nid=0x7516 runnable
"G1 Young RemSet Sampling" os_prio=0 cpu=173.47ms elapsed=565.68s
tid=0x00007f1ac00e7800 nid=0x7503 runnable
"VM Periodic Task Thread" os_prio=0 cpu=353.71ms elapsed=564.52s
tid=0x00007f1ac032b800 nid=0x751a waiting on condition
JNI global refs: 19, weak refs: 0
Heap
garbage-first heap total 716800K, used 312709K [0x0000000082e00000,
0x0000000100000000)
region size 1024K, 35 young (35840K), 5 survivors (5120K)
Metaspace used 97218K, capacity 99705K, committed 99788K, reserved
1132544K
class space used 14830K, capacity 15794K, committed 15820K, reserved
1048576K
