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