Click here to monitor SSC
SQLServerCentral is supported by Red Gate Software Ltd.
 
Log in  ::  Register  ::  Not logged in
 
 
 
        
Home       Members    Calendar    Who's On


Add to briefcase ««12

Mastering SQL Server Profiler - Part 5: Data Columns Expand / Collapse
Author
Message
Posted Monday, March 29, 2010 1:39 PM
SSC Journeyman

SSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC Journeyman

Group: General Forum Members
Last Login: Monday, July 15, 2013 2:52 PM
Points: 89, Visits: 385
I've come to the realization that I won't be able to rely on the sum of the duration column for reporting the accumulated time it takes SQL Server to execute the queries. It seems to only be reliable in reporting the duration of individual transactions. Maybe that's by design, and that's fine, but I wish Microsoft would expand on that in Books Online.

Thanks again for your replies.
Post #892155
Posted Monday, March 29, 2010 6:08 PM


SSC-Insane

SSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-Insane

Group: General Forum Members
Last Login: Wednesday, July 16, 2014 12:52 AM
Points: 21,385, Visits: 9,601
oralinque (3/29/2010)
I've come to the realization that I won't be able to rely on the sum of the duration column for reporting the accumulated time it takes SQL Server to execute the queries. It seems to only be reliable in reporting the duration of individual transactions. Maybe that's by design, and that's fine, but I wish Microsoft would expand on that in Books Online.

Thanks again for your replies.



I'm not sure I understand your conclusion. If you assume you can trust the duration of 1 transaction, then you should also be able to trust the 67 999 999 other transactions.

I think the real problem is that we don't have all the figures here to make a real conclusion.
Post #892350
Posted Tuesday, March 30, 2010 3:27 AM


Old Hand

Old HandOld HandOld HandOld HandOld HandOld HandOld HandOld Hand

Group: General Forum Members
Last Login: Tuesday, November 26, 2013 8:40 AM
Points: 316, Visits: 908
You probably have lots of overlapping queries. If your application generates 20 simultaneous queries that all start at 00:00:00 and then all finish at 00:00:02 the elapsed time would be 2 seconds, but the sum of all durations would be 40 seconds.

It is also possible that you have some queries that take a very long time to complete - possibly because of locking.

Note that the number of overlapping queries has nothing to do with the number of CPU:s in the machine. Even with a single CPU server it is possible for the clients to generate lots of overlapping queries - especially if there are multiple clients involved.

So, in short: It is perfectly normal for the sum of durations to be longer than the elapsed time.

/SG
Post #892560
Posted Tuesday, March 30, 2010 4:06 AM
SSC Journeyman

SSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC Journeyman

Group: General Forum Members
Last Login: Monday, July 15, 2013 2:52 PM
Points: 89, Visits: 385
Ninja's_RGR'us (3/29/2010)

I'm not sure I understand your conclusion. If you assume you can trust the duration of 1 transaction, then you should also be able to trust the 67 999 999 other transactions.


That's my whole point. In smaller tests, this is true. In a 45 minute test, the elapsed time is greater than the sum of the duration. However, on longer tests (4.5 hours) the elapsed time is correct, but the sum of the duration far exceeds the elapsed time.

As Stefan_G suggests, if the problem is that transaction 1 starts at 00:03:00.000 and ends at 00:03:01.000, and transaction 2 starts and ends at the exact same time, the total duration is 1-second, but the sum of the duration column would be 2-seconds. If it were this simple, I could figure out a way to determine the true duration time. However, it's unlikely that they would start and end at the exact same time.
Post #892577
Posted Tuesday, March 30, 2010 2:30 PM
SSC Journeyman

SSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC Journeyman

Group: General Forum Members
Last Login: Monday, July 15, 2013 2:52 PM
Points: 89, Visits: 385
Stefan_G (3/30/2010)
You probably have lots of overlapping queries. If your application generates 20 simultaneous queries that all start at 00:00:00 and then all finish at 00:00:02 the elapsed time would be 2 seconds, but the sum of all durations would be 40 seconds.

