INFO: Results of Function Timing from Microsoft Source Profiler

ID: Q185295

The information in this article applies to:

The Source Profiler, included with:
- Microsoft Visual C++, 32-bit Editions, versions 2.0, 2.1, 2.2, 4.0, 4.1, 4.2, 5.0, 6.0

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.

MORE INFORMATION

Sample Output


   Profile: Function timing, sorted by time
   Date:    Wed Nov 05 23:37:00 1997

Program Statistics


      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


      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. For additional information, please see the following article in the Microsoft Knowledge Base:

Q: 103785 Timing Anomalies of Source Profiler

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.

REFERENCES

Visual C++ online documentation: search on "Function Timing"

Additional query words: Prep Profile Plist Ftime

Keywords : kbVC200 kbVC210 kbVC220 kbVC400 kbVC410 kbVC420 kbVC500 kbVC600
Version : winnt:2.0,2.1,2.2,4.0,4.1,4.2,5.0,6.0
Platform : winnt
Issue type : kbinfo