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