Saturday, March 20, 2010

Where a DB Request Spends Time in DB2 9.7?

This title may sound somewhat familiar if you have been following my Blog for over a year. More than a year ago, I wrote about the shortcomings of time spent monitoring in DB2 (see my post “Where a DB Request Spends Time”). Last year when DB2 9.7 was released (around June 2009), I was thrilled to see “Time-spent monitor elements are more comprehensive” under monitoring enhancements in DB2 9.7. Since then I have been thinking about installing DB2 9.7 on my laptop and having a closer look at this enhancement. Finally, I got chance to do so and here I am going to share my findings.

Without spending too much time trying to come up with a more complex workload, I created a table t3 with similar structure as syscat.columns and populated it with rows from syscat.columns. Then I ran a query against this table as shown below. The real elapsed time of this SQL was more than 38 minutes (long enough for my analysis purpose).

Listing 1

Before I start analyzing the time spent by above SQL, let me list some of the queries that I used for this analysis.

Following query gives the client idle wait time, total request time, total wait time and various processing times for each connection in the database.

Listing 2

If you are interested to drill down the total wait time of each connection, following query can be used.

Listing 3

A connection can have more than one Unit of Work (UOW) and if you are interested to monitor the time spent on UOW level, following query can be used.

Listing 4

Again, if you want to drill down the total wait time of each UOW, following query can be used.

Listing 5

If you are interested to monitor time spent on statement level, you can use mon_get_pkg_cache_stmt table function. Following query gives info on time spent by top 10 dynamic SQL statements (sorted by statement execution time).

Listing 6

If you want to drill down the wait time of dynamic SQL statements returned by above query, following query can be used.

Listing 7

In all the above monitoring queries (Listing 2 through 7), I have intentionally left the WHERE clause as you can use the appropriate WHERE clause as per your specific need. Also, the result set of monitoring table functions used in above queries can be altered through the input parameters passed to those table functions. Check the documentation of these table functions for more detail.

In each of the above monitoring queries, SELECT list has indentation and the indented columns give the individual components of the time spent monitoring element selected just before the indented columns. “Hierarchy of time-spent monitor elements” on DB2 Information Center was very helpful while writing above queries. Also, you might have noticed the most of the wait time components are suffixed with “_wait_time” and similarly most of the processing time components are suffixed with “_proc_time”. Any remaining ambiguities get clarified by looking at the documented hierarchy of time-spent monitor elements.

Though, I found the time-spent monitoring elements available at each level (Connection, UOW, Statement) comprehensive, here I am going to present only the UOW level time spent monitoring for the SQL execution in Listing 1.

Here is the output of db2_mon_uow.sql at the end of SQL execution in Listing 1. To make it more readable, I have presented it vertically.

Listing 8

In the above output and in fact in all the columns selected in Listing 2 through 7, the unit of time is millisecond. As you can see total request time (~2242 seconds) is very close to sum of various time components (~2237 seconds) that constitutes the total request time. Even a minor difference (5 seconds or 0.2 %) can be clearly explained by “Other” category as documented under “Hierarchy of time-spent monitor elements” on DB2 Information Center. Though, the real elapsed time as shown in the output of “time” command (in Listing 1) is higher than the total request time reported by DB2, it can be due to the difference in time recording boundaries used by “time” command versus what’s used by DB2.

Similarly, if you want to drill down the total wait time, here is the output from db2_mon_uow_wait.sql

Listing 9

The difference between total wait time and sum of individual wait time components is just 65 milliseconds.

With this time spent monitoring enhancement, now we can easily find out where a DB request is spending maximum time and accordingly address any problem areas in database if present. Kudos to IBM DB2 team for putting this enhancement in DB2 9.7.