Manually profiling with Stopwatch massively bloats execution time

403 views Asked by At

I have implemented a basic binary heap. I wanted to see just how well it performed so I wrote a quick manual 'profiler':

public class MProfile : IDisposable
{
    private static Dictionary<string, ProfilerEntry> _funcs = new Dictionary<string, ProfilerEntry>();
    private Stopwatch _stopwatch;
    private ProfilerEntry _entry;

    public MProfile(string funcName)
    {
        if (!_funcs.ContainsKey(funcName))
        {
            _funcs.Add(funcName, new ProfilerEntry(funcName));
        }

        _entry = _funcs[funcName];

        _stopwatch = Stopwatch.StartNew();
    }

    public void Dispose()
    {
        _stopwatch.Stop();
        _entry.Record(_stopwatch.Elapsed.TotalMilliseconds);
    }
}

The idea was to wrap it around functions calls with using and it would record the time taken. The ProfileEntry class is just a number of calls and total time taken. By storing them against the name, I can add them up.

Now, if I wrap it around my entire test:

Random random = new Random();

int count = 20000;

using (MProfile profile = new MProfile("HeapTest"))
{
    PriorityHeap<PretendPathNode> heap = new PriorityHeap<PretendPathNode>(count);

    for (int i = 0; i < count; i++)
    {
        int next = random.Next(-1000, 1000);
        heap.Insert(new PretendPathNode(next));
    }

    while (heap.Count() > 0)
    {
        heap.Pop();
    }
}

It will tell me that this took: 40.6682ms

However, if I add more profiler around the Insert and Pop calls, i.e:

using (MProfile profile2 = new MProfile("Insert"))
{
    heap.Insert(new PretendPathNode(next));
}

using (MProfile profile3 = new MProfile("Pop"))
{
    heap.Pop();
}

The total time taken is now: 452ms, with 107ms being from Insert and 131ms being from Pop (note: I've run these tests in huge loops and taken an average). I gather that my extra 'profiling' code will obviously have an impact, but how is it bloating the Insert and Pop times to above the original execution time? I thought they way I'd done the disposable meant that -only- the inner execution time would get recorded, which would still be exactly the same. The extra creating disposable, looking up the func in the dictionary and disposing happens -outside- of the Insert/Pop calls.

Is it to do with things like JIT and compile/run time optimizations? Has throwing in that disposable effectively ruined it? I thought maybe it was GC related but I tried a different profiler (static manual calls to start/stop) that had 0 garbage and it's the same...

Edit: I get the same times using this slightly more confusing code, which caches the MProfile objects and Stopwatch objects, so there is less creation/GC.

public class MProfile : IDisposable
{
    private static Dictionary<string, ProfilerEntry> _funcs = new Dictionary<string, ProfilerEntry>();
    private static Dictionary<string, Stopwatch> _stopwatches = new Dictionary<string, Stopwatch>();
    private static Dictionary<string, MProfile> _profiles = new Dictionary<string, MProfile>();


    private ProfilerEntry _entry;
    private string _name;

    public MProfile(string funcName)
    {
        _name = funcName;
        _entry = new ProfilerEntry(funcName);
        _funcs.Add(funcName, _entry);
    }

    public static MProfile GetProfiler(string funcName)
    {
        if (!_profiles.ContainsKey(funcName))
        {
            _profiles.Add(funcName, new MProfile(funcName));
            _stopwatches.Add(funcName, new Stopwatch());
        }

        _stopwatches[funcName].Restart();
        return _profiles[funcName];
    }



    public void Dispose()
    {
        _stopwatches[_name].Stop();
        _entry.Record(_stopwatches[_name].Elapsed.TotalMilliseconds);
    }
}

And calling it via:

using (profile2 = MProfile.GetProfiler("Insert"))
0

There are 0 answers