Profiling Time Between OutputDebugString and FatalExit

Last reviewed: July 22, 1997
Article ID: Q68624
3.00 3.10 WINDOWS kbprg

The information in this article applies to:

  • Microsoft Windows Software Development Kit for Windows versions 3.0 and 3.1

SUMMARY

During the process of profiling an application, SHOWHITS.EXE typically reveals that a fairly large percentage of time was spent in the Microsoft Windows kernel between the FatalExit and OutputDebugString functions.

This phenomenon occurs because a large amount of code between FatalExit and OutputDebugString is not public; however, this code is common to many public entry points. Therefore, when SHOWHITS.EXE compares the data generated from profiling an application to the data in the kernel symbol file, it matches the closest public symbol to the recorded information. Because the nonpublic code is present, SHOWHITS.EXE reports that the closest public symbols are FatalExit and OutputDebugString. However, the application may not be spending any time in either of these functions; instead, it may be spending time in some private function that is located between these functions.

MORE INFORMATION

Because of the nonpublic code, determining exactly how much time the application is spending in a particular block of code can be difficult.

The GetCurrentTime function and conditional compilation can be very helpful when timing specific sections of application code. GetCurrentTime returns the amount of time that has elapsed since Windows started. If an application calls this function before and after a particular block of code, the application can generate statistics on how much time is required for this block of code to execute.

The following code demonstrates this idea:

// This preprocessor variable should be defined to build a profiling
// version of the application.
#define PROFILING

// This section should be either in the global variable section of the
// application or in the variable declaration section of the function
// to be profiled.
#ifdef PROFILING
   static char szProfBuf[80];
   static DWORD dwPrevTime, dwCurTime;
#endif

// This code initializes the variable and should be placed just before
// the code that is used to time a block of code.
#ifdef PROFILING
   dwPrevTime = GetCurrentTime();
#endif

// This block of code is placed after each section of code timed. It
// will display the elapsed time and update the previous time variable
// so that a number of blocks of code can be timed.
#ifdef PROFILING
   dwCurTime = GetCurrentTime();
   wsprintf((LPSTR)szProfBuf, (LPSTR)"%lu\n\r\0",
            dwCurTime - dwPrevTime);
   OutputDebugString((LPSTR)szProfBuf);
   dwPrevTime = dwCurTime;
#endif

The sample code listed above displays the elapsed time on a secondary debugging monitor. If required, this code can be modified to write the data to a file for analysis instead of displaying the data on a monitor.


Additional reference words: 3.00
KBCategory: kbprg
KBSubcategory: KrDebug
Keywords : kb16bitonly


THE INFORMATION PROVIDED IN THE MICROSOFT KNOWLEDGE BASE IS PROVIDED "AS IS" WITHOUT WARRANTY OF ANY KIND. MICROSOFT DISCLAIMS ALL WARRANTIES, EITHER EXPRESS OR IMPLIED, INCLUDING THE WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE. IN NO EVENT SHALL MICROSOFT CORPORATION OR ITS SUPPLIERS BE LIABLE FOR ANY DAMAGES WHATSOEVER INCLUDING DIRECT, INDIRECT, INCIDENTAL, CONSEQUENTIAL, LOSS OF BUSINESS PROFITS OR SPECIAL DAMAGES, EVEN IF MICROSOFT CORPORATION OR ITS SUPPLIERS HAVE BEEN ADVISED OF THE POSSIBILITY OF SUCH DAMAGES. SOME STATES DO NOT ALLOW THE EXCLUSION OR LIMITATION OF LIABILITY FOR CONSEQUENTIAL OR INCIDENTAL DAMAGES SO THE FOREGOING LIMITATION MAY NOT APPLY.

Last reviewed: July 22, 1997
© 1998 Microsoft Corporation. All rights reserved. Terms of Use.