tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jean-Pascal Houde <jpho...@korem.com>
Subject RE: Tomcat 9.0.14 Windows service slow to stop
Date Tue, 08 Jan 2019 15:25:32 GMT
Thanks all,

Here is a more detailed service log (at FINE level):
[2019-01-08 09:45:21] [debug] ( prunsrv.c:885 ) [ 2752] reportServiceStatusE: dwCurrentState
= 3, dwWin32ExitCode = 0, dwWaitHint = 3000, dwServiceSpecificExitCode = 0
[2019-01-08 09:45:21] [info]  ( prunsrv.c:984 ) [ 8792] Stopping service...
[2019-01-08 09:45:21] [debug] ( javajni.c:937 ) [ 8408] argv[0] = stop
[2019-01-08 09:45:21] [debug] ( javajni.c:990 ) [ 8408] Java Worker thread started org/apache/catalina/startup/Bootstrap:main
[2019-01-08 09:45:21] [debug] ( javajni.c:1013) [ 4108] Java Worker thread finished org/apache/catalina/startup/Bootstrap:main
with status = 0
[2019-01-08 09:45:21] [debug] ( javajni.c:1013) [ 8408] Java Worker thread finished org/apache/catalina/startup/Bootstrap:main
with status = 0
[2019-01-08 09:45:21] [debug] ( prunsrv.c:1577) [ 9012] Worker finished.
[2019-01-08 09:45:21] [debug] ( prunsrv.c:1586) [ 9012] Waiting for ShutdownEvent
[2019-01-08 09:45:21] [debug] ( prunsrv.c:885 ) [ 9012] reportServiceStatusE: dwCurrentState
= 3, dwWin32ExitCode = 0, dwWaitHint = 60000, dwServiceSpecificExitCode = 0
[2019-01-08 09:45:22] [debug] ( prunsrv.c:1032) [ 8792] Waiting for Java JNI stop worker to
finish...
[2019-01-08 09:45:22] [debug] ( prunsrv.c:1034) [ 8792] Java JNI stop worker finished.
[2019-01-08 09:45:22] [debug] ( prunsrv.c:885 ) [ 8792] reportServiceStatusE: dwCurrentState
= 3, dwWin32ExitCode = 0, dwWaitHint = 300000, dwServiceSpecificExitCode = 0
[2019-01-08 09:45:22] [debug] ( prunsrv.c:1141) [ 8792] Waiting for worker to die naturally...
[2019-01-08 09:45:22] [debug] ( prunsrv.c:1152) [ 8792] Worker finished gracefully in 0 ms.
[2019-01-08 09:45:22] [info]  ( prunsrv.c:1162) [ 8792] Service stop thread completed.
[2019-01-08 09:45:22] [debug] ( prunsrv.c:1589) [ 9012] ShutdownEvent signaled
[2019-01-08 09:45:22] [debug] ( prunsrv.c:1594) [ 9012] Waiting 1 minute for all threads to
exit
[2019-01-08 09:45:22] [debug] ( prunsrv.c:885 ) [ 9012] reportServiceStatusE: dwCurrentState
= 3, dwWin32ExitCode = 0, dwWaitHint = 60000, dwServiceSpecificExitCode = 0
[2019-01-08 09:46:22] [debug] ( prunsrv.c:1607) [ 9012] JVM destroyed.
[2019-01-08 09:46:22] [debug] ( prunsrv.c:885 ) [ 9012] reportServiceStatusE: dwCurrentState
= 1, dwWin32ExitCode = 0, dwWaitHint = 0, dwServiceSpecificExitCode = 0
[2019-01-08 09:46:22] [info]  ( prunsrv.c:1645) [ 2752] Run service finished.
[2019-01-08 09:46:22] [info]  ( prunsrv.c:1814) [ 2752] Commons Daemon procrun finished



Catalina log file doesn't have much:
08-Jan-2019 09:44:33.101 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization
in [563] milliseconds
08-Jan-2019 09:44:33.132 INFO [main] org.apache.catalina.core.StandardService.startInternal
Starting service [Catalina]
08-Jan-2019 09:44:33.132 INFO [main] org.apache.catalina.core.StandardEngine.startInternal
Starting Servlet engine: [Apache Tomcat/9.0.14]
08-Jan-2019 09:44:33.132 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler
["http-nio-7980"]
08-Jan-2019 09:44:33.148 INFO [main] org.apache.catalina.startup.Catalina.start Server startup
in [42] milliseconds
08-Jan-2019 09:45:21.833 INFO [Thread-5] org.apache.coyote.AbstractProtocol.pause Pausing
ProtocolHandler ["http-nio-7980"]
08-Jan-2019 09:45:21.866 INFO [Thread-5] org.apache.catalina.core.StandardService.stopInternal
Stopping service [Catalina]
08-Jan-2019 09:45:21.866 INFO [Thread-5] org.apache.coyote.AbstractProtocol.stop Stopping
ProtocolHandler ["http-nio-7980"]



Below is the result of a thread dump while the service waiting to stop:

