You will never be able to find out the time taken to execute a query in the database by measuring the the time it takes to complete any variant of JdbcTemplate.query...() or JdbcTemplate.execute...() . Making use of any of these functions involve the following steps:
- Time taken to borrow a connection from the pool
- Time taken to create a statement from the connection and bind the parameters if needed
- Time taken to send the query to the database
- Time taken to execute the query in the database (this is the time you are specifically interested in)
- Time taken to receive the result from the database (depending on the fetch size you have set, this will vary). For UPDATEs, only the update count is sent back from the database.
- Time taken in the row mapping (if you are making use of RowMapper) or time taken to consume all the rows from ResultSet (if you are making use of ResultSetExtractor)
- Time taken to return the connection to the pool
If you are making use of a connection pool that has all the connections borrowed all the time, then the time taken in steps 1 and 7 are significant. For e.g. during my experiments I have seen some threads waiting as long as 100 ms when there are 10 connections and 23 threads using the connection pool.
So the most reliable way of measuring the time spent in the database will involve the following things:
- Make sure you understand the average round-trip time between the database and your application. You will have to use this one for your analysis. You can use ping to measure this. If ICMP is not allowed in your network, make use of netcat.
- Make use of StatementCallback since it will help you in measuring time taken from steps 2 to 6 above. In other words the measurement will not be skewed by the DBCP borrow and return.
- Make use of PreparedStatementCreator variants of query() so that you will know the time when the statement has been created.
- If you are making use of RowMapper, the approximate time the query completed is when you start processing the first row. If you are making use of ResultSetExtractor, the time when extractData is called is the approximate query completion time. If you are making use of RowCallbackHandler, make use of ResultSet.isFirst() to decide the approximate query completion time.
- There is no way of excluding the time taken in DBCP when making use of batchUpdate().
- There is no way of excluding the time taken in returning a connection back to the pool when making use of update() functions.