June 28, 2016 at 8:12 am
Hi all
I had a procedure that was running slow. I wanted to check which statement causes it to run slow, so I ran it in a specific window in SSMS. I then configured profiler with the events RPC:Completed and SP:StmtCompleted with a filter on the same session id as the one in the SSMS window (filter on SPID). The results were very confusing. The procedure had about 20 statements. Most of them ran for less than 3 milliseconds (showed 0). The longest one ran for 6 milliseconds, but the procedure ran for a little more than 500 milliseconds. Those numbers don't add up. The picture that I attached shows the duration, start and end of the statements. You can see that the line that is marked with blue colure finished running at 12:37:21.893, but the next statement started running at 12:37:22.373. This means that just between those statements I have 481 milliseconds with no explanation of what went on. Of course when I add the 481 to the time that each statement was running, I do get a close number to the duration of the whole procedure. My question is – what can cause the profiler to show such confusing data?
Any help would be appreciated.
Adi
--------------------------------------------------------------
To know how to ask questions and increase the chances of getting asnwers:
http://www.sqlservercentral.com/articles/Best+Practices/61537/
For better answers on performance questions, click on the following...
http://www.sqlservercentral.com/articles/SQLServerCentral/66909/
June 28, 2016 at 8:32 am
Maybe something had to wait before completing? Too little information to be sure what's happening.
June 28, 2016 at 8:43 am
Since you are on SQL 2012, you should start using extended events. Using Profiler for traces has been deprecated.
First, you probably are not capturing all events, and you probably don't want to, because it will really affect your server.
Second, Profiler and extended events can skip recording records if it would put too much strain on the server.
Drew
J. Drew Allen
Business Intelligence Analyst
Philadelphia, PA
June 28, 2016 at 9:04 am
drew.allen (6/28/2016)
Since you are on SQL 2012, you should start using extended events. Using Profiler for traces has been deprecated.First, you probably are not capturing all events, and you probably don't want to, because it will really affect your server.
Second, Profiler and extended events can skip recording records if it would put too much strain on the server.
Drew
There are times that I'm using profiler and times that I use extended events. If I just want to see in a stored procedure how much time each statement is running, profiler will be the tool for me. By the way on this case after I posted the original question, I created an extended event session to check the wait stats for a session that just runs that procedure. I hope that this will give me some explanation as for what the procedure is waiting for.
Adi
--------------------------------------------------------------
To know how to ask questions and increase the chances of getting asnwers:
http://www.sqlservercentral.com/articles/Best+Practices/61537/
For better answers on performance questions, click on the following...
http://www.sqlservercentral.com/articles/SQLServerCentral/66909/
June 28, 2016 at 9:38 am
Each of the individual statements are going to reflect the statement, but the whole RPC will include any round trip waits between the statements as the data moves back to the client. You won't see that extra time within the statements on their own.
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
June 28, 2016 at 9:40 am
And just so you know, the way filtering works in Trace, it captures the events first, using whatever memory & cpu it needs to do that, then determines if the filter criteria are met. When they're not, after consuming the resources, it tosses the results. Extended events, filters before capturing. It's one of the main reasons I keep trying to push everyone to use extended events. It's just better than trace.
"The credit belongs to the man who is actually in the arena, whose face is marred by dust and sweat and blood"
- Theodore Roosevelt
Author of:
SQL Server Execution Plans
SQL Server Query Performance Tuning
June 28, 2016 at 3:39 pm
1) What you did (profile with spid filter) is perfectly fine and appropriate. I do this pretty much every single day of the year for lots of different clients. I will still be doing this at least 10 if not 15 years from now, guaranteed.
2) Statement executions are just a piece of the puzzle when it comes to finding out why things execute slower than we expect/want on SQL Server. Lots of stuff has to be done before the first actual statement executes. If you are sending back any statistics (IO being the most common here) and ESPECIALLY the actual query plan those things take up time. And obviously any server connectivity and DATA TRANSFER TIME will delay completion as well. Do you think maybe some/all of those were to blame here? How many rows and how many columns were sent back to SSMS if any?
3) If you executed the same thing twice, was it as slow? Assuming nothing to prevent plan reuse that is a common thing most forget - the cost of creating/storing a query plan on first execution. Profiler will include that cost.
Best,
Kevin G. Boles
SQL Server Consultant
SQL MVP 2007-2012
TheSQLGuru on googles mail service
Viewing 7 posts - 1 through 6 (of 6 total)
You must be logged in to reply to this topic. Login to reply