"Signal Dispatcher" daemon prio=9 tid=4 RUNNABLE
  
"DestroyJavaVM" prio=5 tid=32 RUNNABLE

"Finalizer" daemon prio=8 tid=3 WAITING
    at java.lang.Object.wait(Native Method)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
       Local Variable: java.lang.ref.ReferenceQueue#20
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)
       Local Variable: java.lang.System$2#1

"Catalina-utility-1" prio=1 tid=15 WAITING
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
       Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#38
       Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject#1
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1081)
       Local Variable: java.util.concurrent.locks.ReentrantLock#1
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
       Local Variable: java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue#1
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
       Local Variable: java.util.concurrent.ScheduledThreadPoolExecutor#1
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
       Local Variable: java.util.concurrent.ThreadPoolExecutor$Worker#10
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
       Local Variable: org.apache.tomcat.util.threads.TaskThread$WrappingRunnable#10
    at java.lang.Thread.run(Thread.java:748)

"FileHandlerLogFilesCleaner-1" daemon prio=5 tid=12 WAITING
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
       Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject#6
       Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#116
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
       Local Variable: java.util.concurrent.locks.ReentrantLock#128
       Local Variable: java.util.concurrent.atomic.AtomicInteger#7
       Local Variable: java.util.concurrent.LinkedBlockingQueue#1
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
       Local Variable: java.util.concurrent.ThreadPoolExecutor#1
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
       Local Variable: java.util.concurrent.ThreadPoolExecutor$Worker#12
    at java.lang.Thread.run(Thread.java:748)

"Attach Listener" daemon prio=5 tid=5 RUNNABLE

"NioBlockingSelector.BlockPoller-1" daemon prio=5 tid=14 RUNNABLE
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296)
    at sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278)
       Local Variable: sun.nio.ch.WindowsSelectorImpl$SubSelector#2
    at sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
       Local Variable: java.util.Collections$UnmodifiableSet#4
       Local Variable: sun.nio.ch.Util$3#3
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
       Local Variable: sun.nio.ch.WindowsSelectorImpl#3
    at org.apache.tomcat.util.net.NioBlockingSelector$BlockPoller.run(NioBlockingSelector.java:298)

"AsyncFileHandlerWriter-1020371697" daemon prio=5 tid=11 TIMED_WAITING
    at sun.misc.Unsafe.park(Native Method)
    at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
       Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject#4
       Local Variable: java.util.concurrent.locks.AbstractQueuedSynchronizer$Node#89
    at java.util.concurrent.LinkedBlockingDeque.pollFirst(LinkedBlockingDeque.java:522)
       Local Variable: java.util.concurrent.locks.ReentrantLock#127
    at java.util.concurrent.LinkedBlockingDeque.poll(LinkedBlockingDeque.java:684)
       Local Variable: java.util.concurrent.LinkedBlockingDeque#1
       Local Variable: java.util.concurrent.TimeUnit$3#1
    at org.apache.juli.AsyncFileHandler$LoggerThread.run(AsyncFileHandler.java:159)

"Reference Handler" daemon prio=10 tid=2 WAITING
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
  
"GC Daemon" daemon prio=2 tid=13 TIMED_WAITING
    at java.lang.Object.wait(Native Method)
    at sun.misc.GC$Daemon.run(GC.java:117)



JP


-----Original Message-----
From: Igal Sapir <igal@lucee.org> 
Sent: Tuesday, January 8, 2019 00:10
To: Tomcat Users List <users@tomcat.apache.org>
Subject: Re: Tomcat 9.0.14 Windows service slow to stop

On Mon, Jan 7, 2019 at 8:57 PM Christopher Schultz < chris@christopherschultz.net> wrote:

> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> Steve,
>
> On 1/7/19 19:47, Steve Demy wrote:
> > This sounds similar to:
> >
> > http://mail-archives.apache.org/mod_mbox/tomcat-dev/201812.mbox/ajax
> > /%
> 3Cbug-63041-78%40https.bz.apache.org%2Fbugzilla%2F%3E
> <http://mail-archives.apache.org/mod_mbox/tomcat-dev/201812.mbox/ajax/
> %3Cbug-63041-78%40https.bz.apache.org%2Fbugzilla%2F%3E>
> >
> >
> and,
> > http://mail-archives.apache.org/mod_mbox/tomcat-users/201812.mbox/aj
> > ax
> /%3CDEB74971-2714-401F-9428-25EE0ECC6D11%40shaw.ca%3E
> <http://mail-archives.apache.org/mod_mbox/tomcat-users/201812.mbox/aja
> x/%3CDEB74971-2714-401F-9428-25EE0ECC6D11%40shaw.ca%3E>
> >
> >  I’m not fluent in Tomcat, but it appears something changed in the 
> > catalina.sh script of 9.0.14 that changed the stop/start behaviour.
>
> Certainly nothing in catalina.sh affects Windows Services. Even 
> catalina.bat is ignored for Windows Services.
>

+1


