Tales From A Lazy Fat DBA

Hi All,

Last week I was looking into a database problem where the customer reported database hang issues when trying to use their Java based application, and that application requires to connect with the database every now and then. This was a brand new platform where they were doing some UAT testing’s and were using WebLogic which they recently configured to use with connection pooling enabled.

Application team reported that they are getting frequent ‘ORA-00018 maximum number of sessions exceeded’ errors in the alert log and that was a big clue. Operations team tried many times to identify all INACTIVE sessions (session limit was 800 in the DB) and manually kill them, but new JDBC Thin Client gets spawns every time … I was sure that this is most probably the JDBC connection leak issue, and those are always difficult to identify!

Now talking about – How to detect this problem ?. Though there were multiple other performance problem on this platform, but none of them seems related with the SQLs, as the execution plan were perfect and reflects a well designed SQL workload. So I suspected the application, started with the WebLogic server logs and there I saw multiple instances of “BEA-000627 Reached maximum capacity of pool “cgDataSource”, making “0” new resource instances instead of “1” “ warnings, and with that, it once again solidified my initial assumption that it as happening all as a result of applications’ code not closing connections properly, connection leakage.

A leaked connection is a connection that was not properly returned to the connection pool in the data source. To automatically recover leaked connections, you can specify a value for Inactive Connection Timeout on the JDBC Data Source. When you set a value for Inactive Connection Timeout, WebLogic Server forcibly returns a connection to the data source when there is no activity on a reserved connection for the number of seconds that you specify. When set to 0 (the default value), this feature is turned off. So we have to we need to set one specific parameter for the data source to force close those connections that are not closed by the application.

Click on Services --> Data Sources --> Click on the Data Source you want to configure --> Click on Connection Pool --> Click on Advanced --> “Inactive Connection Timeout”

And it was set to its default value of 0, means no inactive sessions will be snapped or removed and will stay in the database and consume sessions limit. After carefull observation and a discussion with the team, we set it to a reasonable value and bounced Weblogic Admin and manager servers (MS) to make changes persistent.

But if this was the solution to the problem ? No, it was not! and is always a remedy, to immediately handle the situation while the root cause of the problem is investigated.
I later on investigated the log files in order to isolate the culprit class. Also noticed that after we’d set the ‘Inactive Connection Timeout’ setting, multiple instances of BEA-001153 Warnings were captured within logs. This was because the code does not close the connection, and was waiting for the “Inactive connection timeout” to trigger closure of these objects and that had caused the warning message printed in the admin server logs.

<Dec 3, 2021 10:12:34 AM GMT> 
<Warning> <JDBC> <BEA-001153> <Forcibly releasing inactive connection "weblogic.jdbc.wrapper.PoolConnection_oracle_jdbc_driver_xxCConnection@xxx" back into the connection pool "xxxxxxxx-xxx", currently reserved by: java.lang.Exception
at weblogic.jdbc.common.internal.ConnectionEnv.setup(ConnectionEnv.java:325)
at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:363)
at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:329)
at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:417)
at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:324)
at weblogic.jdbc.common.internal.MultiPool.searchLoadBalance(MultiPool.java:312)
at weblogic.jdbc.common.internal.MultiPool.findPool(MultiPool.java:180)
at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:89)
at weblogic.jdbc.common.internal.RmiDataSource.getPoolConnection(RmiDataSource.java:350)
at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:369)
at oracle.jbo.server.DBTransactionImpl.establishNewConnection(DBTransactionImpl.java:990)
.....
..........

Later I collected JDBC Diagnostic Dumps via admin console to detect and further troubleshoot this JDBC Connection Leak.

Dumping Resource Pool:cgDataSource
Resource Pool:cgDataSource:dumpPool Current Capacity = 4
Resource Pool:cgDataSource:dumpPool dumping available resources, #entries = 0
Resource Pool:cgDataSource:dumpPool dumping reserved resources, #entries = 4
Resource Pool:cgDataSource:dumpPool reserved[0] = autoCommit=true, enabled=true, isXA=true, isJTS=false, vendorID=11, connUsed=true, doInit=false, 'null', destroyed=false, poolname=cgDataSource, appname=null, moduleName=null, connectTime=4941, dirtyIsolationLevel=false, initialIsolationLevel=2, infected=false, lastSuccessfulConnectionUse=1344715611974, secondsToTrustAnIdlePoolConnection=10, currentUser=java.lang.Exception
  at weblogic.jdbc.common.internal.ConnectionEnv.setup(ConnectionEnv.java:308)
  at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:314)
  at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:292)
  at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:425)
  at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:316)
  at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:93)
  at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:61)
  at weblogic.jdbc.jta.DataSource.getXAConnectionFromPool(DataSource.java:1473)
  at weblogic.jdbc.jta.DataSource.refreshXAConnAndEnlist(DataSource.java:1302)
  at weblogic.jdbc.jta.DataSource.getConnection(DataSource.java:425)
  at weblogic.jdbc.jta.DataSource.connect(DataSource.java:382)
  at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:338)
  at troubleshooting.servlets.JdbcConnections.service(JdbcConnections.java:97)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
  at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
......
.........
at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:338)
  at troubleshooting.servlets.JdbcConnections.service(JdbcConnections.java:97)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
  at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
.........
...............
at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:338)
  at troubleshooting.servlets.JdbcConnections.service(JdbcConnections.java:97)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
  at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
.....
......
at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:338)
  at troubleshooting.servlets.JdbcConnections.service(JdbcConnections.java:97)
  at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
  at weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
......
.........

If you watch carefully, on all the dumps above, the method that initiates the connection to the database is troubleshooting.servlets.JdbcConnections.service(), specifically at line 97 on Class JdbcConnections.java, as the stack says.

We went back to the source code for the application (dummy code):

      } else if (i == -1) {
        try {
          InitialContext localInitialContext2 = new InitialContext();

          DataSource localDataSource = (DataSource)localInitialContext2.lookup("cgDataSource");    <========== HERE IS WHERE THE LEAK STARTS

          localObject = localDataSource.getConnection();                                          
          localObject = null;                                                                      <========== HERE IS WHERE THE LEAK OCCURS, WHEN OBJECT IS SET TO NULL BUT CONNECTION NOT CLOSED.
          System.out.println("xxxxxxxxx.");
          localInitialContext2.close();
        } catch (Exception localException2) {
localPrintWriter.println("An exception has been thrown while trying to increase the number of JDBC connection to " + i + ", the error is<br><br>");

And application team immediately recognized the cause, there was a need to explicitly closed the connection and was later on fixed by the application team to something below.

          InitialContext localInitialContext2 = new InitialContext();

          DataSource localDataSource = (DataSource)localInitialContext2.lookup("cgDataSource");

          localObject = localDataSource.getConnection();

          System.out.println("xxxxxxxxx.");
          localInitialContext2.close();
        } catch (Exception localException2) {
          localPrintWriter.println("An exception has been thrown while trying to increase the number of JDBC connection to " + i + ", the error is<br><br>");

        } finally{

          localObject.close()
          localObject = null;

         }

So, that’s how it got resolved after changing the problematic code. Connection leakage is a very tricky scenario which requires careful observation primarily of the application code.

Hope It Helped
Prashant Dixit