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
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
