stored procedure MUCH slower than sql in SQL QA

Please start any new threads on our new site at https://forums.sqlteam.com. We've got lots of great SQL Server experts to answer whatever question you can come up with.

All Forums

SQL Server 2000 Forums

Transact-SQL (2000)

stored procedure MUCH slower than sql in SQL QA

Author

Topic

gdeconto
Posting Yak Master

107 Posts

Posted - 2004-03-03 : 18:00:16

I am finding that some stored procedures are MUCH slower than if I run the exact same code thats in the stored procedure directly in Query Analyser.

Has anyone else come across this?? Not sure why this should be as I thought stored procedures were supposed to be FASTER instead of slower.

For example, I have a stored procedure that takes 7 seconds to run, but only 1 or 2 seconds when I execute the code directly in QA.

Thats a very big difference when it has to be run thousands of times.

Any ideas/comments? Only found one other forum message similar to this but it involved four part names which is not my problem.

Any help appreciated. Here is an example of what the stored procedure does:
-----------------------------------

CREATE PROCEDURE getReport1 @brand_code varchar(5)
AS

SET NOCOUNT ON

DECLARE @eolw datetime, @day int, @week int, @year int

-- get end of last week
SET @day = datepart(weekday, getdate())
IF @day = 1
SET @day = 8

-- remove time part of date (using a function I created to do this)
SET @eolw = dbo.justDate(dateadd(day, -@day + 1, getdate()))

-- get week and year of end of last week
SET @week = datepart(week, @eolw)
SET @year = datepart(year, @eolw)

-- return summarized data
SELECT
sum(CASE WHEN ([year] * 52 + [week]) between (@year * 52 + @week - 12) AND (@year * 52 + @week) THEN isNull(cutcases, 0) ELSE 0 END) as 'shorts',
sum(CASE WHEN ([year] * 52 + [week]) between (@year * 52 + @week - 4) AND (@year * 52 + @week) THEN isNull(cases_actual, 0) ELSE 0 END) as '4wma',
sum(CASE WHEN ([year] * 52 + [week]) between (@year * 52 + @week - 12) AND (@year * 52 + @week) THEN isNull(cases_actual, 0) ELSE 0 END) as '12wma',
sum(CASE WHEN ([year] * 52 + [week]) between (@year * 52 + @week - 52) AND (@year * 52 + @week) THEN isNull(cases_actual, 0) ELSE 0 END) as '52wma'
INTO #t1
FROM somedatabase..myview
WHERE brand_code = @brand_code
GROUP BY field1, field2, field3

-- make the values actual weekly averages
UPDATE #t1
SET
shorts = round(shorts / 12, 0),
[4wma] = round([4wma] / 4, 0),
[12wma] = round([12wma] / 12, 0),
[52wma] = round([52wma] / 52, 0)

SELECT *
FROM #t1
WHERE [52wma] <> 0
ORDER BY field1, field2, field3

DROP TABLE #t1
GO

tkizer
Almighty SQL Goddess

38200 Posts

Posted - 2004-03-03 : 18:26:26

Stored procedures are faster than when you have the T-SQL code inside an application. That's different from having the code inside Query Analyzer.

Tara

gdeconto
Posting Yak Master

107 Posts

Posted - 2004-03-03 : 18:37:37

understood, but thought having a precompiled and optimized sproc would be faster than compiling and optimizing the sql code in query analyser.

at the very least, I would have thought the times would have been pretty close (ie within a second of each other), not five seconds or so difference. Especially since both paths do the same work and return the exact same results.

Thought it might have been that the sproc needed to be recompiled but when I forced it, there was no diff in time.

Havent seen anything in the execution plan of each that gives me any hint.

any help appreciated.

ChrisFretwell
Starting Member

43 Posts

Posted - 2004-03-03 : 19:18:32

Put both the sproc and the code for it in QA and see what the query plans are. Its quite possible that when your sproc was compiled (and the plan saved) that your data was quite different from what it is now, or new indexes were created etc.
If that was the case, recompile your sproc and see if it will use the new and improved plan.

tkizer
Almighty SQL Goddess

38200 Posts

Posted - 2004-03-03 : 19:22:11

He already recompiled it (see his last post).

Does a stored procedure have more overhead than straight T-SQL in Query Analyzer? That's what I'm wondering.

Tara

eyechart
Master Smack Fu Yak Hacker

3575 Posts

Posted - 2004-03-03 : 21:42:45

can you run your code (in QA) with the following options set?

SET STATISTICS IO ON
SET STATISTICS TIME ON

If you could post the results for both runs we can tell where SQL server is spending time.

-ec

robvolk
Most Valuable Yak

15732 Posts

Posted - 2004-03-03 : 22:47:22

Also trying dropping the procedure, run DBCC FREEPROCCACHE, then recreating it. Sometimes plans get stuck in cache and don't always recompile properly unless you drop them.

drymchaser
Aged Yak Warrior

552 Posts

Posted - 2004-03-04 : 08:47:12

When you run it in QA do you run each section separately or in a batch or do you have GO statements between them when in QA?

gdeconto
Posting Yak Master

107 Posts

Posted - 2004-03-04 : 10:27:13

and the winner is ............. robvolk.

and the answers to the posted questions are:

1. drymchaser: I copied all the sproc code to QA, which has only a single GO at the end, added the setup code for the single parameter, then ran the code

2. eyechart: here are the results of the QA Sql code execution (pre robvolks DBCC FREEPROCCACHE or deleting the sproc):

