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.

Comments

Post a Comment

Popular posts from this blog

The mysterious ORA-03111 error

Recently one of the applications that I developed started throwing exceptions, that had the following message: SQL state [72000]; error code [1013]; ORA-03111: break received on communication channel When I googled around, I couldn't come across anything useful. Sadly enough most of the sites just showed the documentation for that error, without any explanation from anyone experiencing that issues. So here you go, with the best possible explanation that I could come up with. My application sets two things on the connection that is throwing this exception: It sets the fetchSize to be 2500 rows It sets the query timeout to be 10 seconds The database server and the application are separated over a long latency network (actually there is a NetEm box that emulates the long latency between these two boxes) which has a latency characteristic of 50+/-5 milliseconds. This is the whole setup. It is important to understand how the timeout is handled by the Oracle client (in my case JDBC clien...
Read more

Note on allocationSize parameter of @SequenceGenerator while using JPA

I ran into what I thought as an issue while I was using the sequence ID generation strategy in JPA. The JPA provider I am using is Hibernate. I think sharing my experience will save someone some time. To use a sequence (For e.g. Oracle sequence) to generate values and assign them to the ID field of your persistence object, you will following something like this: @Id @Column(name = "ITEM_ID") @GeneratedValue(strategy = GenerationType.SEQUENCE, generator="ItemIdSeqGenerator") @SequenceGenerator(name="ItemIdSeqGenerator", sequenceName="ITEM_ID_SEQ", allocationSize=1) private long itemId; This means the following things: The @Id annotation says that the field itemId is a primary key. The @Column annotation says that the corresponding column in the database is ITEM_ID. The @GeneratedValue says that the value that needs to be populated in the itemId should be generated, while that object is persisted. The strategy to generate the value is to...
Read more

xVM's vboxmanage.exe command

You can view and edit the configuration of your guest OSs using the vboxmanage command. To view the list of guest OSs you have, give the following command: C:\Program Files\Sun\xVM VirtualBox>VBoxManage.exe list vms VirtualBox Command Line Management Interface Version 2.2.2 (C) 2005-2009 Sun Microsystems, Inc. All rights reserved. "MySolaris" {dc6dc85f-5583-4a1b-bf3e-969941a2cd91} "Ubuntu" {eb973bbf-d86e-4579-85eb-6ea2cd12bf95} "Debian" {3e784597-89d8-4f17-90cb-63e866c651a3} "openSUSE" {6862884e-60e1-4c65-8aab-b57ec38a3922} "Debian-Lenny" {4b561432-abac-4a27-a501-b42af956b96b} To view the specific guest, you can use the UUID of the guest. For e.g. C:\Program Files\Sun\xVM VirtualBox>VBoxManage.exe showvminfo eb973bbf-d86e-4579-85eb-6ea2cd12bf95 VirtualBox Command Line Management Interface Version 2.2.2 (C) 2005-2009 Sun Microsystems, Inc. All rights reserved. Name: Ubuntu Guest OS: Ubuntu UUID: eb973bb...
Read more