Measuring Execution Time

The System.Environment namespace has a TickCount property, which returns the number of milliseconds relative to an internal system timer. (This value is slightly different from the Ticks value discussed in Chapter 6, “Storing Information in Variables,” because it represents milliseconds rather than nanoseconds and is stored in a variable of type Integer.) However, it is a great tool for measuring execution time, because we are not interested in the actual time value itself, but rather duration.

→ For more on dates and time spans, see Chapter 6, “Storing Information in Variables,” p.139

Listing 26.4 shows how you can subtract tick counts to determine the time it takes to execute a method:

Listing 26.4. PERFORMANCE.ZIP—Tick Count Example

Public Sub MyMethod() 
        Dim intStartTime As Integer 
        Dim intEndTime As Integer 
        Dim intTimeToExecute As Integer 
        intStartTime = System.Environment.TickCount 
'MAIN CODE FOR 
'THIS PROCEDURE 
'GOES HERE 

        intEndTime = System.Environment.TickCount 
        intTimeToExecute = intEndTime – intStartTime 
     Debug.WriteLine("Execution time: " &  intTimeToExecute) 
End Sub 

Listing 26.4 stores the value of the System.Environment.TickCount property before and after the procedure code executes. By subtracting these values, the execution time in milliseconds can be determined. The last statement in the subroutine prints the execution time in the Output window.

The code necessary to measure the execution time of any single method call is very easy to write. However, printing tick counts on the screen is not practical for a large application with hundreds of methods and hundreds of simultaneous users. In the remainder of this section, we will show you how to create a more useful time logging system. The goals of our time logging system include the following:

• Time logging should be able to be activated and deactivated at will, without recompiling the program. This is important because the act of logging time may actually decrease performance.

• To identify slow code, we should be able to easily filter the time log data by a specific method call name.

• We should be able to determine average execution times for a specific method call or user, because execution time may vary with the data used or system resources.

To accurately measure the time, you will have to add some code to every one of your method calls. However, as you will see in the next few sections, we have put most of the code in a separate, generic module to make the process as painless as possible. If the benefits of a time logging module are not yet obvious, keep reading.

Understanding the Database Requirements

To identify trouble spots and trends in our time logging data, we need to be able to run queries against it. Data queries and filtering can be easily accomplished through the use of the Structured Query Language (SQL). Therefore, our sample time logging system uses a SQL database to store its information.

→ For more on SQL, see Chapter 20, “Database Basics,” p.535

Of course, executing the code necessary to store the performance data in a SQL database will itself adversely affect performance! However, in most cases it should not slow your application too terribly. Typically, you will want to capture these statistics for only a few minutes or hours at a time, after which you will turn time logging off and analyze the data.

Setting Up the Database Objects

The performance data will be stored in a table called TimeLog. A stored procedure, spTimeLogAdd, provides insert capabilities for this table to the calling application. Listing 26.5 shows the statements necessary to create these database objects.

Listing 26.5. PERFORMANCE.ZIP—Creating the TimeLog Database

CREATE TABLE TimeLog 
(  UserID char(10) NOT NULL, 
   TimeStamp smalldatetime NOT NULL, 
   TickCount int NOT NULL, 
   MethodName char(35) NOT NULL 
) 
GO 
create procedure spTimeLogAdd 

@charUserID               char(10), 
@intTickCount             int, 
@charMethod               char(35) 

AS 

Insert 
Into  TimeLog 
   ( 
   UserID, 
   TimeStamp, 
   TickCount, 
   MethodName 
   ) 
Values 
   ( 
   @charUserID, 
   getdate(), 
   @intTickCount, 
   @charMethod 
   ) 

Following is a brief explanation of each field’s purpose:

• UserID— Allows you to determine the execution time for all the method calls associated with a particular user. By comparing with other users’ response times, you can determine whether performance problems are application-wide or isolated to a particular user’s data set.

• TimeStamp— Allows you to monitor performance for a specific period of time; for example, just between 8:00 and 9:00 A.M.

