Thread Dump analysis | ojdbc14 | Oracle Connection pool

Thread view:

kiranmalla.in@gmail.com - 23 Nov 2005 02:20 GMT

Hi

The problem description is a bit large...wanted to be more descriptive.

System Architecture:
-------------------
Apache, Tomcats 5.0.x, mod-jk (for load balancing), Oracle, jsp, java,
ojdbc14 for connection pooling, jdk.14.1

Issue:
------
We are running a cluster of 8 tomcats and 4 apache instances load
balanced by mod-jk. Some Tomcats stop responding after running for a
period of time and need a restart. We have observed over a period of
time that a restart of tomcat is required when the thread count is
around 543 and heap is maxed out at 990M. We are giving application
intial memory of 1 GB using the Xms and Xmx settings while starting
tomcats...so memory doesn't seem to be an issue.

Analysis:
---------
We have started recording the thread dumps. Most of the thread dumps
show a similar behaviour. Let's say 500 threads "waiting for a monitor
which is locked by a thread

The messages in 500 threads is "- waiting to lock <0xbf4e9e60> (a
oracle.jdbc.pool.OracleConnectionEventListener)"

This thread has the lock:
"TP-Processor633" daemon prio=5 tid=0x004921d0 nid=0x5ba waiting for
monitor entry [872fe000..872ffc28]
    at
oracle.jdbc.pool.OracleConnectionCacheImpl.closeSingleConnection(OracleConnectionCacheImpl.java:677)
    - waiting to lock <0xbf4e98f8> (a
oracle.jdbc.pool.OracleConnectionCacheImpl)
    at
oracle.jdbc.pool.OracleConnectionCacheImpl.reusePooledConnection(OracleConnectionCacheImpl.java:592)
    at
oracle.jdbc.pool.OracleConnectionEventListener.connectionClosed(OracleConnectionEventListener.java:130)
    - locked <0xbf4e9e60> (a
oracle.jdbc.pool.OracleConnectionEventListener)
    at
oracle.jdbc.pool.OraclePooledConnection.callListener(OraclePooledConnection.java:482)
    at
oracle.jdbc.pool.OraclePooledConnection.logicalClose(OraclePooledConnection.java:445)
    - locked <0xcc9af820> (a oracle.jdbc.pool.OraclePooledConnection)
    at
oracle.jdbc.driver.OracleConnection.logicalClose(OracleConnection.java:2936)
    - locked <0xcc9af8c8> (a oracle.jdbc.driver.OracleConnection)
    at
oracle.jdbc.driver.OracleConnection.close(OracleConnection.java:1454)
    - locked <0xcc9af8c8> (a oracle.jdbc.driver.OracleConnection)
    at com.ss.framework.sql.SqlStatement.close(SqlStatement.java:984)
    at
com.cc.ac.cnams.classmanagement.ClassQry.getCommunityLinksForCourse(ClassQry.java:15796)
    at
com.cc.ac.cnams.classmanagement.ClassQry.getClassDetailsForViewClassInfo(ClassQry.java:8069)

Threads waiting for the above lock to be released (around 500 in
number)
"TP-Processor632" daemon prio=5 tid=0x00491578 nid=0x5b9 waiting for
monitor entry [873fd000..873ffc28]
    at
oracle.jdbc.pool.OracleConnectionEventListener.connectionClosed(OracleConnectionEventListener.java:129)
    - waiting to lock <0xbf4e9e60> (a
oracle.jdbc.pool.OracleConnectionEventListener)
    at
oracle.jdbc.pool.OraclePooledConnection.callListener(OraclePooledConnection.java:482)
    at
oracle.jdbc.pool.OraclePooledConnection.logicalClose(OraclePooledConnection.java:445)
    - locked <0xcd699580> (a oracle.jdbc.pool.OraclePooledConnection)
    at
oracle.jdbc.driver.OracleConnection.logicalClose(OracleConnection.java:2936)
    - locked <0xcd699640> (a oracle.jdbc.driver.OracleConnection)
    at
oracle.jdbc.driver.OracleConnection.close(OracleConnection.java:1454)
    - locked <0xcd699640> (a oracle.jdbc.driver.OracleConnection)
    at com.ss.framework.sql.SqlStatement.close(SqlStatement.java:984)
    at
com.cc.ac.cnams.pa.PersonalAssociationQry.getRole(PersonalAssociationQry.java:1141)
    at
com.cc.ac.cnams.pa.PersonalAssociation.getRole(PersonalAssociation.java:2353)
    at
com.cc.ac.cnams.entitlements.Entitlements.isUserOfRole(Entitlements.java:195)
    at
org.apache.jsp.content.BannerLeftNav_jsp._jspService(BannerLeftNav_jsp.java:201)
    at com.ss.framework.presentation.servlet.Jsp.process(Jsp.java:49)
    at com.ss.framework.presentation.servlet.Jsp.service(Jsp.java:41)
    at
org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:324)
    at
org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:292)

I can provide the complete thread trace if anyone is interested in the
complete dump.

