[Building Sakai] Tomcat not shutting down properly

Mike Jennings mike_jennings at unc.edu
Tue Mar 27 17:01:55 PDT 2012 

I have started doing some initial testing and have setup my instance to 
to work with the visual_vm tool to try and help identify what threads 
are hanging.

I have not had a chance to get back to this testings, as we are in the 
middle of trying to role out our 2.8.1 upgrade, but here is the thread 
dump from Tomcat 5.5.31 when it hangs.

I will try and dedicate some time to this tomorrow to see what I can 
find.  I was even thinking of trying to use the newer version of 
reflectutils and upgrade it to 0.9.16....

Mike

"DestroyJavaVM" prio=10 tid=0x0000000001718000 nid=0x65da waiting on 
condition [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE

"TP-Processor4" daemon prio=10 tid=0x00007fe2698fe000 nid=0x6666 in 
Object.wait() [0x00007fe263cca000]
    java.lang.Thread.State: WAITING (on object monitor)
         at java.lang.Object.wait(Native Method)
         - waiting on <0x00000000d40f1410> (a 
org.apache.jk.common.ChannelSocket)
         at java.lang.Object.wait(Object.java:502)
         at 
org.apache.jk.common.ChannelSocket.accept(ChannelSocket.java:307)
         - locked <0x00000000d40f1410> (a 
org.apache.jk.common.ChannelSocket)
         at 
org.apache.jk.common.ChannelSocket.acceptConnections(ChannelSocket.java:667)
         at 
org.apache.jk.common.ChannelSocket$SocketAcceptor.runIt(ChannelSocket.java:878)
         at 
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
         at java.lang.Thread.run(Thread.java:679)

"http-8080-Processor24" daemon prio=10 tid=0x00007fe2685c5800 nid=0x6660 
waiting on condition [0x00007fe2642d0000]
    java.lang.Thread.State: TIMED_WAITING (sleeping)
         at java.lang.Thread.sleep(Native Method)
         at 
org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:62)
         at 
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
         at java.lang.Thread.run(Thread.java:679)

"Timer-3" prio=10 tid=0x0000000001ecd000 nid=0x6645 in Object.wait() 
[0x00007fe2659fc000]
    java.lang.Thread.State: WAITING (on object monitor)
         at java.lang.Object.wait(Native Method)
         - waiting on <0x00000000ccfd54f8> (a java.util.TaskQueue)
         at java.lang.Object.wait(Object.java:502)
         at java.util.TimerThread.mainLoop(Timer.java:505)
         - locked <0x00000000ccfd54f8> (a java.util.TaskQueue)
         at java.util.TimerThread.run(Timer.java:484)

"Timer-2" daemon prio=10 tid=0x00007fe27169c000 nid=0x662e in 
Object.wait() [0x00007fe267cfb000]
    java.lang.Thread.State: TIMED_WAITING (on object monitor)
         at java.lang.Object.wait(Native Method)
         - waiting on <0x00000000cb19b948> (a java.util.TaskQueue)
         at java.util.TimerThread.mainLoop(Timer.java:531)
         - locked <0x00000000cb19b948> (a java.util.TaskQueue)
         at java.util.TimerThread.run(Timer.java:484)

"SakaiPresenceService.Maintenance" daemon prio=10 tid=0x00007fe270f50000 
nid=0x662b waiting on condition [0x00007fe267ffe000]
    java.lang.Thread.State: TIMED_WAITING (sleeping)
         at java.lang.Thread.sleep(Native Method)
         at 
org.sakaiproject.presence.impl.BasePresenceService$Maintenance.run(BasePresenceService.java:795)
         at java.lang.Thread.run(Thread.java:679)

"FinalizableReferenceQueue" daemon prio=10 tid=0x00007fe271f90800 
nid=0x661c in Object.wait() [0x00007fe26dbad000]
    java.lang.Thread.State: WAITING (on object monitor)
         at java.lang.Object.wait(Native Method)
         - waiting on <0x00000000c4af2f78> (a 
java.lang.ref.ReferenceQueue$Lock)
         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133)
         - locked <0x00000000c4af2f78> (a java.lang.ref.ReferenceQueue$Lock)
         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149)
         at 
