SQLServerCentral / Article Discussions / Article Discussions by Author / Discuss content posted by Brad M. McGehee / Mastering SQL Server Profiler - Part 5: Data Columns / Latest Posts

RE: Mastering SQL Server Profiler - Part 5: Data Columns

Ninja's_RGR'us — Thu, 01 Apr 2010 07:38:46 GMT

Well here's an obvious one I hadn't considered... because I don't trace this one anymoreWere 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 [b]exclude[/b] 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?

RE: Mastering SQL Server Profiler - Part 5: Data Columns

oralinque — Wed, 31 Mar 2010 05:47:38 GMT

[quote][b]Ninja's_RGR'us (3/30/2010)[/b][hr]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!![/quote]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.

RE: Mastering SQL Server Profiler - Part 5: Data Columns

Ninja's_RGR'us — Tue, 30 Mar 2010 18:11:49 GMT

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!!

RE: Mastering SQL Server Profiler - Part 5: Data Columns

oralinque — Tue, 30 Mar 2010 14:30:53 GMT

[quote][b]Stefan_G (3/30/2010)[/b][hr]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.[/quote]That's it. Here is a small sample of three overlapping queries.[code="plain"][b]Event ClientProcessID SPID StartTime EndTime Duration TextData[/b]SQL:BatchCompleted 5740 74 12/1/2009 10:13:01.660 12/1/2009 10:13:01.713 52003 Query1SQL:BatchCompleted 5596 68 12/1/2009 10:13:01.660 12/1/2009 10:13:01.713 52003 Query2SQL:BatchCompleted 812 73 12/1/2009 10:13:01.660 12/1/2009 10:13:01.713 53003 Query3[/code]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.

RE: Mastering SQL Server Profiler - Part 5: Data Columns

oralinque — Tue, 30 Mar 2010 04:06:23 GMT

[quote][b]Ninja's_RGR'us (3/29/2010)[/b][hr]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.[/quote]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.

RE: Mastering SQL Server Profiler - Part 5: Data Columns

Stefan_G — Tue, 30 Mar 2010 03:27:42 GMT

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

RE: Mastering SQL Server Profiler - Part 5: Data Columns

Ninja's_RGR'us — Mon, 29 Mar 2010 18:08:41 GMT

[quote][b]oralinque (3/29/2010)[/b][hr]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.[/quote]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.

RE: Mastering SQL Server Profiler - Part 5: Data Columns

oralinque — Mon, 29 Mar 2010 13:39:07 GMT

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.

RE: Mastering SQL Server Profiler - Part 5: Data Columns

Ninja's_RGR'us — Mon, 29 Mar 2010 11:15:51 GMT

min(starttime), max(endtime))...I don't have a copy of the trace but if you have open connections for a few minutes before starting the "real" work or a few minutes after the end or anything else unexpected, you'll get a longer duration than what actually happened during the real test.That's why I preffer to use start/stop time in a script or just a stop watch. My idea was just to do a sum of endtime - startime for all 68 M queries... this figure "should" match sum(Duration) / 1000.If parralelism is off... or not used for some reason it duplicates the available minutes of processing power.For my rounding theory I have no idea how it affects traces with 2005 and 2008 but I have the feeling it may with my experience in 2000.I think that if you add up all the possible causes you have a probable explaination... 8 cores meaning 8 secs of potential processing per "real time" second + even 0.1 MS rounding error in the data could account for 100% of the discrepency you experience.As annoying as those figures are. I agree with Brad's avice that you should just go with optimizing the most ressources and time hungry queries and let go of this issue, if only for your mental health! :w00t:

RE: Mastering SQL Server Profiler - Part 5: Data Columns

oralinque — Mon, 29 Mar 2010 10:47:16 GMT