• TickCount— Stores the execution time for an individual method call.

• MethodName— Lists the name of the method called.

As you can see, the database requirements for this project are very simple. To test the stored procedure, you can execute it from your interactive query tool by providing values for the three input parameters:

exec spTimeLogAdd 'John Doe', 123456,'TestFunction' 

In an upcoming section, we will describe how to execute the spTimeLogAdd procedure from within your Visual Basic code.

Working with Captured Data

After you have captured some time logging data, you can run SQL queries to determine some interesting information about your application. For example, the following SQL query lists the average execution time of each method:

Select MethodName, Avg(TickCount) From TimeLog Group By MethodName Order BY 
Avg(TickCount) DESC 

If you have only a single user who complains about performance but everyone else is fine, you can compare his execution times to others by filtering on the UserID field.

One important note about this time logging system is that it is not intended to be left on all the time, but rather only when the developer or database administrator is actively participating in performance tuning. Because the TimeLog table has no primary key or indexes, leaving time logging on would adversely affect performance in short order. The general steps for using this system are as follows:

Understanding the TimeLog Code

As you learned at the beginning of this section, the code for determining the elapsed time in ticks is very simple. Listing 26.6 shows the LogExecutionTime subroutine, which executes the spTimeLogAdd stored procedure:

Listing 26.6. PERFORMANCE.ZIP—The TimeLog Class

Public Sub LogExecutionTime(ByVal strUserID As String,_ 
                            ByVal intStartTickCount As Integer,_ 
                            ByVal intEndTickCount As Integer,_ 
                            ByVal strMethodName As String) 
        Dim parms(2) As SqlParameter 


        parms(0) = New SqlParameter("@charUserID", SqlDbType.Char) 
        parms(0).Size = 10 
        parms(0).Value = strUserID 
        parms(0).Direction = ParameterDirection.Input 

        parms(1) = New SqlParameter("@intTickCount", SqlDbType.Int) 
        parms(1).Value = intEndTickCount - intStartTickCount 
        parms(1).Direction = ParameterDirection.Input 

        parms(2) = New SqlParameter("@charMethod", SqlDbType.Char) 
        parms(2).Size = 35 
        parms(2).Value = strMethodName 
        parms(2).Direction = ParameterDirection.Input 

            Dim intRetVal As Integer 
    Call ExecSP("TimeLog", "spTimeLogAdd", intRetVal, parms) 

End Sub 

Note that the code uses the ExecSP function, which was defined in Chapter 22, “Using ADO.NET (ADO).” Now that we have a means to execute the stored procedure, all we need to do is call this subroutine from within the application. Listing 26.7 shows a typical method call that executes the LogExecutionTime subroutine.

Listing 26.7. PERFORMANCE.ZIP—Typical Use of Execution Time Logging

Public Sub TestMethod() 
        Dim intStartTime As Integer 
        Dim intEndTime As Integer 

        If m_bLoggingEnabled Then 
            intStartTime = System.Environment.TickCount 
        End If 

        'PERFORM WORK HERE 

        If m_bLoggingEnabled Then 
            IntEndTime = System.Environment.TickCount 
            Call LogExecutionTime("TestUser", intStartTime,_ 
            intEndTime, "TestMethod") 
        End If 

End Sub 

Notice that the LogExecutionTime function is not called unless the value of the Boolean variable m_bLoggingEnabled is True. A great way to set this variable is to have the component read a registry value at startup and set it to True if necessary. Accessing the Registry is described in Chapter 21, “ActiveX Data Objects (ADO).”

→ For more on reading values from the registry, see “Managing Database Connections,” p.628

Enhancing the System

The time logging system described here is a simplified version of one I have actually used in a multi-tier Web application. As with any program, there is always room for improvement.

For example, you might also want to add the ability to log method call execution time and stored procedure execution time separately. If all you care about optimizing is the database (and not VB code), the time logging could be taken care of entirely on the database end within a stored procedure. The good thing about logging time from Visual Basic code is that it more closely represents the time the user is experiencing.