Access Cookbook, 2nd Edition [Electronic resources] نسخه متنی

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:

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.

   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

 blnDisplay

 blnLog

 blnTimeStamp

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
   "-").

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.

 acbProInitStack

 acbProPushStack

 acbProPopStack

 acbProCurrentProc

 acbProLogString

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.

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 dayif you
need to time a lengthy operation, t

imeGetTime
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
t

imeGetTime to retrieve the current
"time" whenever you push or pop a
value and stores it in the stack array. You can call
t

imeGetTime 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
t

imeGetTime 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"