Thank you for your reply. This is driving me nuts, and I'm sure I'm not the only one out there who has run accross this issue.[quote][b]Ninja's_RGR'us (3/27/2010)[/b][hr]are you using multiple threads in the application?[/quote]Yes. How would that effect the results?[hr][quote]are you using parralelism?[/quote]Yes. I have not changed any of the default server settings, and the application is not passing query hints to set MAXDOP.[hr][quote]Your query seems to basically use this equation... endtime from las query - start time from first query.I think a better equation would be sum(endtime - starttime). That eliminates an errand query in there before or after the real work to sku with those results.[/quote]I'm not sure what you mean here. To get the total duration in milliseconds, I take the difference between when it started, from when it ended using the datediff function (DATEDIFF ( datepart , startdate , enddate )).[hr][quote]One thing that could help explain why this happening is if the server is running at 100% for the whole time of the process and assuming the server uses all 8 availble processors and that each query only uses 1 processor, you just increased your available processing time by 8.... but not 15 obviously. This means that if you have 8 queries running in exactly 1 second each, then could all be processed in 1 second REAL TIME but adding up to 8 seconds total.[/quote]This would make sense. I'll monitor CPU usage next time and see. Would paralleism also have the same effect? On smaller, less instensive tests, the duration time and SQL time seems to fall into place (SQL time being less than total duration time).[hr][quote]One thing I first noticed back in sql 2000 (not sure if it still applies in 2005/08) is that I often had queries that run for very little time (0ms) but every once in a while like 4 or 5 runs, the server showed 13ms. I'm assuming here that there's a rounding error in there or just a weird way to calculate things.Even if a 3 ms error is small over each query... when compounded over 68 millions queries that makes for almost 57 hours in time.[/quote]On SQL 2005/2008, the duration column is captured in microseconds instead of milliseconds when saved to a table (which I'm doing). So what used to show as 0ms might show as 1000 microseconds, allowing you to get a more accurate time.[hr][quote]Can you check the average run time of each query? If I assume 68 M queries over 5 hours, that's only 250 nanoseconds AVERAGE. I think this could explain a great deal in your situation.[/quote]I'm still combing through the latest test, so I'll do further analysis later today.

RE: Mastering SQL Server Profiler - Part 5: Data Columns

bradmcgehee@hotmail.com — Sat, 27 Mar 2010 08:30:06 GMT

[quote][b]Ninja's_RGR'us (3/27/2010)[/b][hr]Just throwing ideas in there...[/quote]Not having direct access to the data, I still find it difficult to offer a good explanation, but certainly Ninga's_RGR'us suggestion that the Duration timing is inaccurate may account for much of the discrepancy. If I was faced with this issue, I would probably not worry about it, as the goal is to maximize overall performance, and not worry about some arbitrary statistics. If you are happy with the current performance, then the stats you see aren't important. If you are not happy with the current performance, then I would start experimenting with alternatives to see what I could do to boost performance in order to reduce the overall time it takes to accomplish your task. While tools, such as Profiler, can be handy, they can sometimes also lead us astray, and distract us for our ultimate goal.

RE: Mastering SQL Server Profiler - Part 5: Data Columns

Ninja's_RGR'us — Sat, 27 Mar 2010 07:54:40 GMT

Just throwing ideas in there...are you using multiple threads in the application?are you using parralelism?Your query seems to basically use this equation... endtime from las query - start time from first query.I think a better equation would be sum(endtime - starttime). That eliminates an errand query in there before or after the real work to sku with those results.That being said it still doesn't explain the ±15 fold different between the numbers, and if anything just widdens the gapOne thing that could help explain why this happening is if the server is running at 100% for the whole time of the process and assuming the server uses all 8 availble processors and that each query only uses 1 processor, you just increased your available processing time by 8.... but not 15 obviously. This means that if you have 8 queries running in exactly 1 second each, then could all be processed in 1 second REAL TIME but adding up to 8 seconds total.One thing I first noticed back in sql 2000 (not sure if it still applies in 2005/08) is that I often had queries that run for very little time (0ms) but every once in a while like 4 or 5 runs, the server showed 13ms. I'm assuming here that there's a rounding error in there or just a weird way to calculate things.Even if a 3 ms error is small over each query... when compounded over 68 millions queries that makes for almost 57 hours in time.Can you check the average run time of each query? If I assume 68 M queries over 5 hours, that's only 250 nanoseconds AVERAGE. I think this could explain a great deal in your situation.Also I may suggest that you try maybe a real ETL process here if possible... do a single, even if parrallel load into a single [set of] table and then do your thing with that data. You should be able to bring that processing time down to a couple minutes or at worse 1 hour.

RE: Mastering SQL Server Profiler - Part 5: Data Columns

oralinque — Fri, 26 Mar 2010 17:26:56 GMT

I was able to reproduce the issue. The total duration below is correct, but the sum of the Duration column is way off.Total Duration in Minutes: 273 (4.5 hours)Sum(Duration) in Minutes: 3476 (57.0 hours)Check my query to make sure I'm not doing something stupid (it happens from time to time).[code="other"]select ((datediff(MS, min(starttime), max(endtime))/1000)/60) as "Total Duration in Minutes", (sum(Duration)/1000000)/60 as "SQL Duration in Minutes"from temp_trc[/code]I'm at a loss, and haven't been able to find anything explaining the discrepancy.

RE: Mastering SQL Server Profiler - Part 5: Data Columns

oralinque — Thu, 25 Mar 2010 05:18:27 GMT

We ran a long test overnight, so I'll check it when I get in and report back. I didn't do the original Profile capture, so it might be a bad capture. It was on a server where the tester had automated scripts to change the time, but I don't know if that happened during the test. I'll go through the original Profile (68 million rows!) and look for a time change. That's the only thing that would make sense. It's the only Profile capture I've run across where this has happened.

RE: Mastering SQL Server Profiler - Part 5: Data Columns

bradmcgehee@hotmail.com — Thu, 25 Mar 2010 03:22:50 GMT

That is certainly curious. I have seen this happen for the CPU time, but have never noticed this for the Duration time. Have you done a second trace too preclude any potential problems?

RE: Mastering SQL Server Profiler - Part 5: Data Columns

oralinque — Wed, 24 Mar 2010 15:30:31 GMT

I have an odd situation in which the total duration for a period of time exceeds that of the given time period. For example, I run Profiler for 3-hours, however the sum of the Duration column for that period of time is 8-hours. I would expect it to be less than 3-hours. How is that possible? Does it have to do with parallel processing (MAXDOP), or do I have a bad Profile capture?

RE: Mastering SQL Server Profiler - Part 5: Data Columns

QPR — Tue, 29 Sep 2009 03:15:34 GMT

Great series Brad. I've used Profiler a fair bit for a while but will certainly be utilising it a lot more after watching your series using what I've learnt.One thing I find frustrating is trying to "profile" events where the application uses a dedicated SQL login and the users are in a terminal server environment.This (as far as I can see) leaves the DBA almost blind as to who and where.The login name is shared among all users and the host is always the terminal server name.Do you have any ideas on how to dig deeper into the data columns to get past this abstraction?

Mastering SQL Server Profiler - Part 5: Data Columns

bradmcgehee@hotmail.com — Thu, 23 Apr 2009 02:45:39 GMT

Comments posted to this topic are about the item [B]Mastering SQL Server Profiler - Part 5: Data Columns [/B]