Analyzing connections which are not being reused

Unofficial Content

Purpose

In some cases the performance of the application can degrade and the first analysis results throw that connections are not being reused in the connection pool, and new connections are created in order to meet new requests.

Using JMX you can check the state of the connections of the connection pool.

The connections in the connection pool are returned to it (and are able to be reused) when there are no open cursors for these connections and there are no uncommited changes (so a commit or a rollback needs to be performed in order to the connection be returned to the connection pool).

When you suspect that there are hung connections, that means that connections are not being returned to the pool, so new connections need to be created, and the others are not being re-used, one possibility is to investigate the application behavior using JMX. In this case we will be using the Management pack (not the Performance pack).

So do the following:

1. Activate JMX. Set Enable Management Property.

2. Open any JMX monitor, such as Jconsole.

3. See the pack GeneXusApplicationServer.ApplicationName.Datastore.ConnectionPool in the console. There you can check the following:

  • ConnectionCount - It indicates the current number of open pool connections.
  • FreeConnectionCount - It indicates the number of free pool connections.
  • RecycledConnectionCount - It indicates the number of connections that were recycled.

You can generate a dump of this information, by which you get a XML file with the summary.

dumppoolinformation

4. In the pack GeneXusApplicationServer.ApplicationName.Datastore.ConnectionPool.Connection you can see all the connections which are alive, and there you can see the attributes of each of them, in particular:

  • Available - It indicates whether this connection is available to be assigned (true) or not.
    availableconnection
  • LastUserAssigned - It's the last user assigned to the connection.
  • OpenCursorCount - It indicates the current number of open cursors in the connection.
    OpenCursorconnection
  • UncommitedChanges - It indicates if the connection has open UTLs (transactions).
    Uncommitedchangesconnection
  • LastSQLStatement - It indicates the last statement already executed or being executed by the connection.

By recycling the connection pool through the "recycle" button of JMX console (in GeneXusApplicationServer.ApplicationName.Datastore.ConnectionPool pack ), you force all the connections which are "recyclable" to be recycled (all the connections which have no open cursors nor uncommitted changes). Application continues the flow of execution after recycling the connections. The recycle from JMX console is on demand, different from the recycle from the application itself which takes effect when there is a new connection request.

When connections are "hung" some of these attributes (OpenCursorCount or UncommitedChanges) do not apply to the conditions needed, so the connection cannot be recycled. There you see the connections which are causing the problem.

In this case you see in the "dump pool" file, the cause of this, and the LastSQLStatement which was executed (which is useful in most cases).

In most cases it's useful also to generate a JDBC log file also, and search for the connection (Connection_Information Id) and the LastUserAssigned. There you can see the statement executed and possibly the cause of the cursor being still open, or the transaction not being closed (by a commit or rollback).

Example

For example, in this case the dump pool file shows this connection which seems to be "hung" (because the application ended in fact but the connection cannot be reused).
 

<Connection_Information Id="13198090">
  <PhysicalId/>
  <CreateTime>29 Feb 2012 18:59:02 GMT</CreateTime>
  <LastAssignedTime>29 Feb 2012 18:59:02 GMT</LastAssignedTime>
  <LastUserAssigned>1972881012</LastUserAssigned>
  <Error>false</Error>
  <Available>false</Available>
  <OpenCursorCount>1</OpenCursorCount>
  <UncommitedChanges>false</UncommitedChanges>
  <RequestCount>5</RequestCount>
  <LastSQLStatement>
   <!CDATA select sid from v$session where audsid = (select sys_context('userenv','sessionid') from dual)>
  </LastSQLStatement>
  <LastSQLStatementTime>29 Feb 2012 18:59:17 GMT</LastSQLStatementTime>
  <LastSQLStatementEnded>true</LastSQLStatementEnded>
  <LastObject>ptest</LastObject>
</Connection_Information>

If you generate a JDBC log file per connection, the connection file will be x13198090.log. 
There you can search for "user" "1972881012" and see the statement being executed and possible causes of the problem. 

Note that the "user" is shown as follows in JDBC log file:
(1972881012)(22:41:43.276)GXConnection/13198090: Reusing cursor H01IZ2..............

Note also that you are specified the name of the GeneXus object involved (where the statement is executed).

Note

When you shutdown the application server (Tomcat for instance), GeneXus application forces a rollback in all connections which are open. In particular by performing a shutdown of application server, connections which were kept "hung" will be rollback.