Connection reference being lost?

[toddrun]

This may be a bug, but I wasn't sure how to verify what "appears" to be happening. Using jboss 3.0.1 with Tomcat 4.0.4 on a Red 7.2 server, we set up a connection pool using microsofts jdbc driver for SQLServer 2000. We set up our mssql-service.xml file with a min of 1 and a max of 2 connections. We then looked at the open processes and set up a trace on SQLServer to watch what was happening.

When we hit our data access code in rapid succession (like an impatient user might), Jboss spawned multiple connections (way more than 2), but that's not the unsettling part. It seems that each time we did a "click-fest", then waited for the timeout period to expire, all the newly spawned connections would drop except one. In other words, after 3 sessions of activity, we were left with 3 connections which appear to be unused by jboss, but are not being garbage collected/destroyed.

How do I verify whether or not this is a bug? What kind of data can I provide to verify that this is occurring? Where should I go from here? David Jencks, if you're reading this, could you please give me a little advice?

Thanks.

[davidjencks]

This seems really odd... unless you are using container managed security and each user is logging into the db as a different user. My first worry is about more than 2 connections being created. Can you provide any more details about what you are doing and how you tell how many (jdbc) connections are created?

thanks

[toddrun]

I'm going to give you as much as I can think will be helpful. Hopefully it's not too much. First of all, we restarted the server and took a screen shot of SQLServers Processes (see ConnGrow.jpg). Then we called out servlet, which calls ReadQueryBean, a stateless session bean (the important code is included in RQSnippet). We then took another screen shot (ConnGrow.jpg - second picture). Then we hammered the site!

The last picture in ConnGrow.jpg shows the connections that were spawned. ConnGo.jpg shows the trace of which connections were reused, and which were spawned anew. After letting the timeout expire (see mssql-service.xml for our config - 1 min, 2 max, 1 minute timeout), we were still left with 3 connections (bottom of ConnGo.jpg).

Though I'm not including the screen prints, I can tell you that of the 3 connections left, only one of them was reused - 2 appear to be zombies. Hammering the server showed that only one of the 3 was used, and after another timeout, we were left with 5 connections (only 1 of which is reused). This will continue until jboss or sql server are restarted, or one of the machines dies.

If you need any other info, have any other questions, or see something stupid on my part, please let me know.

Thanks

[davidjencks]

I'm not sure that mssql's idea of connections are the same as jboss's idea of connections. I will enhance the pool mbean so you can see jboss's idea of the statistics, then we can tell if this is a jboss or ms problem.

If you want to beat me too it, add methods to org.jboss.resource.connectionmanager.JBossManagedConnectionPool

that delegate to poolingStrategy:

getConnectionCount()
getConnectionCreatedCount()
getConnectionDestroyedCount()

Or you can write a little mbean that calls getManagedConnectionPool via the mbean server on the JBossManagedConnectionPool mbean from your config and calls the methods on the returned pooling strategy.

I'm in the middle of some refactoring so I may not get to it immediately

thanks
david jencks


Thanks
david jencks

[toddrun]

So I took your advice, or at least I tried to. I wasn't 100% certain how to do what you posted, so I hacked my own version out. I have a method which calls the 3 methods you mentioned and does System.out with the value of count. I call my method from BaseConnectionManager2.java.allocateConnection

Here's the output I got:
15:14:09,207 INFO [STDOUT] getConnectionCount: 2
15:14:09,209 INFO [STDOUT] getConnectionCreatedCount: 2
15:14:09,210 INFO [STDOUT] getConnectionDestroyedCount: 2
15:14:21,000 INFO [STDOUT] getConnectionCount: 2
15:14:21,001 INFO [STDOUT] getConnectionCreatedCount: 2
15:14:21,002 INFO [STDOUT] getConnectionDestroyedCount: 2
15:14:26,599 INFO [STDOUT] getConnectionCount: 2
15:14:26,600 INFO [STDOUT] getConnectionCreatedCount: 2
15:14:26,601 INFO [STDOUT] getConnectionDestroyedCount: 2
15:14:32,395 INFO [STDOUT] getConnectionCount: 2
15:14:32,396 INFO [STDOUT] getConnectionCreatedCount: 2
15:14:32,397 INFO [STDOUT] getConnectionDestroyedCount: 2
15:22:21,327 INFO [STDOUT] getConnectionCount: 2
15:22:21,329 INFO [STDOUT] getConnectionCreatedCount: 8
15:22:21,329 INFO [STDOUT] getConnectionDestroyedCount: 8
15:22:58,616 INFO [STDOUT] getConnectionCount: 2
15:22:58,617 INFO [STDOUT] getConnectionCreatedCount: 8
15:22:58,617 INFO [STDOUT] getConnectionDestroyedCount: 8
15:33:18,101 INFO [STDOUT] getConnectionCount: 2
15:33:18,102 INFO [STDOUT] getConnectionCreatedCount: 16
15:33:18,103 INFO [STDOUT] getConnectionDestroyedCount: 16
15:36:29,941 INFO [STDOUT] getConnectionCount: 2
15:36:29,942 INFO [STDOUT] getConnectionCreatedCount: 19
15:36:29,942 INFO [STDOUT] getConnectionDestroyedCount: 19

