Deadlock using commons-pool 1.4 and commons-dbcp 1.2.2

I have found critical situation about deadlock.

Http thread was full. Most of apache workers was in sending reply.

Busy http thread grew up until suspending its function. When the apache could not respond any request, it removed from L4 (it have L7 function) because of no response.

Every web servers (600 ea) always does not happen, but some web application servers(10ea) fell into the trouble per 2-3 days.

Apache Status :

Server

Application Version : 2.0.59, Mod_jk 1.2.18, Tomcat 5.5.17, JDK 6.0 update 6 Linux Kernel 2.6.9-67.0.22.ELsmp #1 SMP,
OS : CentOS
gcc version : gcc version 3.4.6 20060404 (Red Hat 3.4.6-9)
glibc 버전 glibc-2.3.4-2.39

I was wonderying why happened.

1) I captured apache server status.

Apache Server Status

Server uptime: 4 days 20 hours 41 minutes 2 seconds

Total accesses: 43491259 - Total Traffic: 10.8 GB

CPU Usage: u33.75 s6.42 cu0 cs0 - .00956% CPU load

104 requests/sec - 27.0 kB/second - 266 B/request

109 requests currently being processed, 4 idle workers

WWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWWW_WWW.WWWWWWWWWWWW CWWWWWWWWWWWWWWWWWWWWW_WWWWCWWWWWWWWWRWWWWWW__CCR.C............. ................................................................ ................................................................ 

Scoreboard Key:
"_" Waiting for Connection, "S" Starting up, "R" Reading Request,
"W" Sending Reply, "K" Keepalive (read), "D" DNS Lookup,
"C" Closing connection, "L" Logging, "G" Gracefully finishing,
"I" Idle cleanup of worker, "." Open slot with no current process

2) lsof

The number of CLOSE_WAIT status tcp sockets was 140. The number was close equal to the number of apache workers was in sending reply.

java 16907 www 52u IPv6 1014864218 TCP localhost.localdomain:8009->localhost.localdomain:35205 (CLOSE_WAIT)

java 16907 www 53u IPv6 1014869414 TCP localhost.localdomain:8009->localhost.localdomain:35414 (CLOSE_WAIT)

java 16907 www 54u IPv6 1014861929 TCP localhost.localdomain:8009->localhost.localdomain:35171 (CLOSE_WAIT)

java 16907 www 55u IPv6 1014863474 TCP localhost.localdomain:8009->localhost.localdomain:35200 (CLOSE_WAIT)

java 16907 www 56u IPv6 1014781598 TCP localhost.localdomain:8009->localhost.localdomain:60006 (CLOSE_WAIT)

java 16907 www 57u IPv6 1014860437 TCP localhost.localdomain:8009->localhost.localdomain:35091 (CLOSE_WAIT)

java 16907 www 58u IPv6 1014859292 TCP localhost.localdomain:8009->localhost.localdomain:35062 (CLOSE_WAIT)

java 16907 www 59u IPv6 1014853698 TCP localhost.localdomain:8009->localhost.localdomain:34860 (CLOSE_WAIT)

java 16907 www 60u IPv6 1014864865 TCP localhost.localdomain:8009->localhost.localdomain:35353 (CLOSE_WAIT)

java 16907 www 61u IPv6 1014868132 TCP localhost.localdomain:8009->localhost.localdomain:35356 (CLOSE_WAIT)

java 16907 www 62u IPv6 1014864283 TCP localhost.localdomain:8009->localhost.localdomain:35222 (CLOSE_WAIT)
..

3) Thread dump

I found dead lock situation in dumped thread in java log.

i. java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:916)
- waiting to lock <0x8fedb478> (a org.apache.commons.pool.impl.GenericObjectPool)

1. "TP-Processor2" daemon prio=10 tid=0x0821f400 nid=0x4286 waiting for monitor entry [0x88ed3000..0x88ed50a0]

