Tek-Tips is the largest IT community on the Internet today!

Members share and learn making Tek-Tips Forums the best source of peer-reviewed technical information on the Internet!

  • Congratulations Chris Miller on being selected by the Tek-Tips community for having the most helpful posts in the forums last week. Way to Go!

stored procedure time out 1

Status
Not open for further replies.

wooody1245

Programmer
Sep 13, 2005
28
US
I have a fairly simple stored procedure. It does a select count(*) and based on the count it inserts a record into one of two tables. The problem is the procedure takes one and a half minutes to run causing my program to issue a time-out error. It used to only take 1 to 2 seconds. After the first run the stored procedure will run very quickly (1 to 2 seconds). It's just the initial run that I'm having an issue with.

I've done an execution plan and a server trace with query analyzer, but I can't see anything wrong with it. The two tables have 200 and 180,000 records in them. Even when the insert is to the small table it times out. Any suggestions on what else to look into would be greatly appreciated.
 
Just for the heck of it try running it with statistics time and statistics io on

My belief is that you might be seeing some fragmentation issues.. This doesn't show up after the first execute as the rows end up being shifted into CACHE. However if you run your proc in query analyser you will proabably see a huge number of physical reads...(and read ahead).

To do this as a clean test run
Code:
DBCC DROPCLEANBUFFERS
(that should take all the pages out of cache)
then
Code:
set statistics time on
set statistice io on
exec [red]yourstoredproc[/red]

also you might want to run dbcc showcontig on the tables you are counting.
Code:
dbcc showcontig ([red]yourtablename[/red])with all_indexes

If you are seeing fragmentation (more extentswitches than extents) try rebuilding your indexes.

Also you might want to place a very small nonclusetered index on the tables - sql can count the rows of a table via a nc index and save the cost of hitting the table.

HTH

Rob
 
I ran dbcc showcontig and found a lot of fragmentation. So I rebuilt the indexes on both tables. This seems to have fixed the problem. Thanks!!
 
I was wrong. The problem is occuring yet AGAIN. I've tried the statistics time and IO, but I don't see any physical reads or read-aheads. Below is part of the statistics. This is the only part that takes more than a few ms. Anymore suggestions??

Table 'table_name'. Scan count 0, logical reads 14, physical reads 0, read-ahead reads 0.

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 98829 ms.

SQL Server Execution Times:
CPU time = 0 ms, elapsed time = 98965 ms.

(2 row(s) affected)


SQL Server Execution Times:
CPU time = 15 ms, elapsed time = 99014 ms.

(1 row(s) affected)
 
And that takes more than 30 seconds to run !

Wow. it is only 14 pages total less that 128k of data.

Is the database being closed between reads?

sp_dboption 'yourdatabase'

and look at autoclose.

 
What the count(*) query looks like? I suppose it not as simple as " select count(*) from theBigTable".
If I'm right, can you post the query as well? Thanks
 
Locking?

Sp_who
Sp_who2
sp_lock

Even 9 seconds after the pages have been shifted into cache seems tooooooo long.

this should take 1 or 2 ms to complete.
 
Here is one of the count queries:
SELECT COUNT(*) FROM table WHERE column = @variable

I don't see any locks on the database and autoclose is not set.

Below is something that I thought might indicate fragmentation. Notice the logical and extent scan fragmentation. Is this high? Shouldn't rebuilding the indexes fix this? I rebuilt the indexes yesterday and it greatly improved the scan density.

LEAF level scan performed.
- Pages Scanned................................: 1136
- Extents Scanned..............................: 150
- Extent Switches..............................: 159
- Avg. Pages per Extent........................: 7.6
- Scan Density [Best Count:Actual Count].......: 88.75% [142:160]
- Logical Scan Fragmentation ..................: 13.20%
- Extent Scan Fragmentation ...................: 15.33%
- Avg. Bytes Free per Page.....................: 90.8
- Avg. Page Density (full).....................: 98.88%
 
Fragmentation looks ok.

you only have 9 more extent switches than extents over 150 extents. THis shows a very small amount of page splitting has happened.

Not worth worrying over.
Do you have an index on the col you reference in the where clause?

