SQL Sam and the Too-Slow Query - Part 1 (with clues)

Wednesday Aug 25th 1999 by Steve Hontz
Share:

There is still one problem that pops up every now and then,' said Tulsa. 'Sometimes the agents report time-out errors when they're waiting to look at the order details for a particular order number. The time-out is thirty seconds, and it doesn't happen often, but none of the agents remember it ever happening before the upgrade.

Environment: SQL Server 6.5, SP4
Turn OFF clues

A familiar shadow fell across the anti-glare screen of SQL Sam's workstation at Books-R-Us. "Hello, Tulsa," Sam grinned, looking up. "Haven't seen you in a while..."

Tulsa Jones brushed back an errant lock of platinum-blonde hair. "Well, Sam, it's been pretty busy around here since we installed the new Bookworm 2 software upgrade," she said. Tulsa was the manager in charge of all the Books-R-Us customer service representatives. She had provided much of the information behind the database design for Bookworm 2, the application the agents used to handle customer's book orders.

"Yes, there were a few unexpected glitches, but the database seems to running smoothly now," said Sam.

"Thanks to you, Sam. But you know, there is still one problem that pops up every now and then," said Tulsa. "Sometimes the agents report time-out errors when they're waiting to look at the order details for a A CLUE!particular order number. The time-out is thirty seconds, and it doesn't happen often, but A CLUE!none of the agents remember it ever happening before the upgrade."

"Let's take a look," said Sam. "What's the table involved?"

"It's called 'order_details'. There- that's it," she said, pointing at the window Sam had brought up:

"It's A CLUE!keyed by the order number and the item number. When the agent selects a particular order number, the details window shows the individual items in the order."

"Okay, it's time to do a SQL Trace," said Sam.

Continue with SQL Sam and the Too-Slow Query

Go to the solution now!

Back to SQL Sam Cases


Steve Hontz is President of The Bit Corner, Inc., a Phoenix-based consulting firm specializing in Windows NT, C++, and SQL Server development. You can reach him at steve@bitcorner.com.


SQL Sam and the Too-Slow Query - Part 2

Environment: SQL Server 6.5, SP4
Turn OFF clues

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 A CLUE!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 A CLUE!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."

What did SQL Sam see? Go to the solution now!

Review SQL Sam and the Too-Slow Query - Part 1

Back to SQL Sam Cases


Steve Hontz is President of The Bit Corner, Inc., a Phoenix-based consulting firm specializing in Windows NT, C++, and SQL Server development. You can reach him at steve@bitcorner.com.


SQL Sam and the Too-Slow Query - Solution!

"I don't see it," Tulsa admitted. "What are you looking at, Sam?"

"Look at how the index is defined, Tulsa. You have a composite key on order_num and item_num, but look at the order of the column names in the index."

"item_num, order_num. Both are needed to make the key unique. What's so special about the order of the columns in the key?"

"Everything. Here's an example. The phone book is essentially indexed by last name, then first name, right? So if I ask you to find Jones, Tulsa, you can do it pretty quick, right?"

"Sure, I just find the Jones' section, and then look for "Tulsa". No problem."

"But what if I asked you to find everyone whose first name is Tulsa? Then how would you do it?"

"Geesh, I'd have to scan the entire phone book, looking at every name, just to see if their first name was Tulsa. The phone book isn't organized by first name-- oh, I get it. The index on the table was created in reverse order, organized by item number first, then order number, so the optimizer couldn't use the index to find a particular order number. That explains the long delay- the entire 300,000 rows had to be checked. But wait a minute - the last time we ran the query, it completed in less than a second. How could that be?"

"I promised I'd tell you. The clue is that while the logical read count was high, indicating a lot of the table had to be scanned, the physical read count was low, indicating that the second time the query was run, the data was in RAM cache. That's why you didn't see this problem all the time- if the data was already in the cache, the query ran in a reasonable amount of time. But if that table got dumped out of the cache, SQL Server had to go to disk to read it back in- resulting in your time-outs."

Sam and Tulsa checked what had happened during the software upgrade. They discovered that the order_details table had been modified by an upgrade script that created a new table and loaded the data from the existing table into it. The developer who had created the script had inadvertently switched the order of the columns in the PRIMARY CONSTRAINT option.

Sam rebuilt the index on the table, putting order_num first, then item_num, in the PRIMARY KEY constraint. Sam and Tulsa then ran the query again, and this time the optimizer choose the clustered index, resulting in only 7 logical reads to find the data. The agents reported no more problems with the order details window.

Go read more exciting SQL Sam Cases!

See the story behind the story in Behind the SQL: The Making of SQL Sam!


Steve Hontz is President of The Bit Corner, Inc., a Phoenix-based consulting firm specializing in Windows NT, C++, and SQL Server development. You can reach him at steve@bitcorner.com.


Share:
Home
Mobile Site | Full Site
Copyright 2017 © QuinStreet Inc. All Rights Reserved