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.
SQL Sam and the Too-Slow Query - Part 1
Environment: SQL Server 6.5, SP4
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 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."
"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 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
SQL Sam and the Too-Slow Query - Part 2
Environment: SQL Server 6.5, SP4
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'
-- 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:
The type of query is SELECT
...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
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
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!