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
// INSTRUMENTATION POINT1
// do some work
// INSTRUMENTATION POINT2
// INSTRUMENTATION POINT3
// do some work again
// CONTEXT SWITCH HERE
// INSTRUMENTATION POINT4
// INSTRUMENTATION POINT5
// 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.
(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.