Recipe 7.3 Create an Execution Time Profiler

7.3.1 Problem

You'd like to optimize your VBA code, but it's almost impossible to tell how long Access is spending inside any one routine and it's difficult to track which procedures are called by your code most often. You'd like some way to track which routines are called, in what order, and how much time each takes to run. Can you do this?

7.3.2 Solution

As outlined in the Solution in Recipe 7.2, you can create a code profiler using a stack data structure to keep track of the execution order and timing of the procedures in your application. Though the code involved is a bit more advanced than that in the Solution in Recipe 7.2, it's not terribly difficult to create the profiler. Using it is simple, as all the work is wrapped up in a single module.

7.3.3 Steps

Open the database 07-03.MDB and load the module basTestProfiler in design mode. In the Immediate window, type:

? A( )

to run the test procedures. Figure 7-4 shows the profile stack and the code in A. As you can see, A calls B, which calls C, which calls D, which waits 100 ms and then returns to C. C waits 100 ms and then calls D again. Once D returns, C returns to B, which waits 100 ms and then calls C again. This pattern repeats until the code gets back to A, where it finally quits. The timings in the profile stack in Figure 7-4 are actual timings from one run of the sample.

Figure 7-4. The profile stack and the sample routines used to fill it

As the code is set up now, the profiler writes to a text file named C:\LOGFILE.TXT. You can read this file in any text editor. For a sample run of function A, the file contained this text:

********************************
Procedure Profiling
8/13/2003 3:29:11 PM
********************************
+ Entering procedure: A( )
    + Entering procedure: B
        + Entering procedure: C
            + Entering procedure: D
            - Exiting procedure : D                 101 msecs.
            + Entering procedure: D
            - Exiting procedure : D                 100 msecs.
        - Exiting procedure : C                     301 msecs.
        + Entering procedure: C
            + Entering procedure: D
            - Exiting procedure : D                 100 msecs.
            + Entering procedure: D
            - Exiting procedure : D                 100 msecs.
        - Exiting procedure : C                     300 msecs.
    - Exiting procedure : B                         701 msecs.
    + Entering procedure: B
        + Entering procedure: C
            + Entering procedure: D
            - Exiting procedure : D                 100 msecs.
            + Entering procedure: D
            - Exiting procedure : D                 100 msecs.
        - Exiting procedure : C                     300 msecs.
        + Entering procedure: C
            + Entering procedure: D
            - Exiting procedure : D                 100 msecs.
            + Entering procedure: D
            - Exiting procedure : D                 101 msecs.
        - Exiting procedure : C                     301 msecs.
    - Exiting procedure : B                         701 msecs.
- Exiting procedure : A( )                         1513 msecs.

To incorporate this sort of profiling into your own applications, follow these steps:

Table 7-2. Parameters for acbProInitCallStack

Parameter name	Usage
blnDisplay	Display message box if an error occurs?
blnLog	Write to a log file or just track items in an array in memory?
blnTimeStamp	If writing to the log file, also write out time values?

7.3.4 Discussion

The module you imported from 07-03.MDB, basProfiler, includes all the code that maintains the profiler. There are five public entry points to the module, as shown in Table 7-3.

Table 7-3. The five entry points into basProfiler

Procedure name	Purpose	Parameters
acbProInitStack	Initialize the profile stack.
acbProPushStack	Add an item to the profile stack.	A string to push
acbProPopStack	Remove an item from the profile stack.
acbProCurrentProc	Retrieve the name of the current procedure.
acbProLogString	Add any string to the log file.	A string to log

In general, the profiler works almost exactly like the simpler procedure stack shown in the Solution in Recipe 7.2. As a matter of fact, the code for this solution was written first and was then stripped down for use in the simpler example. This example includes the code necessary to write to the file on disk as well as to gather timing information. The next few paragraphs outline the major differences and how they work.

Whereas the Solution in Recipe 7.2 used a simple array of strings to hold the stack information, the profiler also needs to store starting and ending times for each routine. To create the stack, it uses an array of a user-defined type, acbStack, which is defined as follows:

Type acbStack
   strItem As String
   lngStart As Long
   lngEnd As Long
End Type
Dim maStack(0 To acbcMaxStack) As acbStack

Access provides the Timer function, which returns the number of seconds since midnight, but this resolution won't give you enough information for measuring the duration of procedures in VBA. Another option is Windows's t function, which returns the number of milliseconds since you started Windows. TimeGetTime resets itself to every 48 days, whereas Timer resets once every day—if you need to time a lengthy operation, timeGetTime provides a mechanism for measuring time spans longer than a single day (and makes it possible to measure time spans that cross midnight). Of course, if you're timing an operation that takes more than a day, you're probably not going to care about millisecond accuracy, but that's what you get! The code in basProfiler calls timeGetTime to retrieve the current "time" whenever you push or pop a value and stores it in the stack array. You can call timeGetTime in any application, once you include this declaration in a global module:

Public Declare Function timeGetTime _
 Lib "Kernel32" ( ) As Long

The code in basTestProfiler also uses timeGetTime in the Wait subroutine. This procedure does nothing but wait for the requested number of milliseconds, calling DoEvents inside the loop and giving Windows time to do its work:

Public Sub Wait (intWait As Integer)
   Dim lngStart As Long
   lngStart = timeGetTime( )
   Do While timeGetTime( ) < lngStart + intWait
      DoEvents
   Loop
End Sub

The code in basProfiler opens and closes the output file each time it needs to write a piece of information. This slows down your application, but it ensures that if your machine crashes for some reason, your log file will always be current. Although you'll never directly call this routine, if you've never used Access to write directly to a text file you may find it interesting to see how it does its work.

The acbProWriteToLog procedure first checks to see if an error has ever occurred in the logging mechanism (that is, if mfLogErrorOccurred has been set to True). If so, it doesn't try to write anything to the file, because something may be wrong with the disk. If not, it gets a free file handle, opens the log file for appending, writes the item to the file, and then closes it. The following is the source code for the acbProWriteToLog routine:

Private Sub acbProWriteToLog (strItem As String)
    Dim intFile As Integer

    On Error GoTo HandleErr

    ' If an error has EVER occurred in this session,
    ' just get out of here.
    If mfLogErrorOccurred Then Exit Sub

    intFile = FreeFile
    Open acbcLogFile For Append As intFile
    Print #intFile, strItem
    Close #intFile
    
ExitHere:
    Exit Sub

HandleErr:
    mfLogErrorOccurred = True
    MsgBox Err & ": " & Err.Description, , "Writing to Log"
    Resume ExitHere
End Sub

As in the Solution in Recipe 7.2, you'll find that for the procedure stack profiler mechanism to be of any value, you must be conscientious about the placement of your calls to acbProPushStack and acbProPopStack. If you have multiple exit points from routines, this is a good time to try to consolidate them. If you can't, you'll need to make sure that you've placed a call to acbProPopStack before every exit point in each procedure.

If you attempt to decipher the log file, you'll notice that the elapsed time for each procedure must also include any procedures it happens to call, as in the example of A calling B, which calls C, which calls D. The elapsed time for function A was 1,702 ms. That's the time that elapsed between the calls to acbProPushStack and acbProPopStack in function A, including the time it took to run all the calls to B, C, and D. This isn't necessarily a problem, nor is it wrong, but you should be aware that there's no way to "stop the clock" while in subordinate procedures.

The code for the profiler includes another public entry point, acbProLogString. The profiler doesn't actually call this procedure, but your own code can. Pass it a single string, and the profile will send that string to the log file for you. For example, the following code will append "This is a test" to the log file:

acbProLogString "This is a test"