JDBC connection leak

JDBC Connection leaks – Generation and Detection [BEA-001153]

Introduction

Some weeks ago, an article about memory leak problems in JVM was posted. Now, it is time to talk about another common problem that affects the performance of the application and even can cause the crash of the server. Before continuing, it is necessary to say that there are different resources consumed by applications that are candidates to generate a leak problem. For example, let us say you are using file properties to read some configuration parameters. During the unitary testing, a developer cannot realize the impact of leaving the file descriptor open. However, during the performance testing, this message must be found “Too many open files,” and then the process is killed by the operating system (Rafael, 2013). Nevertheless, many projects do not include performance testing for several reasons, such as aggressive schedules compromised with customers, and as a result, many leak problems are discovered under a huge load of production systems. With this in mind, the aim of this post is to talk about the JDBC connection leaks. A Weblogic server 12C and 11G will be used as the target of the demonstration. In addition, a little desktop application was generated. This program will allow the generation of leaks and the monitoring of connection pools.

JDBC connection leaks

Have you ever seen an error like this in the Weblogic server log (serverName.log)? “Reached maximum capacity of the pool "cgDataSource", making "0" new resource instances instead of "1 “. According to the technical note 1502054.1 (Oracle, 2014), this message appears when there is a connection leak, and it happens as a result of applications’ code that does not close the connection properly. For example, here, there is a section of code I saw some years ago after detecting a memory leak.

The question is, how could you detect this problem? We had several performance problems on this application and most of them seemed to be related to slower queries, but when the explain plans were got, we realized that the behavior was weird since the explain plan indicated a well-designed query. Thus, we reviewed some indicators on the application server, specifically the “Leaked Connection Count” that according to Oracle (n.d.) means “The number of leaked connections. A leaked connection is a connection that was reserved from the data source but was not returned to the data source by calling close()”

At that time, these metrics were found

How to get these metrics

These figures mean that a parameter was activated in the connection pool in order to force the release of leak connection. This is a good idea, but this is not the solution of the problem. This is activated here:

Let’s say we have a data source called cgDataSource, these are the steps:

1. Click on Services>Data Sources

2. Click on the Data Source you want to configure

3. Click on Connection Pool

4. Click on Advanced

5. You have to set the “Inactive Connection Timeout” in a value greater than zero to force closing those connections that are not closed by the application.

Is that the solution? The answer is not, this is a palliative that is useful and it will help us to afford that situation while the root cause of the problem is investigated. In fact, even though this parameter was activated, the performance of queries were slower and every some weeks the application server where the data source was deployed had to be restarted.

How to find the root cause of the problem

We have two options.

1. Reviewing each class that use that data source.
2. Investigating the log files in order to isolate the culprit class

The best option is the number two. Fortunately, something we realized after that activation of that timeout (“Inactive Connection Timeout”) was the log file was written with several entrances that indicated connections closed by the application server.

In this kind of cases I recommend you to look for the business class that makes use of the method getConnection. In this case is DataSourceProvider whose code was shown previously.

How to generate a scenario like this

Generating a case like this is easy, we have to open several connections without using the close() method. Since I’m not a developer I made my best to create a desktop application to saturate the connection pool. Beyond the flaws caused by my lack of experience as a programmer, I think it could be interesting because this application also allows me (using JMX) to monitor every data source. It means that pieces of code can be used by you in order to monitor your servers. The bad side is since it is a desktop application, the server log will not generate any trace about the class that generates the leak.

JDBC leak generator and monitor

The application uses this simple form to connect to

1. Connect to the Weblogic server.
2. Detect the servers (Admin and Managed) and put them within a combo box.
3. If you select a Server, the data sources that belong to that server will be shown in a combo box.
4. You can enter a number of connection to leak the data source selected
5. You can monitor the status of the connection leak using the Refresh button.

After connecting to the server I can see the AdminServer and its data sources. I will use the cgDataSource

Click on Generate to create the leak scenario

After generating 10 connection the attributes on the Monitoring section change

After 5 minutes (300s) the LeakedConnectionCount will be greater than zero as can be seen in this picture

Now, we can review the AdminServer.log to find traces of this situation.

  
  