Table 'table1'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0.
Table 'table2'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0.
Table 'table3'. Scan count 32, logical reads 64, physical reads 0, read-ahead reads 0.
Table 'table4'. Scan count 32, logical reads 75, physical reads 0, read-ahead reads 0.
Table 'table5'. Scan count 1, logical reads 131, physical reads 0, read-ahead reads 0.
Table 'table6'. Scan count 2, logical reads 7204, physical reads 19, read-ahead reads 76.
Table 'table7'. Scan count 2, logical reads 1751, physical reads 5, read-ahead reads 24.
Table '#t1_________________________________________________________________________________________________________________0000009BC361'. Scan count 0, logical reads 1, physical reads 0, read-ahead reads 0.

SQL Server Execution Times:
CPU time = 1015 ms, elapsed time = 1207 ms.
Table '#t1_________________________________________________________________________________________________________________0000009BC361'. Scan count 1, logical reads 4, physical reads 0, read-ahead reads 0.

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 136 ms.
field1 fields2 field3 shorts 4wma 12wma 52wma
--------- ---------------------------------------- ---------------------------------------- ---------------------------------------- ---------------------------------------- ---------------------------------------- ----------------------------------------
01 result1 NULL 8.00000000000000000 60 22 17
03 result2 NULL 226.00000000000000000 54 90 54

Table '#t1_________________________________________________________________________________________________________________0000009BC361'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0.

3. eyechart: here are the results of the sproc execution (pre robvolks DBCC FREEPROCCACHE or deleting the sproc):

SQL Server parse and compile time:
CPU time = 500 ms, elapsed time = 1765 ms.

Table 'table1'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0.
Table 'table2'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0.
Table 'table3'. Scan count 1, logical reads 4, physical reads 0, read-ahead reads 0.
Table 'table4'. Scan count 2, logical reads 131, physical reads 0, read-ahead reads 0.
Table 'table5'. Scan count 2, logical reads 126, physical reads 0, read-ahead reads 0.
Table 'table6'. Scan count 2, logical reads 7204, physical reads 477, read-ahead reads 5880.
Table 'table7'. Scan count 2, logical reads 1751, physical reads 38, read-ahead reads 1723.
Table '#t1_________________________________________________________________________________________________________________0001009BC36B'. Scan count 0, logical reads 1, physical reads 0, read-ahead reads 0.

SQL Server Execution Times:
CPU time = 8392 ms, elapsed time = 9443 ms.
Table '#t1_________________________________________________________________________________________________________________0001009BC36B'. Scan count 1, logical reads 4, physical reads 0, read-ahead reads 0.

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 0 ms.
field1 field2 field3 shorts 4wma 12wma 52wma
--------- ---------------------------------------- ---------------------------------------- ---------------------------------------- ---------------------------------------- ---------------------------------------- ----------------------------------------
01 result1 NULL 8.00000000000000000 60 22 17
03 result2 NULL 226.00000000000000000 54 90 54

Table '#t1_________________________________________________________________________________________________________________0001009BC36B'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0.

4. robvolk and tduggan: here are the results of the sproc execution (post robvolks DBCC FREEPROCCACHE after deleting the sproc):

SQL Server parse and compile time:
CPU time = 312 ms, elapsed time = 312 ms.

Table 'table1'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0.
Table 'table2'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0.
Table 'table3'. Scan count 32, logical reads 64, physical reads 0, read-ahead reads 0.
Table 'table4'. Scan count 32, logical reads 75, physical reads 0, read-ahead reads 0.
Table 'table5'. Scan count 1, logical reads 131, physical reads 0, read-ahead reads 0.
Table 'table6'. Scan count 2, logical reads 7204, physical reads 0, read-ahead reads 0.
Table 'table7'. Scan count 1, logical reads 1751, physical reads 0, read-ahead reads 0.
Table '#t1_________________________________________________________________________________________________________________0001009BC41D'. Scan count 0, logical reads 1, physical reads 0, read-ahead reads 0.

SQL Server Execution Times:
CPU time = 1015 ms, elapsed time = 1400 ms.
Table '#t1_________________________________________________________________________________________________________________0001009BC41D'. Scan count 1, logical reads 4, physical reads 0, read-ahead reads 0.

field1 field2 field3 shorts 4wma 12wma 52wma
--------- ---------------------------------------- ---------------------------------------- ---------------------------------------- ---------------------------------------- ---------------------------------------- ----------------------------------------
01 result1 NULL 8.00000000000000000 60 22 17
03 result2 NULL 226.00000000000000000 54 90 54

Table '#t1_________________________________________________________________________________________________________________0001009BC41D'. Scan count 1, logical reads 2, physical reads 0, read-ahead reads 0.

Rob:

1. do you think it is possible that there could be hundreds more stored procedures that are running many times slower than they should be, or could this be a one-off problem?

2. any idea why this occurs? ie is it due to my setup, implementation, ...

To all:

thx for the responses. "you learn something new every day"

gdeconto
Posting Yak Master

107 Posts

Posted - 2004-03-04 : 10:29:22

fyi

for those of you who hate to read thru all the results, the stored procedure runs just as fast as the sql code after I used robvolks suggestion. awesome.

robvolk
Most Valuable Yak

15732 Posts

Posted - 2004-03-04 : 23:03:44

I can't really say what causes it, all I know is I banged my head on the keyboard a lot trying to get things to recompile until I found this ultimate solution. Sometimes you just can't erase all of it, gotta start over with a clean page (literally)

Subscribe to SQLTeam.com

SQLTeam.com Articles via RSS

SQLTeam.com Weblog via RSS

- Advertisement -

Resources