That's it. Here is a small sample of three overlapping queries.

Event                   ClientProcessID     SPID  StartTime                EndTime                 Duration   TextData
SQL:BatchCompleted 5740 74 12/1/2009 10:13:01.660 12/1/2009 10:13:01.713 52003 Query1
SQL:BatchCompleted 5596 68 12/1/2009 10:13:01.660 12/1/2009 10:13:01.713 52003 Query2
SQL:BatchCompleted 812 73 12/1/2009 10:13:01.660 12/1/2009 10:13:01.713 53003 Query3


Thanks, Stefan_G.

So in the end, it looks like you should not rely on the sum of the duration column if you want to compare the total SQL duration time with the total elapsed time.
Post #893311
Posted Tuesday, March 30, 2010 6:11 PM


SSC-Insane

SSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-Insane

Group: General Forum Members
Last Login: Wednesday, July 16, 2014 12:52 AM
Points: 21,385, Visits: 9,601
errh what did you understand when I said that the server could possibly handly 8 queries at the SAME TIME giving you 8 seconds of processing power PER SECOND? OBviously that's all theorical since the server can handle more than that when you consider all blockings and lockings, waits... etc.



I'm not trying to be a jerk or anything, but I need to understand where I miscommunicated my message!!
Post #893424
Posted Wednesday, March 31, 2010 5:47 AM
SSC Journeyman

SSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC JourneymanSSC Journeyman

Group: General Forum Members
Last Login: Monday, July 15, 2013 2:52 PM
Points: 89, Visits: 385
Ninja's_RGR'us (3/30/2010)
errh what did you understand when I said that the server could possibly handly 8 queries at the SAME TIME giving you 8 seconds of processing power PER SECOND? OBviously that's all theorical since the server can handle more than that when you consider all blockings and lockings, waits... etc.

I'm not trying to be a jerk or anything, but I need to understand where I miscommunicated my message!!


Ha! So you did. My apologies. You didn't miscommunicate anything, but it was early in the troubleshooting process for me and I had a million ideas running through my head. I should have slowed down and read through the entire thread again. Part of the problem for me was going through 77,000,000 records in the profile table. I spent most of yesterday deleting the non-important records and got it down to about 23,000,000 records which allowed me to finally do some analysis without having to wait for hours for a query to run.

Thank you all for your help.
Post #893660
Posted Thursday, April 1, 2010 7:38 AM


SSC-Insane

SSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-InsaneSSC-Insane

Group: General Forum Members
Last Login: Wednesday, July 16, 2014 12:52 AM
Points: 21,385, Visits: 9,601
Well here's an obvious one I hadn't considered... because I don't trace this one anymore

Were you catching the audit logouts events?

That event keeps the total duration of the whole time when the connection is open (even if nothing is processed). That alone will at the very least double the total duration time. It could be even worse if you open the connection, run a query download the data in your app, process it, do another query. process some more, then finally close the connection. Because the duration now includes all the wait time, client processing time, network time and other stuff which might not be relevant to your situation. (It may be relevant if you realize the network is too slow to handle the load you're throwing at it, but that's another story).

That could explain a lot in your case. Then considering the multiple queries at the same time and adding wait times for resources and data, you pretty much just answered the rest of the discrepancies.


Maybe Brad could confirm this but I once read that the best meter for the processing time is the CPU because this is apparently when the server is actually working on the query. This figures should exclude the time wasted on disk reads and waiting on data because of locks or other waits.


So Brad what's your take on this epiphany?
Post #894756
Posted Tuesday, April 29, 2014 9:13 AM
SSC Rookie

SSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC Rookie

Group: General Forum Members
Last Login: Friday, June 20, 2014 1:29 AM
Points: 28, Visits: 207
Hello

In the video it says duration is the total amount of time spent by an event, from beginning to end.
My question is what is beginning and what is end? For example what are they for a select query coming from a client application?
Does duration include the time spent in a SQLServer:NetworkIOWait?

Thank you,
Iana
Post #1565999
« Prev Topic | Next Topic »

Add to briefcase ««12

Permissions Expand / Collapse