####<Jul 20, 2015 3:46:08 PM CEST> <Warning> <JDBC> <syspwks024> <AdminServer> <[ACTIVE] ExecuteThread: '1' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <fa8deb88ab1c3a08:62e0c37b:14eabadb4de:-8000-0000000000000033> <1437399968564> <BEA-001153> <Forcibly releasing inactive/harvested connection "weblogic.jdbc.wrapper.PoolConnection_oracle_jdbc_driver_T4CConnection@8" back into the data source connection pool "cgDataSource", currently reserved by: java.lang.Exception
 at weblogic.jdbc.common.internal.ConnectionEnv.setup(ConnectionEnv.java:356)
 at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:364)
 at weblogic.common.resourcepool.ResourcePoolImpl.reserveResource(ResourcePoolImpl.java:330)
 at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:469)
 at weblogic.jdbc.common.internal.ConnectionPool.reserve(ConnectionPool.java:363)
 at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:125)
 at weblogic.jdbc.common.internal.ConnectionPoolManager.reserve(ConnectionPoolManager.java:158)
 at weblogic.jdbc.pool.Driver.connect(Driver.java:132)
 at weblogic.jdbc.jts.Driver.getNonTxConnection(Driver.java:658)
 at weblogic.jdbc.jts.Driver.connect(Driver.java:127)
 at weblogic.jdbc.common.internal.RmiDataSource.getConnectionInternal(RmiDataSource.java:533)
 at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:498)
 at weblogic.jdbc.common.internal.RmiDataSource.getConnection(RmiDataSource.java:491)
 at weblogic.jdbc.common.internal.RmiDataSource_WLSkel.invoke(Unknown Source)
 at weblogic.rmi.internal.BasicServerRef.invoke(BasicServerRef.java:667)
 at weblogic.rmi.cluster.ClusterableServerRef.invoke(ClusterableServerRef.java:230)
 at weblogic.rmi.internal.BasicServerRef$1.run(BasicServerRef.java:522)
 at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)
 at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:146)
 at weblogic.rmi.internal.BasicServerRef.handleRequest(BasicServerRef.java:518)
 at weblogic.rmi.internal.wls.WLSExecuteRequest.run(WLSExecuteRequest.java:118)
 at weblogic.work.ExecuteThread.execute(ExecuteThread.java:256)
 at weblogic.work.ExecuteThread.run(ExecuteThread.java:221)
  
  

Unfortunately as my client is a desktop application, I cannot find traces of the culprit class. However, I hope this post can help you to face this kind of problems.

Something interesting I found during this test is that if I user Weblogic Server 12C, it seems to be the attribute “LeakedConnectionCount” is not updated by the system. The previous test was made using a Weblogic Server 11G. Now I will try the 12C.

Now the address of the admin serve is admin12c.sysco.no and the port is 9001 as can be seen in the next picture.

These are the servers and data sources configured for each server.

I tested the cgDataSource deployed on Pegasus (managed server) and I used use 30 connections.

After clicking on Generate we will how the statistics change. Now I have 20 available connections and 30 unavailable

I had to wait for 5 minutes (300 s) before these connections, which do not have a close statement, would be released by the server. As I said before this is because the configuration of the connection pool:

You can use the weblogic console to see the statistics. As you can see it shows the same as the application.

After waiting for 5 minutes I got this message in the Pegasus.log file:

  
  
####<20-jul-2015 00H00' CEST> <Warning> <JDBC> <syspwks024> <Pegasus> <[ACTIVE] ExecuteThread: '23' for queue: 'weblogic.kernel.Default (self-tuning)'> <<WLS Kernel>> <> <> <1437343228017> <BEA-001153> <Forcibly releasing inactive/harvested connection "weblogic.jdbc.wrapper.PoolConnection_oracle_jdbc_driver_T4CConnection@324" back into the data source connection pool "cgDataSource", currently reserved by: java.lang.Exception
  
  

However, the attribute (LeakedConnectionCount) that indicates the presence of the problem did not update its value

I thought it was a problem with my application. However, the Admin Console showed the same value.

Does it mean a problem with the Admin Console? I do not think so and I used WLST to review this value.

1. I had to connect to the server using WLST

2. I used domainRuntime()

3. I had to change to

cd('ServerRuntimes/Pegasus/JDBCServiceRuntime/Pegasus/JDBCDataSourceRuntimeMBeans/cgDataSource')

4. I used ls() and as you can see I got the same value.

I am not sure if this is a problem of the version 12.1.3 or just a problem within the configuration on my laptop and then I encourage you to test this counter.

Let me apologize for my lack of skills on web programming. This example would be more useful if I made a web module. However, I hope this post could be useful for you.

Application

The application used in this demonstration was made using NetBeans and you can download the project here: Application. Please be careful, it is a demonstration and as I am not a developer, it could have some bugs. It would be nice if you could develop the web version of this little application.

References list

Rafael (2013) FIXING FILE DESCRIPTOR LEAKS IN LONG-LIVED SERVERS [Online document] Available from: http://oroboro.com/file-handle-leaks-server/ (Accessed: July 20, 2015)

Oracle (2014) How To Detect a Connection Leak Using Diagnostic JDBC Dumps (Doc ID 1502054.1) [Online document] Available from: https://support.oracle.com (Accessed: July 20, 2015)

Oracle (n.d.) JDBC Data Source: Monitoring: Statistics [Online document] Available from http://docs.oracle.com/cd/E13222_01/wls/docs100/ConsoleHelp/pagehelp/JDBCjdbcdatasourcesjdbcdatasourcemonitorstatisticstitle.html (Accessed: July 20, 2015)