BUG: Profiler not correctly removing overhead from timings

dannytuppeny

I think I've found a bug in the profiler to do with it not removing its own overhead properly. The code below might seem a little strange, but it was the best example I could come up with. I think the problem is related to ValueType.GetHashCode using reflection and increasing the profile overhead, but the resulting timings are way off.

List<KeyValuePair<string, int>> items = new List<KeyValuePair<string, int>>();
Dictionary<KeyValuePair<string, int>, bool> dict = new Dictionary<KeyValuePair<string, int>, bool>();

for ( int i = 0; i < 1000; i++ )
    items.Add( new KeyValuePair<string, int>( "MyTest", i ) );

DateTime start = DateTime.Now;

foreach ( var item in items )
    if ( !dict.ContainsKey( item ) )
        dict.Add( item, true );

DateTime end = DateTime.Now;
Console.WriteLine( end - start );

If I run the code manually, it takes 2.2 seconds. When I run it under the profiler the profiler reports Program.Main() taking 18.8 seconds.

I understand that things take longer under the profiler due to its overhead, but I'm talking about the final report. It shows Program.Main() as taking 18 seconds, which as I understood should have been the "actual time had the profiler not been attached".

ValueType.GetHashCode seems to be completely evil (lots of ValueType methods are using Reflection under the hood to loop through all fields), and we're trying to change our code to remove this. However I thought you might be interested in checking this out

dannytuppeny

I've just read a few posts about tight loops where the overhead calculation massively slows thigns down and inflates reported answers. Maybe that's what we're seeing?

Brian Donahue

Hi Danny,

Yes, that's fairly accurate. The overhead calculation can suffer if a very few lines of code are looped. I don't believe that this is the major reason for the code actually running more slowly when an application is 'under the influence' of Profiler. The re-written core of ANTS Profiler 4 will hopefully be quite a bit more accurate.

dannytuppeny

Brian Donahue wrote:

I don't believe that this is the major reason for the code actually running more slowly

I've no problem with the code actually runnign slowler, that's expected and not a problem. The problem is that if the profiler doesn't accurately remove its overhead the results are quite skewed. The results make it look like a part of our application takes over 40 seconds (not good in a web page request!) when in reality this wasn't the case.

It's not a big deal, and we changed some things around that seemed to solve it. I've also been playing with the new version and I'll keep an eye on how things go with that one