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 Thursday, April 23, 2009 2:45 AM


SSC-Enthusiastic

SSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-Enthusiastic

Group: General Forum Members
Last Login: Friday, January 10, 2014 7:20 AM
Points: 175, Visits: 723
Comments posted to this topic are about the item Mastering SQL Server Profiler - Part 5: Data Columns

Brad M. McGehee
Microsoft SQL Server MVP
Director of DBA Education, Red Gate Software
www.bradmcgehee.com
Post #702966
Posted Tuesday, September 29, 2009 3:15 AM
Valued Member

Valued MemberValued MemberValued MemberValued MemberValued MemberValued MemberValued MemberValued Member

Group: General Forum Members
Last Login: Monday, July 25, 2011 11:00 PM
Points: 56, Visits: 41
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?



Post #794974
Posted Wednesday, March 24, 2010 3: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
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?
Post #889386
Posted Thursday, March 25, 2010 3:22 AM


SSC-Enthusiastic

SSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-Enthusiastic

Group: General Forum Members
Last Login: Friday, January 10, 2014 7:20 AM
Points: 175, Visits: 723
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?

Brad M. McGehee
Microsoft SQL Server MVP
Director of DBA Education, Red Gate Software
www.bradmcgehee.com
Post #889625
Posted Thursday, March 25, 2010 5:18 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
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.
Post #889671
Posted Friday, March 26, 2010 5:26 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 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).

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

I'm at a loss, and haven't been able to find anything explaining the discrepancy.
Post #891177
Posted Saturday, March 27, 2010 7:54 AM


SSC-Insane

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

Group: General Forum Members
Last Login: Yesterday @ 11:08 PM
Points: 21,385, Visits: 9,602
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 gap

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.


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.
Post #891285
Posted Saturday, March 27, 2010 8:30 AM


SSC-Enthusiastic

SSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-EnthusiasticSSC-Enthusiastic

Group: General Forum Members
Last Login: Friday, January 10, 2014 7:20 AM
Points: 175, Visits: 723
Ninja's_RGR'us (3/27/2010)
Just throwing ideas in there...


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.


Brad M. McGehee
Microsoft SQL Server MVP
Director of DBA Education, Red Gate Software
www.bradmcgehee.com
Post #891295
Posted Monday, March 29, 2010 10: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
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.

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


are you using multiple threads in the application?

Yes. How would that effect the results?



are you using parralelism?

Yes. I have not changed any of the default server settings, and the application is not passing query hints to set MAXDOP.



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.

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 )).



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.

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).



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.

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.



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.

I'm still combing through the latest test, so I'll do further analysis later today.
Post #892021
Posted Monday, March 29, 2010 11:15 AM


SSC-Insane

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

Group: General Forum Members
Last Login: Yesterday @ 11:08 PM
Points: 21,385, Visits: 9,602
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!
Post #892050
« Prev Topic | Next Topic »

Add to briefcase 12»»

Permissions Expand / Collapse