JdbcTemplate pooling and performance

Question

I am working on a project where we are optimizing a legacy codebase that used boilerplate jdbc code and in our new project we use springs jdbcTemplate. I've found the query times in the legacy code are twice as fast and am curious if its jdbcTemplate that's at fault or something else...

We use apache commons BasicDataSource (to provide the pooling). My question is, I'm not too sure if the pooling is actually working correctly. Below are my configurations...

data source

Wiring of the datasource

To analyze this, I start the application and wire up all the jdbc stuff and simply run the same query 100 times. I am also using log4j to get some metrics around the actual performance. 1 line will print the actual jdbc call time, and I have an additional wrapper around the entire jdbcTemplate call to see how long the entire thing takes (shown below)...

Edit: Adding image of RowMapper

Below shows what my logs look like...

DEBUG org.springframework.jdbc.core.JdbcTemplate - Executing prepared SQL query
DEBUG org.springframework.jdbc.core.JdbcTemplate - Executing prepared SQL statement [my select query]
DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Fetching JDBC 
Connection from DataSource
DEBUG com.custom.frameworkx.spring.datasource.DebugDataSource - before executeQuery() sql=my select query
DEBUG com.custom.frameworkx.spring.datasource.DebugDataSource - after executeQuery() [time=30ms] sql=my select query
DEBUG com.custom.frameworkx.spring.datasource.DebugDataSource - 
DebugResultSet.close()
DEBUG org.springframework.jdbc.datasource.DataSourceUtils - Returning JDBC Connection to DataSource
Full jdbcTemplate call time: 119

Notice how the actual query time takes 30 milliseconds. yet the entire jdbcTemplate call takes 119 milliseconds. I assume this is from jdbcTemplate overhead like adding + releasing resources so I guess this might be acceptable but in the legacy version of this code the entire connection creation+query+resource releasing is still twice as fast.

While debugging through org.springframework.jdbc.datasource.DataSourceUtils.java, I can see the code goes to line 328, which to me doesn't really look like its returning the connection to the pool for re-use later, is this the expected behavior of springs jdbcTemplate? To me it looks like if pooling was working it should hit line 323.

Above the code you've highlighted in `JdbcTemplate` you can see if the connection is transactional it won't close it. The way you make a connection transactional is to add the `@Transactional` annotation to the calling method, this ensures a single connection is reused and shared by the different processes inside of the method. It would be interesting to see if adding this makes any difference to performance. We use it all the time to ensure connection pool efficiency. — mohammedkhan, Jul 16 '18 at 15:31
What does `getJdbcTemplate()` do? (please post code and not images). I'm guessing it creates a new instance which is different from the bean which creates a new instance in the constructor only once. Also, JdbcTemplate is thread safe so instead of injecting the data source and creating a new instance you could inject a jdbcTemplate directly. — Andrew S, Jul 16 '18 at 15:37
With `jdbcTemplate` as result of your code you get list of objects converted from all records in result set. Is it what you also do in your boilerplate jdbc code? Also there might be difference in `fetchSize` between your code with jdbcTemplate and your plane jdbc code — Ivan, Jul 16 '18 at 15:42
@Andrew S getJdbcTemplate is just a method from the abstract DAO layer. It simply returns the autowired jdbcTemplate, it doesn't create a new one. — Jason, Jul 16 '18 at 16:12
@Ivan I already tried setting the fetchSize on the jdbctemplate with many different values and that made no difference. the actual queries are quite small, only returning a small set of rows. To my understanding the fetchsize will only optimize larger running queries at the cost of memory — Jason, Jul 16 '18 at 16:13
@Jason, but what about all other stuff? What do you measure in your jdbc code? Just time taken by `preparedStatement.executeQuery()`? — Ivan, Jul 16 '18 at 16:19
@Ivan yes currently thats all thats logged. I'm actually forced to use an in-house jdbc debugger that I was also skepticle about if it had some processes that could be slowing things down. For now I'm going to have a look into optimizing that to get more information as well as the transactional suggestion from Mohammed — Jason, Jul 16 '18 at 16:29
You state it is twice as fast BUT are you really comparing apples with apples or apples with bananas? That is hard to tell from only posting the Spring code here. The Spring code also does object conversion, creating statements etc. etc. so make sure you are really comparing the same things and not half of it. Also pooling is working just fine, calling `close` on a pooled connection will actually return it to the pool. Final thought you added/enabled logging, logging is slow and really slow. Disable query logging at least. — M. Deinum, Jul 16 '18 at 17:53
@M.Deinum thanks, im comparing granny smith apples to candy apples basically. Both codebases have the same entry point on the service layer -> dao layer. So technically I am wrapping both entry/exit points to what I believe to be enough of a valid comparison. I tried Mohammed's suggestion and I do see the transactional logs now as well as the jdbcTemplate code going in a different direction but ultimately it didn't help much with performance. I guess I'll accept that the pooling is working correctly and start searching elsewhere. Thanks to all! — Jason, Jul 16 '18 at 18:47
I would really make sure you are really testing the same things (wouldn't be the first time that someone thought the were measuring the same but instead weren't). Which `RowMapper` are you using? Also instead of adding debug and timing logs all around, I suggest configuring a `PerformanceMonitorInterceptor` for both apps/services and use that for comparison (you can configure it with some AOP). — M. Deinum, Jul 16 '18 at 18:49
@M.Deinum org.springframework.jdbc.core.RowMapper. I've got some timing logs wrapped around the rowmapper and suprisingly it spits out 0 milliseconds. the row mapper only deals with 1 result set with my current test so I doubt thats where the overhead is — Jason, Jul 16 '18 at 18:51
Well obviously that is the interface, but are you using a custom implementation or something like the `BeanPropertyRowMapper` (which is slower then a custom implementation). If it is a custom implementation, please add it to your post. And in addition instead of the Commons DBCP pool I would suggest to use HikariCP as the connection pool (more recent, activity maintained and apparently faster). — M. Deinum, Jul 16 '18 at 18:52
@M.Deinum added a screenshot of the rowmapper, sorry had to block some sensitive things. — Jason, Jul 16 '18 at 19:02
Generally I dislike images of code (that is what we have code tags etc. for). But there isn't anything strange in there (seen row mappers doing the iteration etc. ). Just wanted to make sure that that wasn't the case. — M. Deinum, Jul 16 '18 at 19:04
yeah i normally use code snippets as well, was faster to just screenshot it in this case — Jason, Jul 16 '18 at 19:04
Well thanks again everyone for tossing in your inputs, it was all valuable. I'm going to have a look at the PerformnaceMonitorInterceptor and see if this problem is throughout the application or isolated to specific services. Thanks! — Jason, Jul 16 '18 at 19:11

JdbcTemplate pooling and performance

0 Answers0