Huge difference in dotTrace and Stopwatch function timings

Question

Profiling performance of a couple functions in my C# application. I was using the .Net Stopwatch to time a function over 20,000 calls. And the timing worked out to around 2.8ms per call.

However when using dotTrace in line by line mode I find that 20,000 calls to my function takes 249,584ms which is ~12.5ms per call.

Now, the function is attached to a dispatch timer, so the Stopwatch was located inside the function and not registering the call itself. Like so:

private static Stopwatch myStop = new Stopwatch();
private MyFunction(object obj, EventArgs e)
{
    myStop.Start()

    //Code here

    myStop.Stop();
    Console.WriteLine("Time elapsed for View Update: {0}", myStop.Elapsed);
    myStop.Reset();
}

However, I find it hard to believe that the call was taking 10 milliseconds on average.

Is there anything else that could be affecting the timing of the profiler or Stopwatch? Is the dispatch timer event affecting the timing that much?

I've looked through some of the JetBrains forums and wasn't able to find anything related something like this, but I'm sure I could have looked harder and will continue to do so. I do realize that the Stopwatch is unreliable in some ways, but didn't think it could be this much.

It should be noted that this is the first time I've profiled code in C# or .Net.

score 0 · Answer 1 · answered Apr 20 '15 at 10:39

Short answer: line-by-line profiling have biggest overhead than any other profiling type.

For the line-by-line profiling dotTrace(and others profilers) will insert calls to some profiler's function, lets call it for example GetTime() which calculates time spent from the previous call, sums it and write somewhere in snapshot.

So your function not so fast and simple anymore. Without profiling your code can look like this:

myStop.Start();
var i = 5;
i++;
myStop.Stop();

And if you start it under profiler it will be like this:

dotTrace.GetTime();
myStop.Start();
dotTrace.GetTime();
var i = 5;
dotTrace.GetTime();
i++;
dotTrace.GetTime();
myStop.Stop()

So 12.5 ms you get includes all this profiler API calls and distorts absolute function time alot. Line-by-line profiling mostly needed to compare relative statements times. So if you want to accurately measure absoulte function times you should use Sampling profiling type.

For more information about profiling types you can refer to dotTrace Profiling Types and comparison of profiling types help pages.

Huge difference in dotTrace and Stopwatch function timings

1 Answers1