Hello,
it looks like your application opens several ports for RMI communication.
One class is mentioned in your first mail: ShopdbCacheSynchronizer
Maybe you can ask the developer guys to check whether these threads / ports are
terminated / closed cleanly on shutdown event.
Quite often developers don't care much about shutting down their stuff cleanly.
Greetings,
Thomas
-----Ursprüngliche Nachricht-----
Von: Simon Matter <simon.mat...@invoca.ch>
Gesendet: Dienstag, 30. November 2021 15:40
An: Tomcat Users List <users@tomcat.apache.org>
Betreff: Re: Tomcat 9 doesn't shutdown cleanly
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.clearReferencesRmiTa
>> rgets 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.clearReferencesRmiTa
>> rgets Found RMI Target with stub class class [com.sun.proxy.$Proxy51]
>> and value
>> [Proxy[ShopdbCacheSynchronizer,RemoteObjectInvocationHandler[UnicastR
>> ef
>> [liveRef:
>> [endpoint:[157.161.91.47:1096](local),objID:[-6f4b2f9d:17d70eb1ef4:-7
>> ffd, -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.clearReferencesRmiTa
>> rgets 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
