| 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, 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, 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: -
Clear the TimeLog table with a DELETE or TRUNCATE TABLE statement. -
Turn on time logging in your VB application (as described in the next section). -
After a period of time, turn off time logging and analyze the resulting data with SQL queries. -
Improve your code with optimizations and repeat the process.
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, 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. | 