(you are still talking about a table that is only 9 megs in size - it shouldn't be taking over 30secs to bring up...)

Does it take the same time (over 30seconds) to return from the query in QA as your applicaion? (after freeing the cache.)

 
Could your server be running another process that is taking time away from SQL?
 
Yes the column referenced in the count query is indexed.

The stored procedure takes around 1:40 to complete in query analyzer. My application times out after 30 seconds. After the first run of 1:40, it only takes a second to run.

The server is running other processes but nothing that should tie up sql server. It runs other stored procedures very quickly.

I've noticed that when the procedure takes 1:40 to run the logical reads are up around 2000-3000. When it runs quickly the logical reads are only around 14.
 
Next thought is...

what do your query plans look like?

You haven't got any "optimizer hints" in there specifying a non-clustered index have you?

 
A quicker way of accessing this info is
Code:
Select rowcnt from sysindexes syi
inner join sysobjects syo on syo.id = syi.id
where syi.indid < 2 and syo.name = 'TableName'

Although this still doesnt fix your original problem it should be a work around.

Although my opinion would be that this is some form of locking issue. try taking out an exlcusive lock on the table within a transaction and then execute the stored proc all from the same spid (same window in QA).
This will at least rule out locking.

Also - remember to rollback tran.


"I'm living so far beyond my income that we may almost be said to be living apart
 
I ran the above query from hmckillop and it returned 180075, which is one less than the row count in my table.

I don't understand what hmckillop is suggesting. Could someone explain to me how to take out an exlcusive lock on a table within a transaction.
 
Good point I should have read all the way through.

What I meant by the locking is this.

If you do the following

Code:
BEGIN TRAN

SELECT count(*) FROM table (TABLOCKX) --exclusively lock your table up front meaning no-one else or no other locks will interfere.
--do a print message
print 'Exclusively locked table at :' + convert(varchar,getdate(),102)

--now exec your stored procedure
exec mystoredproc
print 'Stored procedure completed at :' + convert(varchar,getdate(),102)

rollback tran 
--this will now rule out locking/blocking as the issue

Is the disk nearly full? (clutching at straws now)

"I'm living so far beyond my income that we may almost be said to be living apart
 
Actually if you want to know just how perverse your locking is...

Try (in QA)

Dbcc Trace ON (3604,1200)

Then run your proc..

then start looking for X locks or TAB-X locks..

The output is perverse in it's ability to spew out information, but it can be very enlighnening.

(row by row)

Rob
 
I ran the dbcc traceon command and I see I few x locks like this: Process 59 acquiring X lock on KEY: 10:1206295357:4 (650130866315) (class bit2000000 ref1) result: OK. What does this mean?

I'm getting really frustrated with this problem. Nothing is making sense. On the first run the procedure it takes 1:48 to run. It's always within 1 to 2 seconds of this time. Runs after this will only take a second. This seems to indicate that the procedure is being sped up by the cache. But I can clear the cache with DBCC DROPCLEANBUFFERS and the procedure will only take a second to run.

As you can see from my posts above, fragmentation has been ruled out. The drive is nowhere near full. I can't seem to find any locks on the table. If the table or database had locks on it during the run of the procedure, why would it always take 1:48 to run? Wouldn't the time be varied at least slightly?
 
First Re..
KEY: 10:1206295357:4
I think (from memory) that = Databaseid (master.dbo.sysdatabases). ObjectID (loacldb.sysojectes): page in the table. But that is only a page. I am guessing it will go away just about as fast.


It sounds more like you are seeing parse and compile time issues.

DBCC FreeProcCache

should be a way to clear it and test for sure.
Then run your proc with

statisitcs time on
The parse and complie output is generally above the RowCount Output..

Also.. what happens if you run your proc, free the proccache and run it again?

The rows should be in mem but the plan cache will be clear. It should reproduce your issue.

-----

Other thoughts..
If it is only the first time the proc is run that it causes the issue, can you set it up as a "startup Proc"..


To quote BOL
scan for startup procs Option
Use the scan for startup procs option to scan for automatic execution of stored procedures at Microsoft® SQL Server™ startup time. If this option is set to 1, SQL Server scans for and executes all automatically executed stored procedures defined on the server. The default value for scan for startup procs is 0 (do not scan).

The value for this option can be set using sp_configure; however, it will be set automatically if you use sp_procoption, which is used to mark or unmark stored procedures as automatically executed (autoprocs). When sp_procoption is used to mark the first stored procedure as an autoproc, this option is set automatically to a value of 1. When sp_procoption is used to unmark the last stored procedure as an autoproc, this option is automatically set to a value of 0. If you use sp_procoption to mark and unmark autoprocs, and always unmark autoprocs before dropping them, there is no need to set this option manually.

scan for startup procs is an advanced option. If you are using the sp_configure system stored procedure to change the setting, you can change scan for startup procs only when show advanced options is set to 1. The setting takes effect after stopping and restarting the server.

To set the scan for startup procs option

 
Status
Not open for further replies.

Part and Inventory Search

Sponsor

Back
Top