Condividi tramite

What is the difference between Elapsed and Application Time?!

  • Articolo

This is the second in my series of posts on what the heck all these numbers mean in the profiler.

In instrumentation mode, we give 4 varieties of statistics for each function in the reports:

- Elapsed Inclusive
- Elapsed Exclusive
- Application Inclusive
- Application Exclusive

The first post in this series is here and discusses the difference between Inclusive and Exclusive time.

Elapsed time is the difference in the tick count between the entrance to a function and matching exit.  If you were to convert that tick count to milliseconds by using processors clock frequency (see 1 below), this would give you a rough estimate of the wall clock time.  Elapsed inclusive would therefore indicate the total time spent between the enter and exit to a function and Elapsed exclusive would be that time with the time spent in called functions discounted.

Application time is our way of estimating the amount of the Elapsed time actually spent executing your code.  If a transition between kernel and user mode occurs between two instrumentation points, we remove the time between those instrumentation points from the Application time.  For example, if the thread being profiled gets context switched out while executing a function, all of the time between the two instrumentation points the context switch occured between will be credited to that function's Elapsed statistics, but not its Application statistics.  Transitions can also be caused by explicit system calls like WriteFile. (see 2 below)

Here's an example where all the instrumentation points are labelled.
Let's say that a thread is executing foo and it at the point labelled "CONTEXT SWITCH HERE", when a context
switch occurs.

int foo()
{
   // INSTRUMENTATION POINT1

   // do some work
   ...

   // INSTRUMENTATION POINT2
   bar();
   // INSTRUMENTATION POINT3

   // do some work again 
   ...
   // CONTEXT SWITCH HERE
   ...

   // INSTRUMENTATION POINT4
   WriteFile(...);
   // INSTRUMENTATION POINT5

   return 0;
   // INSTRUMENTATION POINT6
}

All of the time between INSTRUMENTATION POINT 3 and INSTRUMENTATION POINT 4 will be credited to Elapsed statistics for function foo(), but not to the Application statistics.  Similarly, the call to WriteFile causes a transition to kernel mode, and the time between points 4 and 5 are not charged to Application time. 

So, in summary, Elapsed time is total time spent executing a function.  Application time is an approximation of the time spent executing your code with system time taken out.  You can use the distinction between the two to find places where resource contention is high.  Those resources could be anything from I/O to critical sections to pipes.

I'll try to update this post with a diagram once I get the webhosting for pictures situation sorted out.

Any questions?

[steve carroll]

(1) Given the sophistication of modern computer architecture, converting clock ticks to seconds by dividing by the clock frequency is a really gross approximation. (EWW GROSS!)  Things like power management, which will lower the frequency dynamically on some machines, can make these estimates completely wrong.  However, we will be providing a ticks->milliseconds conversion in the finished product because the feedback has been that our users want it.  You have been warned!

(2) The transition detection mechanism is based on tracking the number of Ring 0 instructions retired.  This counter is not available on a per-thread so transitions are global.  Therefore, Application Time is an approximation only.

Comments

  • Anonymous
    August 05, 2004
    I don't understand:
    Beetwen Point3 & Point4 there could be a lot app code and all of will be subtracted just because some other thread had a ring0 transition?
  • Anonymous
    August 05, 2004
    Yeah. The saving grace here is that every call statement will have instrumentation points surrounding it, so hopefully the amount of good application time that you lose due to these false positives will be kept to a minimum. (hopefully ;-))

    Like I said above, Application Time is a big approximation. We figured it was best to just be open and honest about that up front rather than have our most sophisticated users scratching their heads. This is definitely an area where we know we have room for improvement, but thanks for the feedback. In practice, this approximation seems to be good enough to find areas of major contention.
  • Anonymous
    August 05, 2004
    Why not just have a list of function (customizable) time of which not to include in app time?
    All locking/file/gdi/etc. Let us pick categories.
    IMHO this will be very usefull.

    Thanks for being honest. I hate when products do magic. When that happens I cann't use the results.

    Thanks again
  • Anonymous
    August 06, 2004
    Yeah, I know what you mean about the magic. Great feedback. We'll definitely see what we can do about the filtering you discuss going forward.
  • Anonymous
    July 19, 2007
    PingBack from http://learningdotnet.wordpress.com/2007/07/19/visual-studio-profiler-difference-between-elapsed-and-application-time/