Microsoft KB Archive/185295

= INFO: Results of Function Timing from Microsoft Source Profiler =

Article ID: 185295

Article Last Modified on 12/1/2003

-

APPLIES TO

 Microsoft Source Profiler 1.2, when used with:  Microsoft Visual C++ 2.0 Professional Edition

 Microsoft Visual C++ 2.1

 Microsoft Visual C++ 2.2

 Microsoft Visual C++ 4.0 Standard Edition</li></ul>

 Microsoft Visual C++ 4.1 Subscription</li></ul>

 Microsoft Visual C++ 4.2 Enterprise Edition</li></ul>

 Microsoft Visual C++ 4.2 Professional Edition</li></ul>

 Microsoft Visual C++ 5.0 Enterprise Edition</li></ul>

 Microsoft Visual C++ 5.0 Professional Edition</li></ul>

 Microsoft Visual C++ 6.0 Enterprise Edition</li></ul>

 Microsoft Visual C++ 6.0 Professional Edition</li></ul>

 Microsoft Visual C++ 6.0 Standard Edition</li></ul> </li></ul>

-

<div class="notice_section">

This article was previously published under Q185295

<div class="summary_section">

SUMMARY
This article describes the output generated from the Microsoft Source Profiler and specifically focuses on the use of function timing. The sample output comes from a default MFC AppWizard-based application called ProfTest. Although it is not a complete listing of the output from this profile, it is sufficient to demonstrate the output results. A description of each entry presented in the "Sample Output" section follows in the "Output Description" section of this article.

<div class="moreinformation_section">

Sample Output
<pre class="fixed_text">  Profile: Function timing, sorted by time Date:   Wed Nov 05 23:37:00 1997

Program Statistics
<pre class="fixed_text">     Command line at 1997 Nov 05 23:35: "C:\code\ProfTest\Debug\ProfTest" Total time: 88816.409 millisecond Time outside of functions: 86.090 millisecond Call depth: 21 Total functions: 317 Total hits: 23933 Function coverage: 58.0% Overhead calculated 8 Overhead average 8

Module Statistics for proftest.exe
<pre class="fixed_text">     Time in module: 88730.319 millisecond Percent of time in module: 100.0% Functions in module: 317 Hits in module: 23933 Module function coverage: 58.0%

Func            Func+Child      Hit Time      %     Time       %    Count  Function -

86571.608 97.6  87316.863  98.4   70   CWinThread::PumpMessage(void) (mfc42d.dll) 246.177  0.3    367.692   0.4  184   CMDIFrameWnd::DefWindowProcA (unsigned int,unsigned                                             int,long) (mfc42d.dll) 188.947  0.2    188.947   0.2  751   CView::AssertValid(void) (mfc42d.dll) 171.866  0.2    172.011   0.2    1   CToolBar::Create(class CWnd                                              *,unsigned long,unsigned int) (mfc42d.dll) 144.324  0.2    940.322   1.1  517   CWnd::OnWndMsg(unsigned                                              int,unsigned int,long,long *) (mfc42d.dll) 94.550  0.1    314.706   0.4   69   CWinThread:: PreTranslateMessage(struct                                             tagMSG *) (mfc42d.dll) 50.008  0.1  88727.904 100.0    1   AfxWinMain(struct HINSTANCE__                                              *,struct HINSTANCE__ *,char                                              *,int) (mfc42d.dll)

Output Description
Program Statistics:

Command line -

Time and date the application ran, and the complete command line issued by the profiler.

Total time -

Total application execution time. The time listed in milliseconds might not be completely accurate. Use the times as a relative measure.

Time outside of functions -

Time spent outside of any profiled functions. If a top level profiled function is called, no time is added to this value until that function returns.

Call depth -

The deepest level of functions called. For example, if function A calls function B which calls function C, the call depth is 3.

Total functions -

The number of functions listed in the output.

Total hits -

How many times the functions listed were executed.

Function coverage -

The percentage of time spent in the listed functions.

Overhead calculated -

A relative value that represents profiler overhead. This is not a measure of time, but a larger value indicates more time spent in overhead.

Overhead average -

The average overhead required for all profiles. This should be the same as the overhead calculated, unless you are merging multiple profiles.

Module Statistics:

These statistics are similar to the Program Statistics. They are useful when profiling multiple modules, such as an executable and dynamic link library.

Function Time:

In the Function Timing section of the Visual C++ online documentation, there is one error. The function time is in milliseconds, not seconds as it is stated in the documentation. The following excerpt is reprinted from the documentation with the correct measure for function time (milliseconds):

The Func Time column reports how much time it took for the function to run in milliseconds. The next column shows what percent of the total profile time is represented by the function time. Func+Child Time refers to the total time profiled for the function as well as any functions called by that function. The next column shows what percent of the total profile time is represented by the Func+Child time. The Hit Count column reports the number of times that the function was called. The Function column displays the decorated name of the function.

If a called function contains profiler information, then the Func+Child Time is greater than the Func Time.

<div class="references_section">