October 28, 2010 at 1:27 pm
Hello all,
Hello All,
Have an interesting problem, where a stored proc is taking about 15 mins when run a prod server. I used profiler,
with the duration template. In the agregated view, it shows the entire stored proc took 15 mins (rightfully), but other
stmts inside are only about 2 or 3 secs.
The interesting thing is, I was able to see from the profiler where the delay was: There was almost 15 mins. gap between one stmt, and another stmt.
But these two stmts. are different.
The gap time was taken by other processes on the server.
Little puzzled here, because, if the 15 min. gap was by a stmt. inside the stored proc, I can identify the offending query.
I am captureing, RPC Completed, SQLBatchStarting, SQLBatchCompleted, SPCompleted events.
Any ideas, or suggestions. (Do I need to be capturing something else also)
Thanks
Paul
October 28, 2010 at 1:31 pm
At a guess, it's probably waiting for a lock. Check while you run the process (exec proc) from a query window and then monitor that spid in sysprocesses. See if anything's blocking it. My guess is it's waiting for exclusive table or page access for an update and other things are using it at the time.
That's where I'd start with the limited information provided.
Never stop learning, even if it hurts. Ego bruises are practically mandatory as you learn unless you've never risked enough to make a mistake.
For better assistance in answering your questions[/url] | Forum Netiquette
For index/tuning help, follow these directions.[/url] |Tally Tables[/url]
Twitter: @AnyWayDBA
October 28, 2010 at 3:08 pm
Thanks for the advice, Craig.
Can you shed little more light on this, is there a way I can do it in the Profiler at all?
Thank you.
October 28, 2010 at 3:24 pm
you might be able to do it via profiler, but two commands in another query window while your first one calls the proc will be much easier, to the point I've forgotten how to do it in profiler:
EXEC sp_lock
and
SELECT * From master..sysprocesses WHERE spid = <whatever the procedure's call's spid is>
Never stop learning, even if it hurts. Ego bruises are practically mandatory as you learn unless you've never risked enough to make a mistake.
For better assistance in answering your questions[/url] | Forum Netiquette
For index/tuning help, follow these directions.[/url] |Tally Tables[/url]
Twitter: @AnyWayDBA
October 28, 2010 at 5:41 pm
October 28, 2010 at 6:31 pm
Thanks Craig.
I did what you adviced, and found about 1000 entries in the sp_loc got the process, but all of them had a GRANT status.
Also, the sysprocesses table did not have a blocking id throughoutout the wait time...
Here is a snippet of the area where the time gap is:
WHILE @pageFirst < @maxDetailCount
SELECT .....
end
For the params I am giving, it only goes once in the loop, but from the profiler, the long wait (about 15min) is after the WHILE stmt. and getting to execute the SELECT Stmt.
So as there has to be other locking/processes (as Craig indicates), that is causing the delay.
Any ideas on how to narrow it down?
Thanks much.
October 28, 2010 at 7:57 pm
Hi there,
Simple questions, but...are you sure it's not the first statement just taking 15 mins to execute? You are using a WHILE loop and iterative operations are notoriously slow. I'd be putting my money on the T-SQL used before looking at locks, particularly if it _always_ takes 15 mins; locking would give a greater variety of durations.
Also, rereading your initial post, I get the feeling you read profiler in a sequential manner, as in "the time between was taken up by other processes". This is not the case, as processes can execute in parallel and other processes can be executed whilst 1 15-min processes is running. (If I misread your post and you already know this, sorry, but I just want to make sure that isn't a source of confusion.)
S.
October 28, 2010 at 8:03 pm
Mymail,
The grant's are the concern, it's the IX (Intent Exclusives) I'm curious about. Beyond that though, the very short description you gave scares the heck out of my inner optimizer. 🙂
Any chance you can post the proc?
Never stop learning, even if it hurts. Ego bruises are practically mandatory as you learn unless you've never risked enough to make a mistake.
For better assistance in answering your questions[/url] | Forum Netiquette
For index/tuning help, follow these directions.[/url] |Tally Tables[/url]
Twitter: @AnyWayDBA
October 29, 2010 at 9:39 am
Attached is a snippet of the proc (rather large)
Thank you.
October 29, 2010 at 11:55 am
Heh, meant to say the grants themselves aren't the concern, sorry for that.
That is the beginnings of a perfectly good monster, alright, but I'm curious about the wrapper logic. Specifically the controls for this:
WHILE @pageFirst < @maxDetailCount
I'm curious as how often this loop expects to run, and why. The select query itself is large and semi-complex, but nothing that is utterly insane.
This component as well:
INTO #PackingSlipPage
FROM #NewPackages
Can also be causing a chunk of the slowdown. Check your write waits to tempdb. I'm wondering if you're running into datapump issue slowdowns.
At a guess, the logic of this proc needs to be stripped down end to end, compared to the underlying DDL, and rebuilt from the ground up. There's a few places in the main proc I could see already making some alterations.
One of the things that stands out to me in the select statement is the CASE WHEN ELSE CASE WHEN END END structure. I've never seen that usage and I don't know the impact offhand on large queries. You can write it simpler (sample) as CASE WHEN e.orgflag = 'O' then ... WHEN e.IncludeOrgName = 1 THEN ... ELSE ... END AS Billaddr2.
Another item is you may get some benefit from building this component:
(SELECT o.OrderId, OC1.Comm AS Comment1, OC2.Comm AS Comment2
FROM OrderHeader o
LEFT OUTER JOIN OrderComments OC1
ON o.OrderId = OC1.OrdNbr AND OC1.PrintFlag = 'Y'
LEFT OUTER JOIN OrderComments OC2
ON o.OrderId = OC2.OrdNbr AND (OC1.OrderCommentsId IS NULL OR OC1.OrderCommentsId <> OC2.OrderCommentsId) AND OC2.PrintFlag = 'Y'
LEFT OUTER JOIN
(SELECT OrdNbr AS OrderId, MIN(OrderCommentsId) AS MinId
FROM OrderComments
GROUP BY OrdNbr) MinId
ON OC1.OrdNbr = MinId.OrderId
WHERE (OC2.OrderCommentsId IS NULL OR OC2.OrderCommentsId <> MinId.MinId) AND (OC1.PrintFlag = 'Y' OR OC2.PrintFlag = 'Y')
) c
before you enter the loop into a temptable to reduce repeated requerying. This structure has no concerns on the where clause so a single build then brought into the loop may improve performance.
Optimizing this will have a lot to do with rows/pages per table, actual DDL, and indexing.
However, honestly, from just this snippet? 15 minutes may just be cost of doing business for this query. It needs to be shredded, reviewed, and rebuilt.
Never stop learning, even if it hurts. Ego bruises are practically mandatory as you learn unless you've never risked enough to make a mistake.
For better assistance in answering your questions[/url] | Forum Netiquette
For index/tuning help, follow these directions.[/url] |Tally Tables[/url]
Twitter: @AnyWayDBA
October 29, 2010 at 12:08 pm
ok, thanks.
But, this just runs in over 5 secs on a test server.
The only difference is that there are other processes that are running on the prod server. (which Im sure has to do w the delay). But how can I identify these other processes that may be holding/interrupting the proc?
Thank you
October 29, 2010 at 12:17 pm
Can you confirm that both the indexing and the data volume are the same between the Test and the Prod servers you're getting different results on?
There's more here than blocking, I think. Between slowdowns to write to tempdb, possibly changing from 2 loops to 200, and having to wait for other updates/inserts to get out of the way of the reads are all possible issues.
One way to make sure that this process isn't being blocked by locks elsewhere is to set the isolation level in the proc itself. MAKE A COPY for testing only, don't do this test in the original.
Put this line in at the beginning of your proc: SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
When you're done with this test, close the query window you run it it. This modification changes the isolation level on a connection/spid, and I forget if there's an easy way to set it back to default.
What this does is turn everything in the proc into a dirty read (NOLOCK hint, if that helps). No locks, no waits. Now, you can get bad data, but it is a quick way to determine a locking problem.
Never stop learning, even if it hurts. Ego bruises are practically mandatory as you learn unless you've never risked enough to make a mistake.
For better assistance in answering your questions[/url] | Forum Netiquette
For index/tuning help, follow these directions.[/url] |Tally Tables[/url]
Twitter: @AnyWayDBA
November 1, 2010 at 1:16 pm
Thanks again.
But, the test and prod have the same volume of data.
On the prod. system, I have noticed while running the process, in the sysprocesses table, there is a SOS_SCHEDULER_YIELD for the spid.
Thanks.
November 1, 2010 at 1:24 pm
Were you able to try this in a copy of the proc?
SET TRANSACTION ISOLATION LEVEL READ UNCOMMITTED;
I'm curious if we can completely absolve the system of the locking issue.
Never stop learning, even if it hurts. Ego bruises are practically mandatory as you learn unless you've never risked enough to make a mistake.
For better assistance in answering your questions[/url] | Forum Netiquette
For index/tuning help, follow these directions.[/url] |Tally Tables[/url]
Twitter: @AnyWayDBA
November 1, 2010 at 4:07 pm
Craig,
I will do it now, but just to make sure I understand:
This change is going to go on the test system right, and being executed on the test system right?
(The test system, BTW has no issues, it runs fine/quick)
Thank you.
Viewing 15 posts - 1 through 15 (of 25 total)
You must be logged in to reply to this topic. Login to reply