Mastering SQL Server Profiler - Part 5: Data Columns

SQLServerCentral is supported by Red Gate Software Ltd.

Popular Topics

Home

Members

Calendar

Who's On

Home » Article Discussions » Article Discussions by Author » Discuss content posted by Brad M. McGehee » Mastering SQL Server Profiler - Part 5: Data...

18 posts, Page 2 of 2

««1 2

Mastering SQL Server Profiler - Part 5: Data Columns

Rate Topic

Display Mode

Topic Options

Author

Message

oralinque

Posted Monday, March 29, 2010 1:39 PM

SSC Journeyman

Group: General Forum Members
Last Login: Tuesday, February 19, 2013 4:01 PM
Points: 89, Visits: 377

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

Ninja's_RGR'us

Posted Monday, March 29, 2010 6:08 PM

SSC-Insane

Group: General Forum Members
Last Login: Yesterday @ 10:55 PM
Points: 21,357, Visits: 9,534

oralinque (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.

I think the real problem is that we don't have all the figures here to make a real conclusion.

Post #892350

Stefan_G

Posted Tuesday, March 30, 2010 3:27 AM

SSC Veteran

Group: General Forum Members
Last Login: Monday, April 29, 2013 2:13 AM
Points: 275, Visits: 750

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

oralinque

Posted Tuesday, March 30, 2010 4:06 AM

SSC Journeyman

Group: General Forum Members
Last Login: Tuesday, February 19, 2013 4:01 PM
Points: 89, Visits: 377

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

oralinque

Posted Tuesday, March 30, 2010 2:30 PM

SSC Journeyman

Group: General Forum Members
Last Login: Tuesday, February 19, 2013 4:01 PM
Points: 89, Visits: 377

Stefan_G (3/30/2010)

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

Ninja's_RGR'us

Posted Tuesday, March 30, 2010 6:11 PM

SSC-Insane

Group: General Forum Members
Last Login: Yesterday @ 10:55 PM
Points: 21,357, Visits: 9,534

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

oralinque

Posted Wednesday, March 31, 2010 5:47 AM

SSC Journeyman

Group: General Forum Members
Last Login: Tuesday, February 19, 2013 4:01 PM
Points: 89, Visits: 377

Ninja's_RGR'us (3/30/2010)

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

Ninja's_RGR'us

Posted Thursday, April 01, 2010 7:38 AM

SSC-Insane

Group: General Forum Members
Last Login: Yesterday @ 10:55 PM
Points: 21,357, Visits: 9,534

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

« Prev Topic | Next Topic »

18 posts, Page 2 of 2

««1 2

Permissions