2. "TP-Processor2" daemon prio=10 tid=0x0821f400 nid=0x4286 waiting for monitor entry [0x88ed3000..0x88ed50a0]

Found one Java-level deadlock:

=============================

"TP-Processor200":

waiting to lock monitor 0x080dfd24 (object 0x8fedb478, a org.apache.commons.pool.impl.GenericObjectPool),

which is held by "Timer-0"

"Timer-0":

waiting to lock monitor 0x080dfcc0 (object 0x8fee6f70, a org.apache.commons.dbcp.PoolableConnection),

which is held by "TP-Processor28"

"TP-Processor28":

waiting to lock monitor 0x080dfd24 (object 0x8fedb478, a org.apache.commons.pool.impl.GenericObjectPool),

which is held by "Timer-0"

"TP-Processor200": (Select query) return queryForList("xxx.selectXXXCount",param);

"TP-Processor28": (Select query)

queryForObject("selectmusic",params);

This deadlock reported in "Dead lock using the evictor"(https://issues.apache.org/jira/browse/DBCP-270)

In this jira, there are patch on that.

Commons Dbcp Dead lock using the evictor Created: 26/Jun/08 10:18 AM Updated: 27/Jun/08 03:41 AM

Component/s: None Affects Version/s: 1.2.2 Fix Version/s: 1.3

Patch attached, dead lock reported. the abandonedtrace does synchronized(this) when it really only needs to do synchronized(this.trace)

Dead lock reported when using the evictor

=============================
"Timer-3":
waiting to lock monitor 0x0000000053b40548 (object 0x00002aaabf3210f0, a
org.apache.tomcat.dbcp.dbcp.PoolableConnection),
which is held by "TP-Processor27"
"TP-Processor27":
waiting to lock monitor 0x0000000053b404d0 (object 0x00002aaab9fa8b08, a
org.apache.tomcat.dbcp.pool.impl.GenericObjectPool),
which is held by "Timer-3"

Java stack information for the threads listed above:

patch source

Index: src/java/org/apache/commons/dbcp/AbandonedTrace.java

===================================================================

--- src/java/org/apache/commons/dbcp/AbandonedTrace.java (revision 671937)

+++ src/java/org/apache/commons/dbcp/AbandonedTrace.java (working copy)

@@ -172,7 +172,7 @@

* @param trace AbandonedTrace object to add

*/

protected void addTrace(AbandonedTrace trace) {

- synchronized (this) {

+ synchronized (this.trace) {

this.trace.add(trace);

}

setLastUsed();

@@ -182,8 +182,8 @@

* Clear the list of objects being traced by this

* object.

*/

- protected synchronized void clearTrace() {

- if (this.trace != null) {

+ protected void clearTrace() {

+ synchronized(this.trace) {

this.trace.clear();

}

}

@@ -194,8 +194,10 @@

* @return List of objects

*/

protected List getTrace() {

- return trace;

+ synchronized (this.trace) {

+ return new ArrayList(trace);

}

+ }

/**

* If logAbandoned=true, print a stack trace of the code that

@@ -206,7 +208,7 @@

System.out.println(format.format(new Date(createdTime)));

createdBy.printStackTrace(System.out);

}

- synchronized(this) {

+ synchronized(this.trace) {

Iterator it = this.trace.iterator();

while (it.hasNext()) {

AbandonedTrace at = (AbandonedTrace)it.next();

@@ -220,8 +222,8 @@

*

* @param trace AbandonedTrace object to remvoe

*/

- protected synchronized void removeTrace(AbandonedTrace trace) {

- if (this.trace != null) {

+ protected void removeTrace(AbandonedTrace trace) {

+ synchronized(this.trace) {

this.trace.remove(trace);

}

}

Because Commons-dbcp 1.3 is not year released in formal. (now : 4. 2009) and I do not know what willing happen if the snapshop patch version, I used patched commons-dbcp 1.2.2 library.

After patching that version, there is no trouble or problem like that.