Friday, April 17, 2009

How to measure time to execute a query when using DBCP+JdbcTemplate

Keep the following things in your mind if you are planning to measure the time taken to execute a query when you make use of Apache DBCP + Spring JdbcTemplate.

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:
  1. Time taken to borrow a connection from the pool
  2. Time taken to create a statement from the connection and bind the parameters if needed
  3. Time taken to send the query to the database
  4. Time taken to execute the query in the database (this is the time you are specifically interested in)
  5. 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.
  6. 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)
  7. Time taken to return the connection to the pool
If you are sending the request over a long latency line, the time you are measuring is bound to be off by a few milliseconds due to steps 3 and 5. For e.g. to reach from west coast to east coast in US, it might takes 50 ms or more.

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:
  1. 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.
  2. 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.
  3. Make use of PreparedStatementCreator variants of query() so that you will know the time when the statement has been created.
  4. 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.
  5. There is no way of excluding the time taken in DBCP when making use of batchUpdate().
  6. There is no way of excluding the time taken in returning a connection back to the pool when making use of update() functions.
Hope these guidelines will be useful to you. I followed them when I had to measure the time difference between the database and the host where my application was running. It is very tricky in the presence of the DBCP since borrowing and returning always skews the numbers.

No comments: