VBA Details - 7.3 Create an Execution Time Pro?ler

(Page 3 of 5 )

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?

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.

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.

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

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

********************************
+ 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:

1. Import the module basProfiler into your application. This module includes all the procedures needed to initialize and use the profile stack.
   
2. Insert a call to acbProInitCallStack into code that's executed when your application starts up. In the Solution in Recipe 7.2, you might have gotten by without calling the initialization routine. In this situation, however, you must call acbProInitCallStack each time you want to profile your code, or the profile stack will not work correctly. To call acbProInitCallStack, you must pass it three parameters, all of which are logical values ( True or False ). Table 7-2 lists the question answered by each of the parameters.

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?

The procedure initializes some global variables and, if you're writing to a log file, writes a log header to the file. A typical call to acbProInitCallStack might look like this:

acbProInitCallStack False, True, True

3. For each procedure in your application, place a call to acbProPushStack as the first statement. This procedure places the value it's passed on the top of the stack, along with the current time. As the single argument for each call, pass the name of the current procedure. Our example places a pair of parentheses after function names and nothing after subroutine names, as a matter of style. As the last line in each procedure, add a call to acbProPopStack, which will remove the current name from the top of the stack and record the current time.
   
4. You can retrieve the name of the currently executing procedure at any time by calling the acbProCurrentProc function. This function looks at the top of the stack and returns the string it finds there.
   
5. To review the outcome of your logging, view the file LOGFILE.TXT (in your Access directory) in any text editor. If you followed the previous steps carefully, you should see matching entry and exit points for every routine. Nested levels are indented in the printout, and entry and exit points are marked differently (entry points with a "+" and exit points with a "-").

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 pro-cedure.
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"

Next: 7.4 Multitask Your VBA Code >>
 

More Microsoft Access Articles
More By O'Reilly Media

Comments On: VBA Details

· This article is an excerpt from the book "Access Cookbook, Second Edition,"...   >>> Post your comment now!

Buy this book...

This article is excerpted from chapter seven of the Access Cookbook, Second Edition, written by Ken Getz, Paul Litwin, and Andy Baron (O'Reilly, 2005; ISBN: 0596006780). Check it out today at your favorite bookstore. Buy this book now.