Having difficulty seeing what's important

Code profiling for .NET Developers

Moderators: StephenC, Alex.Davies, AndrewH

Having difficulty seeing what's important

Postby gsmalter » Wed Nov 04, 2009 1:17 am

When working with code that uses anonymous methods or lambda expressions to wrap blocks of code, it is difficult to see what the problem spots are when profiling because these methods tend to make everything else look unimportant.

For example, if you have code like...

AppTools.ExecuteWithStandardExceptionHandling( delegate {

// Basically the entire program

}; );

.. where ExecuteWithStandardExceptionHandling is a simple method that does a try/catch and emails errors to developers in the case of an unhandled exception, the profiler makes it look like 99% of your processing power gets spent on ExecuteWithStandardExceptionHandling. This is technically true, but it's really not useful. Yes, the whole program executes inside it, but it spends almost no (usually, none) time running its own error emailing code - it's just running the code inside it.

So, everything the profiler is telling me is technically correct, and I can track down specific pieces of my "actual" code and see how many milliseconds it is consuming, but it is very difficult to quickly identify trouble spots when there are these wrapping methods hogging the charts.

Is there any way around this? Thank you.
gsmalter
 
Posts: 6
Joined: Wed Nov 04, 2009 1:10 am

Postby Chris.Allen » Thu Nov 05, 2009 1:07 pm

Just a very quick check- are you using "line level" mode of profiling (most detail)?

(I think the problem is actually deeper than this so I'll check with the developer but I just thought I'd ask this one :-)
Chris.Allen
 
Posts: 594
Joined: Thu Mar 12, 2009 4:17 pm

Defaults

Postby gsmalter » Thu Nov 05, 2009 3:40 pm

I am using the defaults. So, Line-level and method-level timings; only methods with source (detailed), for the setting you are talking about, I think.
gsmalter
 
Posts: 6
Joined: Wed Nov 04, 2009 1:10 am

Postby Chris.Allen » Fri Nov 06, 2009 12:21 pm

Can you post a screenshot of what the results look like in the source code view please (wth line-level timings).
Chris.Allen
 
Posts: 594
Joined: Thu Mar 12, 2009 4:17 pm

Postby gsmalter » Fri Nov 06, 2009 3:39 pm

http://picasaweb.google.com/lh/photo/Xj ... directlink

Here's a view of the worst-offending single line of code I could find. It gets called 271 times, takes up 3.6 seconds of execution time cumulatively, and if were were to cache the result it would make for a big improvement. But look where it is in the big picture. It's like the 25th line in a list of methods that are mostly garbage. The methods above it include the ones that parse the command line arguments and invoke the operation, and methods that help you invoke a database operation.

I don't know how the profiler would know what methods I don't care about and which ones I do, and most of this problem is due to my lack of experience with the program, I'm sure. I'm just looking for ideas to help me find critical areas faster. I've had some luck sorting by Hit Count or Time rather than Time With Children.

The only thing that strikes me as outright wrong in this picture is that you'll notice the chart above shows Time With Children as 944ms, while the line in the code shows the time as 3,681. I'm not sure what's causing the difference there.

Thanks.
Last edited by gsmalter on Fri Nov 06, 2009 4:22 pm, edited 1 time in total.
gsmalter
 
Posts: 6
Joined: Wed Nov 04, 2009 1:10 am

Postby StephenC » Fri Nov 06, 2009 3:58 pm

Hi,

I can't seem to access the image. Could you check the URL.

Thanks,

Stephen
StephenC
 
Posts: 306
Joined: Mon Oct 15, 2007 9:18 am
Location: Cambridge

Postby gsmalter » Fri Nov 06, 2009 4:23 pm

Picasa sucks. Try again.
gsmalter
 
Posts: 6
Joined: Wed Nov 04, 2009 1:10 am

Postby Chris.Allen » Tue Nov 10, 2009 9:12 pm

Yes- I see what you mean, when represented in the methods view grod, its only claiming 3.6 milliseconds but in the source code view its 3.6 seconds. This is rather odd, is it easily reproducible?
Chris.Allen
 
Posts: 594
Joined: Thu Mar 12, 2009 4:17 pm

Postby gsmalter » Tue Nov 10, 2009 9:59 pm

I don't think it's as simple as it being off by a factor of 1000. But, regardless, this actually isn't central to the problem. There are other cases where the time is accurate but the fact remains that it is hard to sift through a dozen meaningless methods to find the real performance bottlenecks in the system.
gsmalter
 
Posts: 6
Joined: Wed Nov 04, 2009 1:10 am

Postby Brian Donahue » Fri Nov 20, 2009 6:09 pm

Hello,

I got some information earlier in the week that the source code view does not employ the ANTS Performance Profiler's overhead compensation. If you "disable overhead compensation" in the options, you should notice that the source and grid times match up.
Brian Donahue
 
Posts: 6669
Joined: Mon Aug 23, 2004 10:48 am

Postby Chris.Allen » Tue Dec 15, 2009 5:25 pm

We've acknowledged this as a UI bug (PP-895) and will hopefully enhance the presentation of such data in the next version.
Chris.Allen
 
Posts: 594
Joined: Thu Mar 12, 2009 4:17 pm


Return to ANTS Performance Profiler 5

Who is online

Users browsing this forum: No registered users and 0 guests