At usage peak times we are experiencing a very slow production system which
we have to restart in order to overcome it. After a while with the same usage
load we run into the same problem (30 minutes to a few hours). If usage is
low we do not experience any problems. Usage peak happens a few days a month.
The following is two thread dumps from our system sampled with a minute in
difference when the system was experienced to be slow. First thread dump:
Thread "http-thread-pool-8580-(718)" thread-id: 4,481 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:109)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(715)" thread-id: 4,474 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(714)" thread-id: 4,473 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(712)" thread-id: 4,470 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(711)" thread-id: 4,469 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(710)" thread-id: 4,468 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(708)" thread-id: 4,466 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(705)" thread-id: 4,460 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(704)" thread-id: 4,457 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:109)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(701)" thread-id: 4,454 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:109)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(699)" thread-id: 4,452 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(691)" thread-id: 4,442 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(689)" thread-id: 4,440 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(688)" thread-id: 4,439 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(676)" thread-id: 4,420 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(673)" thread-id: 4,417 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(665)" thread-id: 4,408 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(660)" thread-id: 4,403 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(1)" thread-id: 233 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "PayrollQuartzScheduler_Worker-1" thread-id: 201 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
They are all waiting for http-thread-pool-8580-(703) which is in RUNNABLE
state.
Thread "http-thread-pool-8580-(703)" thread-id: 4,456 thread-state: RUNNABLE
at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Second thread dump:
Thread "http-thread-pool-8580-(717)" thread-id: 4,480 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_ee1f05 at:
com.sun.grizzly.util.SyncThreadPool$SyncThreadWorker.getTask(SyncThreadPool.java:434)
at:
com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:323)
Thread "http-thread-pool-8580-(715)" thread-id: 4,474 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(714)" thread-id: 4,473 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:109)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(711)" thread-id: 4,469 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(708)" thread-id: 4,466 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(705)" thread-id: 4,460 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:109)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(701)" thread-id: 4,454 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(699)" thread-id: 4,452 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(694)" thread-id: 4,447 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(693)" thread-id: 4,446 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:109)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(692)" thread-id: 4,443 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(691)" thread-id: 4,442 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(676)" thread-id: 4,420 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "http-thread-pool-8580-(672)" thread-id: 4,416 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:109)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(663)" thread-id: 4,406 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_ee1f05 at:
com.sun.grizzly.util.SyncThreadPool$SyncThreadWorker.getTask(SyncThreadPool.java:434)
at:
com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:323)
Thread "http-thread-pool-8580-(660)" thread-id: 4,403 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:108)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(2)" thread-id: 235 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:109)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
Thread "http-thread-pool-8580-(1)" thread-id: 233 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Thread "PayrollQuartzScheduler_Worker-1" thread-id: 201 thread-state: BLOCKED
Waiting on lock: java.lang.Object_at_1170d6c at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.stopConnectionLeakTracing(ConnectionLeakDetector.java:129)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToFree(ConnectionPool.java:303)
Notice that they are all waiting for http-thread-pool-8580-(680) which is not
the same thread as in the first thread dump. They are still waiting for a
lock on the same object
(com.sun.enterprise.resource.pool.ConnectionLeakDetector.connectionLeakLock).
Thread "http-thread-pool-8580-(680)" thread-id: 4,424 thread-state: RUNNABLE
at: java.lang.Throwable.getStackTraceElement(Native Method) at:
java.lang.Throwable.getOurStackTrace(Throwable.java:591) at:
java.lang.Throwable.getStackTrace(Throwable.java:582) at:
java.lang.Thread.getStackTrace(Thread.java:1436) at:
com.sun.enterprise.resource.pool.ConnectionLeakDetector.startConnectionLeakTracing(ConnectionLeakDetector.java:110)
at:
com.sun.enterprise.resource.pool.ConnectionPool.setResourceStateToBusy(ConnectionPool.java:319)
In the first dump 20 threads are waiting for the lock. In the second dump we
are down to 17. Of the 11 threads which are present in both dumps the
following are not waiting in the same line of code in
com.sun.enterprise.resource.pool.ConnectionLeakDetector.
http-thread-pool-8580-(676). Waiting in line 108 in dump 1, line 129 in dump
2. http-thread-pool-8580-(701). Waiting in line 109 in dump 1, line 129 in
dump 2. http-thread-pool-8580-(705). Waiting in line 108 in dump 1, line 109
in dump 2. http-thread-pool-8580-(714). Waiting in line 129 in dump 1, line
109 in dump 2. http-thread-pool-8580-(715). Waiting in line 108 in dump 1,
line 129 in dump 2. http-thread-pool-8580-(714) is a bit odd in comparison to
the others because line 129 (stopConnectionLeakTracing) should be invoked
before line 109 (startConnectionLeakTracing). I am interpreting this to be
because dump 1 is serving another request than dump 2. Does it seem fair?
http-thread-pool-8580-(1) waits at the same line in both threads but the
statistics is a little different.
This thread is blocked waiting on lock owned currently by thread named:
http-thread-pool-8580-(703), id: 4,456 Number of times this thread was
blocked (to enter/reenter a Monitor): 21,827 Number of times this thread
waited for a notification (i.e. it was in WAITING or TIMED_WAITING state):
14,775 Total CPU time for this thread: 253 seconds 490,000,000 nanoseconds.
User-level CPU time for this thread: 253 seconds 490,000,000 nanoseconds.
Object Monitors currently held or requested by this thread: [] Ownable
Synchronizers (e.g. ReentrantLock and ReentrantReadWriteLock) held by this
thread: [] This thread is blocked waiting on lock owned currently by thread
named: http-thread-pool-8580-(680), id: 4,424 Number of times this thread was
blocked (to enter/reenter a Monitor): 21,899 Number of times this thread
waited for a notification (i.e. it was in WAITING or TIMED_WAITING state):
14,775 Total CPU time for this thread: 253 seconds 530,000,000 nanoseconds.
User-level CPU time for this thread: 253 seconds 530,000,000 nanoseconds.
Object Monitors currently held or requested by this thread: [] Ownable
Synchronizers (e.g. ReentrantLock and ReentrantReadWriteLock) held by this
thread: []
Our GlassFish monitoring is telling us that all worker threads are busy and
that a lot of garbage collecting is occuring at the same time. Apparently the
tenured generation is full and a full GC does not reclaim sufficient space.
We know how to overcome this by setting appropriate VM parameters (increase
heap and tune GC). However, we are still unsure whether or not the thread
dumps above can be explained by a system doing a lot of GC? 3 x 2 thread
dumps taken with a few hours apart after system restart show the same thread
dumps (thread waiting in ConnectionLeakDetector). After turning off
connection leak detection we still experienced a slow system. Same pattern
with a lot of GC happening and many threads waiting for a lock that another
thread which is in RUNNABLE state has aquired (see post
http://www.java.net/forum/topic/glassfish/glassfish/many-threads-blocked-during-jndi-lookup-data-source).
How would you explain the thread dumps? Any input would be appreciated.
--
[Message sent by forum member 'mphaua']
View Post: http://forums.java.net/node/798504