You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Simon Matter <si...@invoca.ch> on 2021/11/30 13:21:10 UTC
Tomcat 9 doesn't shutdown cleanly
Hi,
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.
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.
So both methods somehow terminate Tomcat partly but not completely.
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.
I've tried, beside a lot of other things, to set
skipMemoryLeakChecksOnJvmShutdown="true" in context.xml but it seems to
change nothing at all.
Any help would be much appreciated.
Thanks,
Simon
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat 9 doesn't shutdown cleanly
Posted by "Terence M. Bandoian" <te...@tmbsw.com>.
On 11/30/2021 8:40 AM, Simon Matter wrote:
> 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
I would take a look at all the "RMI" threads.
-Terence Bandoian
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AW: AW: Tomcat 9 doesn't shutdown cleanly
Posted by Simon Matter <si...@invoca.ch>.
Hi,
> Hello Simon,
>
> if you use the Registry to bind Objects / Stubs, you must also call
> "unbind" on shutdown:
> https://docs.oracle.com/javase/7/docs/api/java/rmi/registry/Registry.html
>
> I think the developer who implemented the RMI stub, should also now what
> to unbind.
>
> Greetings,
> Thomas
The issue has been solved now by adding two unbind() where they were
clearly missing. Tomcat shuts down cleanly now with no delay.
Thanks to all who helped!
Regards,
Simon
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
AW: AW: Tomcat 9 doesn't shutdown cleanly
Posted by "Thomas Hoffmann (Speed4Trade GmbH)" <Th...@speed4trade.com.INVALID>.
Hello Simon,
if you use the Registry to bind Objects / Stubs, you must also call "unbind" on shutdown:
https://docs.oracle.com/javase/7/docs/api/java/rmi/registry/Registry.html
I think the developer who implemented the RMI stub, should also now what to unbind.
Greetings,
Thomas
-----Ursprüngliche Nachricht-----
Von: Simon Matter <si...@invoca.ch>
Gesendet: Dienstag, 30. November 2021 16:10
An: Tomcat Users List <us...@tomcat.apache.org>
Betreff: Re: AW: Tomcat 9 doesn't shutdown cleanly
Hi Thomas,
> Hello,
>
> it looks like your application opens several ports for RMI communication.
> One class is mentioned in your first mail: ShopdbCacheSynchronizer
Yes, and it's true that when I'm looking at the shut down Tomcat instance VM, I see several RMI threads lingering around.
>
> 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.
Good guess, that's exactly what I'm trying to do, finding out why we have the shutdown problems so the "developer guys" can finally fix this issue.
From how I understand it, we have an internal application server which initiates RMI connections to the Tomcat instance sitting in the DMZ. My question is, can we terminate the RMI connections on the Tomcat instance only and shut down Tomcat, or do we have to close the RMI connections on the internal appserver which initiated the connections?
Apart from RMI, is there anything in the thread dump which indicates an issue in out Tomcat app?
Kind regards,
Simon
>
> Greetings,
> Thomas
>
> -----Ursprüngliche Nachricht-----
> Von: Simon Matter <si...@invoca.ch>
> Gesendet: Dienstag, 30. November 2021 15:40
> An: Tomcat Users List <us...@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.clearReferencesRmiT
>>> a 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.clearReferencesRmiT
>>> a rgets Found RMI Target with stub class class
>>> [com.sun.proxy.$Proxy51] and value
>>> [Proxy[ShopdbCacheSynchronizer,RemoteObjectInvocationHandler[Unicast
>>> R
>>> 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.clearReferencesRmiT
>>> a 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/Unk
> nown
> 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/Unk
> nown
> 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/U
> nknown
> Source)
> at
> java.util.concurrent.LinkedBlockingDeque.poll(java.base@11.0.13/Unknow
> n
> Source)
> at
> org.apache.juli.AsyncFileHandler$LoggerThread.run(AsyncFileHandler.jav
> a: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.r
> mi@11.0.13/Unknown
> Source)
> at
> sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@11.0.13/Unk
> nown
> 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.r
> mi@11.0.13/Unknown
> Source)
> at
> sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@11.0.13/Unk
> nown
> 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.mana
> gement.agent@11.0.13/Unknown
> Source)
> at
> sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(java.r
> mi@11.0.13/Unknown
> Source)
> at
> sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@11.0.13/Unk
> nown
> 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.r
> mi@11.0.13/Unknown
> Source)
> at
> sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@11.0.13/Unk
> nown
> 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.r
> mi@11.0.13/Unknown
> Source)
> at
> sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@11.0.13/Unk
> nown
> 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/Unk
> nown
> 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/Unkn
> own
> Source)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.13/Un
> known
> Source)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.13/U
> nknown
> 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-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
> Т
> ХF V 7V'67& &R R â W6W'2 V 7V'67& &T
> F 6B 6 R &pФf "FF F 6 G2 R â W6W'2ֆV
> F 6B 6 R &pР
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AW: Tomcat 9 doesn't shutdown cleanly
Posted by Simon Matter <si...@invoca.ch>.
Hi Thomas,
> Hello,
>
> it looks like your application opens several ports for RMI communication.
> One class is mentioned in your first mail: ShopdbCacheSynchronizer
Yes, and it's true that when I'm looking at the shut down Tomcat instance
VM, I see several RMI threads lingering around.
>
> 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.
Good guess, that's exactly what I'm trying to do, finding out why we have
the shutdown problems so the "developer guys" can finally fix this issue.
From how I understand it, we have an internal application server which
initiates RMI connections to the Tomcat instance sitting in the DMZ. My
question is, can we terminate the RMI connections on the Tomcat instance
only and shut down Tomcat, or do we have to close the RMI connections on
the internal appserver which initiated the connections?
Apart from RMI, is there anything in the thread dump which indicates an
issue in out Tomcat app?
Kind regards,
Simon
>
> Greetings,
> Thomas
>
> -----Ursprüngliche Nachricht-----
> Von: Simon Matter <si...@invoca.ch>
> Gesendet: Dienstag, 30. November 2021 15:40
> An: Tomcat Users List <us...@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-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
> �Т���������������������������������������������������������������������ХF�V�7V'67&�&R�R���âW6W'2�V�7V'67&�&TF��6B�6�R��&pФf�"FF�F����6����G2�R���âW6W'2ֆV�F��6B�6�R��&pР
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
AW: Tomcat 9 doesn't shutdown cleanly
Posted by "Thomas Hoffmann (Speed4Trade GmbH)" <Th...@speed4trade.com.INVALID>.
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 <si...@invoca.ch>
Gesendet: Dienstag, 30. November 2021 15:40
An: Tomcat Users List <us...@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-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat 9 doesn't shutdown cleanly
Posted by Simon Matter <si...@invoca.ch>.
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-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Tomcat 9 doesn't shutdown cleanly
Posted by Christopher Schultz <ch...@christopherschultz.net>.
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"`
> 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.
> 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.
-chris
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org