Timings reported by Profiler far exceed actual runtimes

splmal

I am using the trial version of ANTS Profiler to evaluate for the company I work for. I had a few issues with getting it to run, but this forum has been very helpful (I needed to register some DLLs). I am hoping it will be helpful in determining the cause of the timing discrepancies I am seeing.

Here is the scenario:
I am profiling code that loads 598 documents into a database. When I run this routine from start to finish it only takes about 6 seconds. I've timed this with both a stop watch and TimeSpan objects in the code. However, when I profile the same code the method being timed reports that the method takes approximately 2 to 3 times longer than what is possible.

Any thoughts on what I am not seeing here? The counts look fine, but timings appear greatly inflated.

When I look through all the methods and their timings everything makes sense except for this:

XmlValidatingReader xvr = new XmlValidatingReader(xrd);
xvr.Schemas.Add(_xs);
The last line of code is reported as taking up 5.75 seconds which isn't possible. It is part of System.Xml namespace in .NET 1.1.

If I take this value out of the equation then the timing values across the board add up to the actual runtime of the method I was testing.

Brian Donahue

Hello Slpmal,

Thanks for your forum post. I'll pass this on to the relevant people to look at.

In general, though ANTS Profiler can produce inflated times with recursive code and very, very tight loops.

We're also on the verge of an update release that may produce improved results.

Brian Donahue

Tight code loops are still an issue, but overall, version 2.5 is now twice as accurate when compared to 2.0 in tight loops of code.

RogerSchultz

I'm seeing the same thing concerning inflated times. I'm trying out the trial version 2.5 on a fairly computationally intensive method in c#. If I call this program in a loop (no ANTs) 1,000,000 times, it runs in 45 seconds for all million executions (elapsed time, looking at my watch). If I take the same code and execute under ANTs, it reports the time taken by the program and its children as 864 seconds. This means it's reporting is off by 20X. Am I just trying to get it to do things it wasn;t intended to do? This is critical code, often executed we'd like to speed up.

Tom Harris

Hi there,

my name is Tom Harris; I'm responsible for the development of ANTS Profiler. I'm sorry to hear that the timings are not coming out right with the app you are profiling. The most likely explanation is that recursive functions are being called at some point. This may not necessarily be in your code, but in the heart of the .NET Framework libraries. We have an open issue with gathering timings for recursive methods that will hopefully be mopped in the next update.

Could you send through a set of profiling results to support@redgate.com? It would be useful if they were generated with 'Profile all .NET methods' so that we can drill into the data.

Many thanks,

Tom