Oracle

February 15, 2011

One way to detect JDBC connection leaks

Filed under: Uncategorized — srivenu @ 8:21 am

I just wanted to blog about a connect leak issue that i had encountered in a in-house developed, Email center application. The application was developed using struts and commons pool. After some code and configuration changes, the application started facing performance issues and was hanging after 1-2 days of app server startup. The workaround was to restart the app server.
The error_log during the period showed the following message “oc4j_socket_recvfull timed out”.
The java thread during the hang dump showed several threads with the following state
(I had renamed our code names with xyz.abc)

"AJPRequestHandler-RMICallHandler-231" prio=1 tid=0x0849e0c8 nid=0x5d3c in Object.wait() [0x58925000..0x58925da0]
	at java.lang.Object.wait(Native Method)
	- waiting on  (a org.apache.commons.pool.impl.GenericObjectPool)
	at java.lang.Object.wait(Object.java:474)
	at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:810)
	- locked  (a org.apache.commons.pool.impl.GenericObjectPool)
	at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:96)
	at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:880)
	at com.xyz.abc.dao.SummaryCount.mailsInQueue(SummaryCount.java:356)
	at com.xyz.abc.actions.MailInQueAction.execute(MailInQueAction.java:36)
	at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:484)
	at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:274)
	at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1482)
	at org.apache.struts.action.ActionServlet.doPost(ActionServlet.java:525)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:763)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:856)
	at com.evermind.server.http.ResourceFilterChain.doFilter(ResourceFilterChain.java:64)
	at com.xyz.abc.utils.EmcSecurityFilter.doFilter(EmcSecurityFilter.java:152)
	at com.evermind.server.http.ServletRequestDispatcher.invoke(ServletRequestDispatcher.java:644)
	at com.evermind.server.http.ServletRequestDispatcher.forwardInternal(ServletRequestDispatcher.java:391)
	at com.evermind.server.http.HttpRequestHandler.doProcessRequest(HttpRequestHandler.java:908)
	at com.evermind.server.http.HttpRequestHandler.processRequest(HttpRequestHandler.java:458)
	at com.evermind.server.http.AJPRequestHandler.run(AJPRequestHandler.java:313)
	at com.evermind.server.http.AJPRequestHandler.run(AJPRequestHandler.java:199)
	at oracle.oc4j.network.ServerSocketReadHandler$SafeRunnable.run(ServerSocketReadHandler.java:260)
	at oracle.oc4j.network.ServerSocketAcceptHandler.procClientSocket(ServerSocketAcceptHandler.java:234)
	at oracle.oc4j.network.ServerSocketAcceptHandler.access$700(ServerSocketAcceptHandler.java:29)
	at oracle.oc4j.network.ServerSocketAcceptHandler$AcceptHandlerHorse.run(ServerSocketAcceptHandler.java:879)
	at com.evermind.util.ReleasableResourcePooledExecutor$MyWorker.run(ReleasableResourcePooledExecutor.java:303)
	at java.lang.Thread.run(Thread.java:595)

After seeing the error message, i thought i would monitor the open database connections for this application.

select 	count(*)
from 	v$session
where 	username = 'ABCD'
and 	machine = 'XYZ'
and 	program = 'JDBC Thin Client'
/

After monitoring this output for sometime, i could see a steady increase in the number of open connections. This clearly pointed out to a connection leak in the code.
The next logical step was to identify the offending piece of code and fix it. The developers have informed that they had already done several thorough checks of their code. They were also sceptical that the issue was due to a bug in the commons pool and wanted to use a different pool. I could understand their problem as the code was huge and ran into thousands of lines. It wouldnt be practically feasible to identify the culprit unless the search was somehow narrowed down.

I used the following method to help the developers in narrowing down their search operation for a connection leak. My thought was that if there is a connection leak, then the PREV_HASH_VALUE (it was 8i hence no SQL_ID) of the sessions (corresponding to leaked connections) would point out the last sql that was executed before the connection object went out of scope in the java application. So i used the following sql to get the last sql’s executed by the sessions

col sid head "Sid" form 9999 trunc
col serial# form 99999 trunc head "Ser#"
col username form a15 trunc
col machine head "Client|Machine" form a20 trunc
col login head "Login" form a11
col sql_hash_value head "Curr|Hash|Value" form 9999999999
col prev_hash_value head "Prev|Hash|Value" form 9999999999
col "last call"  form 9999999 trunc head "Last Call|In Secs"
col status form a6 trunc

select	sid, serial#, username, machine,
        to_char(logon_time,'ddMon hh24:mi') login,
        SQL_HASH_VALUE, PREV_HASH_VALUE,
        last_call_et "last call", status
from 	v$session
where 	username = 'ABCD'
and 	machine = 'XYZ'
and 	program = 'JDBC Thin Client'
order 	by logon_time
/

The output was something like this


                                                                     Curr        Prev
                             Client                                  Hash        Hash Last Call
  Sid   Ser# Username        Machine              Login             Value       Value   In Secs STATUS
----- ------ --------------- -------------------- ----------- ----------- ----------- --------- ------
 1386  13316 ABCD            machin11             15Sep 14:52           0  1836767206      1563 INACTI
 3168  12144 ABCD            machin11             15Sep 14:53           0  1836767206      1561 INACTI
 5718   7638 ABCD            machin11             15Sep 14:53           0  1836767206      1571 INACTI
 4312   9851 ABCD            machin11             15Sep 14:54           0  1836767206      1578 INACTI
 5512   9858 ABCD            machin11             15Sep 14:54           0  1836767206      2262 INACTI
 1988  11653 ABCD            machin11             15Sep 14:55           0  1836767206      2130 INACTI
 6924    314 ABCD            machin11             15Sep 14:55           0  1836767206      2142 INACTI
 3515   7286 ABCD            machin11             15Sep 14:57           0  1836767206      1281 INACTI
 6633   3135 ABCD            machin11             15Sep 14:57           0  1836767206      1520 INACTI

There were hundreds of sessions which pointed out to the same hash_value “1836767206”.
I gathered the sql_text for this hash_value and the developers said that i came from a DAO.
Seeing where this DAO is accessed from and searching nearby, we could quickly catch the culprit! By mistake, a new connection object is being obtained on the same connection variable, without releasing it first, thereby making the old connection go out of scope.

Thought this blog entry might help others in trying to debug database connection leak issues.

Advertisements

7 Comments »

  1. realy helpfull article

    Comment by sangeeth — February 16, 2011 @ 4:10 am | Reply

  2. Concept seems pretty good..Let me put the thought in my application.:)

    Comment by Phani Kumar Pendurthi — February 26, 2011 @ 10:30 am | Reply

  3. Phani

    what application you are working on?

    Comment by XYZ — February 28, 2011 @ 12:23 am | Reply

  4. OMG you just kept me from getting fired! I had been using v$session to watch my app grid down but didn’t have a clue about the hash_value or v$sqltext.
    thank you thank you thank you thank you thank you thank you

    Comment by Scott — April 11, 2013 @ 11:43 am | Reply

  5. Call me a dummy… but I don’t know how to use the Hash value to track down my offending Java code. Any help appreciated! thx

    Comment by Gary Grubb — May 20, 2013 @ 7:28 am | Reply

  6. A look at comment #5 cleared the air. Good stuff! thx

    Comment by Gary Grubb — May 20, 2013 @ 7:31 am | Reply

  7. This is awesome work. Never paid attention to hash_codes from v$session. Thanks for putting it up.

    Comment by Pravin Kalekar — July 18, 2016 @ 12:29 pm | Reply


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Create a free website or blog at WordPress.com.

%d bloggers like this: