The Trace

SQL Sam turned on SQL Trace and selected the options to include performance information and to log to a file. After letting it run for a few minutes, Sam stopped the trace. He and Tulsa then examined the trace file.

“Look, here’s one,” said Sam, pointing at a query that took a long time:

select * from order_details where order_num='42758025'
go
-- 4/15/99 07:53:37.326 Duration 35.297, CPU 0.125, Reads 1558, Writes 0

“Yep,” agreed Tulsa. “That one definitely exceeded the 30 second time-out. Now how do we fix it?”

“Let’s find out why the query takes so long to run, first. We need to see what the optimizer did with the query.” Sam opened a query window in the Enterprise Manager and pasted the query into it. He turned on the Show Query Plan, Show Stats Time, and Show Stats I/O options. Then he ran the query. This is what they saw:

STEP 1
The type of query is SELECT
FROM TABLE
order_details
Nested iteration
Table Scan

…table results omitted…

Table: order_details scan count 1,  logical reads: 20490,  physical reads: 0,  read ahead reads: 0
Server Execution Times:  cpu time = 0 ms.  elapsed time = 703 ms.

“Oh oh,” said Sam. “The optimizer did a table scan, when it should have used the clustered index from the key.”

“Okay, I know a table scan on a large table is generally a bad thing. But look – this time the query took less than a second,” exclaimed Tulsa.

“I can explain that. But first let’s see if the optimizer had good distribution statistics to work with.” Sam ran dbcc update_statistics (order_details, order_details_PK) and got this result:

Updated              Rows        Steps       Density
-------------------- ----------- ----------- ------------------------
Apr 14 1999  2:00AM  297184      89          0.00161452
All density              Columns
------------------------ ------------------------------
0.073217                 item_num
3.36492e-006             item_num, order_num

“Well, the distribution statistics are up-to-date,” sighed Tulsa. “I guess we still don’t know what’s wrong.”

“On the contrary,” announced Sam. “It’s right there.”