> Your issue is that Tomcat's scripts (well, actually, some 3rd-party 
> scripts, actually) can't manage to stop Tomcat. Jean-Pascal's problem 
> is that his shutdown is taking 60sec when he thinks it shouldn't take 
> that long.
>

I've seen this happen when an application, or a 3rd-party library starts a non-daemon thread
and it is not stopped prior to the shutdown attempt.  I think that there is a 60 second timeout
because I've also noticed about that same time frame when it happens.


>
> Jean-Pascal, what do the Tomcat logs say? There should be something 
> like catalina.out or stdout.log or something like that.
>

+1

Another thing I would try is to look at a thread dump.

Igal


>
> - -chris
>
> >> On Jan 7, 2019, at 3:38 PM, Jean-Pascal Houde <jphoude@korem.com>
> >> wrote:
> >>
> >> Hello,
> >>
> >> I'm having a problem that seems to occur only since Tomcat 9.0.14. 
> >> I'm using Tomcat installed as a service on a Windows 2012
> >> R2 server. The service starts normally, but stopping it from the 
> >> Windows Services window takes a long time (about a minute). This 
> >> happens even with no web application deployed on the server. I've 
> >> tried downgrading to 9.0.13 and 9.0.12 and both version stops 
> >> normally, under 1-2 seconds.
> >>
> >> Here is what I am doing: 1. Download Tomcat Windows 64-bit zip 2.
> >> Install service using "service install tomcat9" 3. Open Windows 
> >> "Services" control panel 3. Start Tomcat9 service -> very fast 4.
> >> Stop Tomcat9 service -> gets stuck on "stopping service..." for 
> >> around a minute.
> >>
> >> This is what the commons-daemon log file shows: [2019-01-07 
> >> 18:27:21] [info]  [ 7500] Commons Daemon procrun (1.1.0.0 64-bit) 
> >> started [2019-01-07 18:27:21] [info]  [ 7500] Running 'tomcat9'
> >> Service... [2019-01-07 18:27:21] [info]  [ 3904] Starting 
> >> service... [2019-01-07 18:27:22] [info]  [ 3904] Service started in 
> >> 1190 ms. [2019-01-07 18:27:23] [info]  [ 9796] Stopping service... 
> >> [2019-01-07 18:27:24] [info]  [ 9796] Service stop thread 
> >> completed. [2019-01-07 18:28:24] [info]  [ 7500] Run service 
> >> finished. [2019-01-07 18:28:24] [info]  [ 7500] Commons Daemon 
> >> procrun finished
> >>
> >> You can see the full minute between the initial "Stopping 
> >> services..." and the finish of the stopping process. Other log 
> >> files don't show anything suspicious.
> >>
> >> Anyone seeing the same issue with this version?
> >>
> >> Thanks,
> >>
> >>
> >> Jean-Pascal Houde
> >>
> >>
> >> -------------------------------------------------------------------
> >> --
> >>
> >>
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> >> For additional commands, e-mail: users-help@tomcat.apache.org
> >>
> >
> >
> > --------------------------------------------------------------------
> > -
> >
> >
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> > For additional commands, e-mail: users-help@tomcat.apache.org
> >
> -----BEGIN PGP SIGNATURE-----
> Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
>
> iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAlw0LcEACgkQHPApP6U8
> pFgfsg//Yv9k+Lqnn/nH2Pd2iahEJnPRZVRUeg2bRFQGlpwRURApBzup8646UsFE
> zo9zxfJuuw2L/jea7rfZaXJaXay6nhaJ/h5+RPfq1CExNLjcK/3GjJwmZxSUqJxl
> PtNtpjsJr8lD3OXMzu9sqr26Zj3AtPbAqpJFr1A9LGlflpIi5ohqzVkpA3h2knEH
> luxjEbsD5uaG7YlQdzal76a81RBN0glBUvdgP1dPsgXKscMdYkoIzNYL7G5TniAx
> 3Jsilp0oWYfDEJ0oFRmUAjN++jq4QefMZHow3QUEU8xZ8L47JQv6ZlmkSbqPndH0
> /kdrUA9Cv82lN0czBz2u+KmKduot7tc+KEqS+RJD8Pkj9Jy7FOLCu9klLXk3LXFG
> M22XPJdwnIDQeVnjJKxjiUhetFjOCSzH3FyL/VuxAsO4qsCqSgiW/RRrU+FdLYfs
> OQPjOzGISu/9lwZ+M7yPJ1XzCoBbpVE1iHf0R5vuI0H922oXRu0dyx/IKnEpbGrv
> GY6zRrte4AtLO0oMXeDxWH/iC9xgRn+B4oy8Gd3RY9l6A1vLeT41flCSjAvtSkeU
> AE5N4iJp39mGJ/iUpWa7C5tzwbV1syv1weC4BzHVl5+W+YBBlv6x/HJX2Zc9dsMO
> okn6tCEuKFnSCqc4N4IdocolkISqObVe35RYioYHxBStMDr5dpU=
> =xtqK
> -----END PGP SIGNATURE-----
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
Mime
View raw message