In the application, we are using ojdbc14 (oracle's connection pool) for
handling the connections. I have observed that after doing all the
operations in a DB object, we close the prepared statement
(SqlPreparedStatement.close). RESULT SET is not closed explicitly. Can
this issue be due to the resultset not being closed explicitly.

Javadoc for jdk 1.4.2 says: "A Statement object is automatically
closed when it is garbage collected. When a Statement object is closed,
its current ResultSet object, if one exists, is also closed.

"http://java.sun.com/j2se/1.4.2/docs/api/java/sql/Statement.html#close()

However, some doubts have been raised by people in the links below:
http://www.theserverside.com/discussions/thread.tss?thread_id=33592
http://forum.java.sun.com/thread.jspa?threadID=135291&messageID=2615181

I'm not sure if not closing the 'REsult Set' explicitly can create this
type of issue as it is supposed to be handled by the java. Not sure if
ojdbc14 has implemented it as per the spec though.

Any pointers around the thread dump or the issue of whether ResultSet
should be closed explicity while using ORACLE Conneciton pool (ojdbc14)
would be higly appreciated. I can provide more details if required.

Thanks
Kiran

Reply to this Message

Bjorn Abelli - 23 Nov 2005 03:04 GMT

<kiranmalla.in@gmail.com> wrote...

> In the application, we are using ojdbc14 (oracle's connection pool) for
> handling the connections. I have observed that after doing all the
> operations in a DB object, we close the prepared statement
> (SqlPreparedStatement.close). RESULT SET is not closed explicitly. Can
> this issue be due to the resultset not being closed explicitly.

[snip]

> Any pointers around the thread dump or the issue of whether ResultSet
> should be closed explicity while using ORACLE Conneciton pool (ojdbc14)
> would be higly appreciated. I can provide more details if required.

Oracle claims that there are problems with some JVMs on the issue of
finalizers, therefore they urge users to explicitly close ResultSets.

// Bjorn A

Reply to this Message

kiranmalla.in@gmail.com - 23 Nov 2005 03:32 GMT

Thanks Bjorn,

Some additional info:
We are using sun'
"java version "1.4.1_02a"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.4.1_02a-b01)
Java HotSpot(TM) Client VM (build 1.4.1_02a-b01, mixed mode)"

Is the Oracle recommendation documented at some place, so that I can
refer to that and make a case for closing the resultSets explicitly?

A strange behaviour in most of the threads (of the thread dump) is that
they have kept a lock at "
oracle.jdbc.pool.OracleConnectionCacheImpl.closeSingleConnection(OracleConnectionCacheImpl.java:677)
- waiting to lock <0xbf4e98f8> (a
oracle.jdbc.pool.OracleConnectionCacheImpl)"

I can understand if a thread is locked while getting a connection which
in turn can lead to other threads wait for the resource. But, I am
surprised as to why it is creating this issue, while closing the
connection.

Polling the group for any other inputs and known issues with the Oracle
connection pool.

Thanks
Kiran

Reply to this Message

Bjorn Abelli - 23 Nov 2005 03:57 GMT

<kiranmalla.in@gmail.com> wrote...

> Is the Oracle recommendation documented at some place,
> so that I can refer to that and make a case for closing
> the resultSets explicitly?

I would have given you a link to the documentation at Oracle, but it seems
like I would have to login to their technet-pages to find it, and I don't
have my password at hand, so I looked up a "mirror" instead...

http://techdoc.c-bizz.klopotek.de/classes12-O9i/oracle/jdbc/driver/OracleResultS
et.html#close()%20

or...

http://tinyurl.com/9asac

...look what it says on the close() method...

// Bjorn A

Reply to this Message

steve - 25 Nov 2005 21:49 GMT

> Thanks Bjorn,
>
[quoted text clipped - 9 lines]
> A strange behaviour in most of the threads (of the thread dump) is that
> they have kept a lock at "

oracle.jdbc.pool.OracleConnectionCacheImpl.closeSingleConnection(OracleConnect

> ionCacheImpl.java:677)
> - waiting to lock <0xbf4e98f8> (a
[quoted text clipped - 10 lines]
> Thanks
> Kiran

just a tip.

Explicitly close EVERYTHING you can.

Statments & result sets, and anything else you are using, ( apart from the
connection, if you are re-using it)

Basically if the oracle or SQL object has a ".close()" then use it
Explicitly.

Anything else is the kiss of death, but it looks like you may already know
that.

Steve

Reply to this Message

Thomas Hawtin - 23 Nov 2005 11:14 GMT

> The messages in 500 threads is "- waiting to lock <0xbf4e9e60> (a
> oracle.jdbc.pool.OracleConnectionEventListener)"
[quoted text clipped - 6 lines]
> - waiting to lock <0xbf4e98f8> (a
> oracle.jdbc.pool.OracleConnectionCacheImpl)

Somewhere there may be a thread which holds that particular lock, which
may have a more interesting stack. You may have a situation where many
threads are acquiring and releasing the lock.

The ResultSets should be closed at the latest when commit or rollback is
called (unless you use HOLD_SURSORS_OVER_COMMIT). However, in the past
some drivers have not been without bugs.

> Javadoc for jdk 1.4.2 says: "A Statement object is automatically
> closed when it is garbage collected. When a Statement object is closed,
> its current ResultSet object, if one exists, is also closed.

Don't rely on finalisation. Perhaps it will release the resource, but
you may already have run into trouble before it happens.

Tom Hawtin

Signature

Unemployed English Java programmer
http://jroller.com/page/tackline/

Reply to this Message

Thread Dump analysis | ojdbc14 | Oracle Connection pool

Free Magazines