Determine the Performance Effect of Query Plan Changes

Q: How can you tell whether the stored procedure query plan changes you make actually improve your CPU time and logical reads?

A: Apart from looking at the query plans themselves—which I do using SQL Sentry’s free and excellent Plan Explorer tool—I look at three measurements to determine whether my changes have been effective in increasing performance: elapsed time, CPU time, and I/O. I can obtain all this information from the following two commands:

SET STATISTICS TIME ON;SET STATISTICS IO ON;

Figure 1 shows an example of some of the output these commands produce for a poorly performing query at a client site (table names changed). As you can see, the output shows how many I/O operations are performed for each table, any temporary worktables that are required, number of scans, CPU time, and elapsed time.

Figure 1: Example output for a poorly performing query

(3342 row(s) affected)Table 'table1'. Scan count 1, logical reads 633, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.Table 'table2'. Scan count 1, logical reads 23, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.Table 'table3'. Scan count 7, logical reads 3538, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.Table 'table4'. Scan count 281, logical reads 17402, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.Table 'Worktable'. Scan count 267, logical reads 2143562, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.(1 row(s) affected)SQL Server Execution Times:   CPU time = 33495 ms,  elapsed time = 45545 ms.

By creating indexes, updating statistics, changing the code, and using other tuning methods, you can alter the query plan for better or worse (hopefully better!). Run the query again after making changes, and see whether the numbers improve. Be careful to make only one change at a time so that you can see whether the change was beneficial or detrimental.

Figure 2 shows the output for the same query after adding some good covering nonclustered indexes. As you can see, the large worktable disappeared, the number of I/O operations on two of the tables dropped drastically, and the CPU and elapsed times decreased.

Figure 2: Output after adding nonclustered indexes

(3342 row(s) affected)Table 'table1'. Scan count 1, logical reads 633, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.Table 'table2'. Scan count 1, logical reads 23, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.Table 'table3'. Scan count 7, logical reads 301, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.Table 'table4'. Scan count 281, logical reads 412, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.(1 row(s) affected)SQL Server Execution Times:   CPU time = 1233 ms,  elapsed time = 1544 ms.

Of course, a plethora of performance monitoring tools and methodologies exist. However, using the two commands I cover here is one of the simplest ways to measure performance changes.