SQL Clone
SQLServerCentral is supported by Redgate
 
Log in  ::  Register  ::  Not logged in
 
 
 


Mastering SQL Server Profiler - Part 5: Data Columns


Mastering SQL Server Profiler - Part 5: Data Columns

Author
Message
oralinque
oralinque
SSC-Enthusiastic
SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)

Group: General Forum Members
Points: 109 Visits: 441
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.
Ninja's_RGR'us
Ninja's_RGR'us
One Orange Chip
One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)

Group: General Forum Members
Points: 28765 Visits: 9671
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.
Stefan_G
Stefan_G
SSC-Addicted
SSC-Addicted (497 reputation)SSC-Addicted (497 reputation)SSC-Addicted (497 reputation)SSC-Addicted (497 reputation)SSC-Addicted (497 reputation)SSC-Addicted (497 reputation)SSC-Addicted (497 reputation)SSC-Addicted (497 reputation)

Group: General Forum Members
Points: 497 Visits: 960
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
oralinque
oralinque
SSC-Enthusiastic
SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)

Group: General Forum Members
Points: 109 Visits: 441
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.
oralinque
oralinque
SSC-Enthusiastic
SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)

Group: General Forum Members
Points: 109 Visits: 441
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.
Ninja's_RGR'us
Ninja's_RGR'us
One Orange Chip
One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)

Group: General Forum Members
Points: 28765 Visits: 9671
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!!
oralinque
oralinque
SSC-Enthusiastic
SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)

Group: General Forum Members
Points: 109 Visits: 441
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.
Ninja's_RGR'us
Ninja's_RGR'us
One Orange Chip
One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)One Orange Chip (28K reputation)

Group: General Forum Members
Points: 28765 Visits: 9671
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?
ioana-477197
ioana-477197
SSC-Enthusiastic
SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)SSC-Enthusiastic (109 reputation)

Group: General Forum Members
Points: 109 Visits: 278
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
Go


Permissions

You can't post new topics.
You can't post topic replies.
You can't post new polls.
You can't post replies to polls.
You can't edit your own topics.
You can't delete your own topics.
You can't edit other topics.
You can't delete other topics.
You can't edit your own posts.
You can't edit other posts.
You can't delete your own posts.
You can't delete other posts.
You can't post events.
You can't edit your own events.
You can't edit other events.
You can't delete your own events.
You can't delete other events.
You can't send private messages.
You can't send emails.
You can read topics.
You can't vote in polls.
You can't upload attachments.
You can download attachments.
You can't post HTML code.
You can't edit HTML code.
You can't post IFCode.
You can't post JavaScript.
You can post emoticons.
You can't post or upload images.

Select a forum

































































































































































SQLServerCentral


Search