The min is still set to 1 and the max to 2. We still get more than 2 connections in SQL and we get zombied connections.

I guess I don't understand how the Counter class in InternalManagedConnectionPool.java keeps track. As you can see from the output, all the getter methods return 2 on our first session. After waiting 8 minutes, the getConnectionCount is still 2 but the other two methods return 8. After another pause, we hit 16. I don't understand what's going on.

Thanks again

Todd

[davidjencks]

Well, there's nothing like untested code for hiding errors. If you look in InternalManagedConnectionPool$Counter.getDestroyedCount you will see the problem. I'm fixing it in cvs head, where I have also made these into mbean attributes in the pool mbean

Let me know what you find out with more accurate counts.

[toddrun]

The information we get from the getConnection count methods is not consistant with the information we get from SQL Server. We played around with the log output - I've attached the critical portion.

This is incredibly frustrating! You can see that InternalManagedConnectionPool.createConnection gets called 2 times (exactly as we'd expect). But looking at SQL Server, there are 6. After the timeout period (set to 2), you see that the pool is cleaned, and a new connection is created (to get the 1 minimum we've requested). SQL Server shows 3. 2 of those will never be called.

Is the error in the javax.resource.spi.ManagedConnectionFactory? Is it something in the mssql driver? Where do I go from here? It certainly appears that the JBoss code is working fine, but that doesn't help when my boss asks why we have bogus connections showing up in SQL Server.

Thanks

Todd

[toddrun]

[sorry if this shows up twice - doesn't appear that the first submittal was successful]

The information we get from the getConnection count methods is not consistant with the information we get from SQL Server. We played around with the log output - I've attached the critical portion.

This is incredibly frustrating! You can see that InternalManagedConnectionPool.createConnection gets called 2 times (exactly as we'd expect). But looking at SQL Server, there are 6. After the timeout period (set to 2), you see that the pool is cleaned, and a new connection is created (to get the 1 minimum we've requested). SQL Server shows 3. 2 of those will never be called.

Is the error in the javax.resource.spi.ManagedConnectionFactory? Is it something in the mssql driver? Where do I go from here? It certainly appears that the JBoss code is working fine, but that doesn't help when my boss asks why we have bogus connections showing up in SQL Server.

Thanks

Todd

[davidjencks]

Well, the managed connection factory isn't doing anything complicated, just calling driverManager.getConnection(props). Maybe writing a little standalone program that creates 3 connections would be informative.

[toddrun]

I had a colleague write his own connection pool using this driver. Our findings were very enlightening.

His code created a vector, spawned new connections and added them to the vector. The connections were used to make calls against the database. We verified that the connections could be reused, new connections could be added and connections could be removed from the vector.

What we couldn't do was get SQL Server to recognize that the connection was no longer valid. We tried closing the connection, destroying the connection, setting the connection to null - even getting rid of the whole vector. The connections were still held at the server.

So, unless you have another suggestion, we plan on writing what we're calling a "static pool" mbean that will start up with a set number of connections and service all requests with those connections. We'll include logging so that we can tell when our static pool abandons an unusable connection, or when the static pool has to check each connection multiple times for availability. While it's not nearly as scalable as the jboss connection pool, we hope to get enough feedback to manually tune the pool.

Any suggestions, comments, ideas, or insults are welcome.

Thanks

Todd