Time excluding children seems wrong.

In a sample execution of the mandelbrot program, the total time reported in Main() (including children) was about 140 seconds. The time reported in Main() (excluding children) was about 70 seconds.

Main() contains only the following code:
Application.Run(new Form1());

The body of Main() is absolutely trivial. It allocates a new object and passes it to a static function. That's all. It shouldn't take 70 seconds to allocate a single object and initiate a single function call.

After allocating that single object and calling Run(), the rest of the time is spent there, inside Run() -- inside a child of Main(). Run() doesn't return until the application is exiting. So I would expect nearly ALL of the time to be spent in Main() (with children) and nearly 0 time spent in Main() (excluding children).

So I'm not sure why Main() (excluding children) is shown as 70 seconds.

Comments

  • Hi Adam,

    time spent in a method is the total time minus the time spent in profiled child methods. We DO not include the time spent in nonprofilled child methods though. This was a design decision that made the most sense to us. If you follow through your logic, you would nearly always end up with no time being spent in your source code as everything happens in child methods. We felt that this would not be helpful in tracking down bottle necks.

    However, it does mean that Main will always pop up at the top of your list. We'd like to find a way of measuring proceesor time to eliminate the confusion in the next version of ANTS Profiler.

    Regards,

    Tom Harris

    Red Gate Software Ltd
  • I see why it's reporting 70 seconds, but I don't think it has to be that way. I assume that by non-profiled child methods you are referring to code that's excluded by the filter (the filter that by default excludes methods that have no source code).

    This problem doesn't only affect Main(), then. In fact, any function that makes a call into an external (filtered out) method, either directly or indirectly, would have inaccurate timing.

    And I don't think that by following my logic you'd wind up with no time being spent in my source code, unless of course that was actually the case.

    I would simply expect it to show that the majority of the time is spent sitting in various parts of the System.Windows.Forms namespace, waiting for events, etc. (You might just say that 70 seconds were spent in "external methods", referring to methods that were filtered out). The remaining time would be the true time spent in my application (or at least the parts of my application that I, with the filter, decided that I wanted to focus on).

    Following my logic, I wouldn't have a large number of seconds mysteriously being attributed to the wrong functions.

    Perhaps you're applying your filter too early in the profiling process. I imagine that when you filter methods, you're not timing them at all. This seems consistent with the problem.

    A better method would be to still time filtered methods (not at a per-line level, of course) and then to simply not display them in the results. This would give you the information you need to determine the correct time. It also increases the flexibility of the profiler because you'd be able to change the filter after the results have already been collected if you wanted to view the results in a different way.
This discussion has been closed.