org.azeckoski.reflectutils.refmap.FinalizableReferenceQueue$1.run(FinalizableReferenceQueue.java:54)

"org.azeckoski.reflectutils.refmap.Finalizer" daemon prio=10 
tid=0x00007fe271716000 nid=0x660b in Object.wait() [0x00007fe26e3b5000]
    java.lang.Thread.State: WAITING (on object monitor)
         at java.lang.Object.wait(Native Method)
         - waiting on <0x00000000c3705ae8> (a 
java.lang.ref.ReferenceQueue$Lock)
         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133)
         - locked <0x00000000c3705ae8> (a java.lang.ref.ReferenceQueue$Lock)
         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149)
         at 
org.azeckoski.reflectutils.refmap.Finalizer.run(Finalizer.java:127)

"MySQL Statement Cancellation Timer" daemon prio=10 
tid=0x00007fe27105a800 nid=0x65ff in Object.wait() [0x00007fe26edbf000]
    java.lang.Thread.State: WAITING (on object monitor)
         at java.lang.Object.wait(Native Method)
         - waiting on <0x00000000c088bc80> (a java.util.TaskQueue)
         at java.lang.Object.wait(Object.java:502)
         at java.util.TimerThread.mainLoop(Timer.java:505)
         - locked <0x00000000c088bc80> (a java.util.TaskQueue)
         at java.util.TimerThread.run(Timer.java:484)

