TomcatJdbcConnectionTest

The goal of this web app is to show how to analyze the tomcat connection pool in case of abandoned connections.

How it works

This web app let you create as many abandoned connections as you want just clicking on a button. In fact, each time the button is pressed a new connection is opened and never closed. This scenario let us investigate how set up the tomcat datasource configuration in order to show the code line where the connection was abandoned.

Hypotesys

You need the following tools to execute the "experiment". The tool versions are not stricly important but they are what I actualy tested:

Tomcat 7.0.70
Mysql Connector Java 5.1.39
Mysql Server 5.x

Thesis

When a jdbc connection is marked as 'abandoned' a log is shown and a jmx notification is triggered.

Demostration

In order to demostrate the thesis you need to follow these steps:

Starting the web application
Replicating the abandoned connections
Enabling the stacktrace log
Activating jdbc notificaions on jmx
Final considerations

1. Starting the web application

Clone this repository
Change the /META-INF/context.xml specifying username, password and jdbc url of your db under test in the <Resource> section

  <Resource name="jdbc/backoffice"
            auth="Container"
            type="javax.sql.DataSource"
            factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
            validationQuery="/* ping */"
            maxActive="32"
            minIdle="0"
            maxIdle="4"
            maxWait="3000"
            driverClassName="com.mysql.jdbc.Driver"
            username="<change_username_on_context_xml>" password="<change_password_on_context_xml>"
            url="<change_url_on_context_xml>" />

Deploy and run the application on your tomcat

2. Replicating the abandoned connections

Open jconsole and connect to the tomcat using jmx. Open the jmx MBean Catalina -> DataSource -> /JdbcTomcatConnectionTest -> localhost -> javax.sql.DataSource -> jdbc/backoffice and open the 'active' graph clicking on its value.

open in a browser the welcome page [http://localhost:8080/JdbcTomcatConnectionTest/] (http://localhost:8080/JdbcTomcatConnectionTest/) and click on the button open a new abandoned connection.

Now you could see on jconsole that, each time you click on the button, the line of active connections grows and never goes down

3. Enabling the stacktrace log

You don't see any warning in the log because the abandoned connection recognizer is not active by default on Tomcat. From the tomcat documentation regarding the jdbc pool we could use three useful properties:

property name	description
removeAbandoned	(boolean) Flag to remove abandoned connections if they exceed the removeAbandonedTimeout. If set to true a connection is considered abandoned and eligible for removal if it has been in use longer than the removeAbandonedTimeout Setting this to true can recover db connections from applications that fail to close a connection. See also logAbandoned The default value is false.
removeAbandonedTimeout	(int) Timeout in seconds before an abandoned(in use) connection can be removed. The default value is 60 (60 seconds). The value should be set to the longest running query your applications might have.
logAbandoned	(boolean) Flag to log stack traces for application code which abandoned a Connection. Logging of abandoned Connections adds overhead for every Connection borrow because a stack trace has to be generated. The default value is false.

You should therefore try to add the following properties in the <Resource> inside the /META-INF/context.xml as below

  <Resource name="jdbc/backoffice"
...
	removeAbandoned="true"
	removeAbandonedTimeout="10" 
	logAbandoned="true"

...	/>

logAbandoned requests tomcat to print the stacktrace of the code that is responsible of the abandoned connection. removeAbandonedTimeout is set to 10 seconds for speed up the test. removeAbandoned is in charge of

enabling abandoned connections check
if logAbandoned is true, logging the stacktrace
really closing the connection

It's important to know that without removeAbandoned=true the stacktrace will not appear because actually the abandoned connection check is not performed

3.1 Verifying the configuration

restart the tomcat and connect again with jconsole
click on the open a new abandoned connection button as before and take a look on jconsole. Now the line grows and after 10 seconds drops down. If you take a look at the log you shoud see the stacktrace with the point where the connection was opened.

 [Wed Aug 31 17:24:33 CEST 2016] WARNING: [org.apache.tomcat.jdbc.pool.ConnectionPool] Connection has been abandoned PooledConnection[com.mysql.jdbc.JDBC4Connection@173432e9]:java.lang.Exception
	at org.apache.tomcat.jdbc.pool.ConnectionPool.getThreadDump(ConnectionPool.java:1072)
	at org.apache.tomcat.jdbc.pool.ConnectionPool.createConnection(ConnectionPool.java:715)
	at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:644)
	at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:187)
	at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:128)
	at com.fgiovannetti.FireConnector.execute(FireConnector.java:29)

4. Activating jdbc notifications on jmx

Now we have to demostrate that when the connection is abandoned a new jmx notificaton is triggered. First of all we have to add a new property in our <Resource>

  <Resource name="jdbc/backoffice"
...
	jmxEnabled="true"
...	/>

With jmxEnabled a new MBean will be registered on jmx called tomcat.jdbc.

4.1 Verifying the configuration

Restart the tomcat and connect again with jconsole. Go into the path tomcat.jdbc -> ConnectionPool -> jdbc/backoffice -> /JdbcTomcatConnectionTest -> Catalina -> localhost -> org.apache.tomcat.jdbc.pool.jmx.ConnectionPool and click on Notifications and therefore on Subscribe.

Now click on the open a new abandoned connection button as before and take a look on jconsole. Some notifications show up. The message field gives you the stacktrace as in the log.

5. Final considerations

You could think that

tomcat.jdbc -> ConnectionPool -> jdbc/backoffice -> /JdbcTomcatConnectionTest -> Catalina -> localhost -> org.apache.tomcat.jdbc.pool.jmx.ConnectionPool

is very similar to the previously analyzed

Catalina -> DataSource -> /JdbcTomcatConnectionTest -> localhost -> javax.sql.DataSource -> jdbc/backoffice

They are almost the same, but for some reason the second MBean doesn't show any notification event.

gnosly/TomcatJdbcConnectionTest