"Low Memory Detector" daemon prio=10 tid=0x00007fe270035800 nid=0x65e7 
runnable [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x00007fe270033000 nid=0x65e6 
waiting on condition [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x00007fe270030000 nid=0x65e5 
waiting on condition [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE

"JDWP Event Helper Thread" daemon prio=10 tid=0x00007fe27002e000 
nid=0x65e4 runnable [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE

"JDWP Transport Listener: dt_socket" daemon prio=10 
tid=0x00007fe27002a000 nid=0x65e3 runnable [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00007fe27001f000 nid=0x65e2 
waiting on condition [0x0000000000000000]
    java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00007fe270001000 nid=0x65e1 in 
Object.wait() [0x00007fe274b11000]
    java.lang.Thread.State: WAITING (on object monitor)
         at java.lang.Object.wait(Native Method)
         - waiting on <0x00000000c0e8b9b0> (a 
java.lang.ref.ReferenceQueue$Lock)
         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:133)
         - locked <0x00000000c0e8b9b0> (a java.lang.ref.ReferenceQueue$Lock)
         at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:149)
         at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)

"Reference Handler" daemon prio=10 tid=0x0000000001786800 nid=0x65e0 in 
Object.wait() [0x00007fe274c12000]
    java.lang.Thread.State: WAITING (on object monitor)
         at java.lang.Object.wait(Native Method)
         - waiting on <0x00000000c0e8b970> (a java.lang.ref.Reference$Lock)
         at java.lang.Object.wait(Object.java:502)
         at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
         - locked <0x00000000c0e8b970> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x000000000177f800 nid=0x65df runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x0000000001723000 
nid=0x65db runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x0000000001724800 
nid=0x65dc runnable

"GC task thread#2 (ParallelGC)" prio=10 tid=0x0000000001726800 
nid=0x65dd runnable

"GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000001728800 
nid=0x65de runnable

"VM Periodic Task Thread" prio=10 tid=0x00007fe270040800 nid=0x65e8 
waiting on condition

JNI global references: 36988

Heap
  PSYoungGen      total 260096K, used 161178K [0x00000000e8000000, 
0x00000000fc3d0000, 0x0000000100000000)
   eden space 218368K, 73% used 
[0x00000000e8000000,0x00000000f1d668a8,0x00000000f5540000)
   from space 41728K, 0% used 
[0x00000000f5540000,0x00000000f5540000,0x00000000f7e00000)
   to   space 43136K, 0% used 
[0x00000000f99b0000,0x00000000f99b0000,0x00000000fc3d0000)
  PSOldGen        total 601472K, used 335230K [0x00000000c0000000, 
0x00000000e4b60000, 0x00000000e8000000)
   object space 601472K, 55% used 
[0x00000000c0000000,0x00000000d475fac8,0x00000000e4b60000)
  PSPermGen       total 524288K, used 265631K [0x00000000a0000000, 
0x00000000c0000000, 0x00000000c0000000)
   object space 524288K, 50% used 
[0x00000000a0000000,0x00000000b0367ce0,0x00000000c0000000)



==============================================================================
Mike Jennings
Teaching and Learning Developer
University of North Carolina at Chapel Hill

Office: (919) 843-5013
Cell: (919) 698-3746
E-mail: mike_jennings at unc.edu

On 3/27/2012 7:52 PM, Steve Swinsburg wrote:
> There are a few related Jira's here:
>
> https://jira.sakaiproject.org/browse/SAK-2908 - User presence persisitng after browser shutdown without logout
> https://jira.sakaiproject.org/browse/SAK-12598 - Thread should be daemons to prevent tomcat process hanging on shutdown
> https://jira.sakaiproject.org/browse/SAK-20847 - Presence throws NPE after Tomcat shutdown
>
>
>
>
> On 28/03/2012, at 10:47 AM, Adams, David wrote:
>
>> We've seen this behavior for years. I find it amusing that Aaron's name is in the culprit class. Nevertheless we just have our shutdown script check to see if tomcat is stopped at intervals and kill it after a reasonable amount of time (we've settled on about 15 seconds). It only has to resort to that about half of the time I'd guess. There don't seem to be any ill effects from this forced shutdown. Most everything has shutdown correctly by then, but we've been running that way for years.
>>
>> On Mar 27, 2012, at 11:03 AM, "Brian Jones"<bjones86 at uwo.ca>  wrote:
>>
>>> Community,
>>>
>>> Recently we here at Western University polled the community for existing
>>> certification tools for Sakai. Rsmart was kind enough to provide their
>>> certification tool as contrib.
>>>
>>> We've tested deploying this tool on our local and dev environments and
>>> noticed something troubling. In a nutshell, after deploying the tool, it
>>> causes Tomcat to be unable to shut down properly. It's always waiting for
>>> some threads that are waiting for something.
>>>
>>> Please find attached two files, one outlining the test plan which verified
>>> the certification tool as the culprit, the second a thread dump. I noticed
>>> in the thread dump there are two suspicious entries:
>>>
>>> . "SakaiPresenceService.Maintenance"
>>> . "org.azeckoski.reflectutils.refmap.Finalizer"
>>>
>>> But I can't find any references to these objects/packages/methods in any the
>>> code of either rsmart-common or the certification tool itself. We're kind of
>>> at a loss as to how to track this issue down, or what to do to resolve it.
>>> If anyone in the community, or at Rsmart, has an ideas we would be extremely
>>> appreciative.
>>>
>>> Thanks in advance,
>>>
>>> Brian Jones
>>> Applications Development
>>> Information Technology Services
>>> Support Services Building, Room 4326
>>> University of Western Ontario
>>> (519) 661-2111 x86969
>>> bjones86 at uwo.ca
>>>
>>> <Test Plan.txt>
>>> <threadDump.log>
>>> _______________________________________________
>>> sakai-dev mailing list
>>> sakai-dev at collab.sakaiproject.org
>>> http://collab.sakaiproject.org/mailman/listinfo/sakai-dev
>>>
>>> TO UNSUBSCRIBE: send email to sakai-dev-unsubscribe at collab.sakaiproject.org with a subject of "unsubscribe"
>> _______________________________________________
>> sakai-dev mailing list
>> sakai-dev at collab.sakaiproject.org
>> http://collab.sakaiproject.org/mailman/listinfo/sakai-dev
>>
>> TO UNSUBSCRIBE: send email to sakai-dev-unsubscribe at collab.sakaiproject.org with a subject of "unsubscribe"
>
> _______________________________________________
> sakai-dev mailing list
> sakai-dev at collab.sakaiproject.org
> http://collab.sakaiproject.org/mailman/listinfo/sakai-dev
>
> TO UNSUBSCRIBE: send email to sakai-dev-unsubscribe at collab.sakaiproject.org with a subject of "unsubscribe"

More information about the sakai-dev mailing list