.NET Code Execution Timer / Logger

Build a Versatile .NET Code Execution Timer / Logger

By Peter A. Bromberg, Ph.D.
Printer-Friendly Version

When you build ASP.NET applications that have multiple assemblies and a lot of business logic going on, it becomes extremely valuable to be able to trace and log the execution times of various operations within the application, and log them to a file or database where items can be grouped by function, calling assembly, time, elapsed time, method name and so on.

This ability gives you the power to isolate and identify bottlenecks in your code, and to know the "real time" execution path your application is taking. It makes it much easier to improve your code and easily measure the results.

There are some new products on the market for .NET that are starting to do this type of measurement, and they are without exception very expensive to buy.

I needed to "wire up" a web-based application we're completing so that we could easily measure the execution times of various entry and exit points where methods were called, objects instantiated, and so on. And we needed to get it stored in a central location and be able to easily "sort it out" after a test run. We also needed the ability to write separate named log files at will, and even to have multiple instances of the logging component write to the same log file at the same or nearly the same time.

The component I came up with is just a start - there are a lot more features we could have put into it -- but it does everything I've just described and should be easy to extend and improve depending on your needs.

Here's the VB.NET code for my base logging component class, and then I'll explain what it does:

Imports System.IO
Imports System.Text
Public Class Logging
    Public Shared StartTicks As Long
    Public Shared LastInterTicks As Long
    Public Shared InterTicks As Long
    Public Shared EndTicks As Long
    Public Shared strActiveGUID As String
    Public strLogFileName As String
    Public Function StartLogEntry(ByVal strLogEntryName As String, _
                                  Optional ByVal strComment As String = "") As String
        Dim lf As String
        If strLogFileName <> "" Then
            lf = "\" & strLogFileName & ".csv"
        Else
            lf = "\DefaultAppLog.csv"
        End If
        Dim strFullLogPathName As String = System.AppDomain.CurrentDomain.BaseDirectory.ToString & lf
        Dim strLogEntryGUID As String = Guid.NewGuid().ToString()
        strActiveGUID = strLogEntryGUID
        Dim strtime As String = DateTime.Now().ToShortDateString & ": " & DateTime.Now().ToShortTimeString
        If StartTicks <> 0 Then
            Throw New Exception("Error: Timer already engaged!")
            Return "Error"
            Exit Function
        End If
        StartTicks = DateTime.Now.Ticks
        Dim sbLog As New StringBuilder()
        sbLog.Append("New Entry: ")
        sbLog.Append(",")
        sbLog.Append(strLogEntryGUID)
        sbLog.Append(",")
        sbLog.Append(strtime)
        sbLog.Append(",")
        sbLog.Append(strLogEntryName)
        sbLog.Append(",")
        sbLog.Append(strComment)
        sbLog.Append("| Caller: ")
        Dim strCallAssy As String = System.Reflection.Assembly.GetCallingAssembly.ToString()
        strCallAssy = Mid(strCallAssy, 1, InStr(strCallAssy, ","))
        sbLog.Append(strCallAssy)

        sbLog.Append(",")
        sbLog.Append("")
        sbLog.Append(",")
        sbLog.Append("")
        sbLog.Append(vbCrLf)
        Try
            Dim fi As FileInfo = New FileInfo(strFullLogPathName)
            Dim sWriterAppend As FileStream = fi.Open(FileMode.Append, FileAccess.Write, FileShare.ReadWrite)
            sWriterAppend.Write(System.Text.Encoding.ASCII.GetBytes(sbLog.ToString), 0, sbLog.Length)
            sWriterAppend.Flush()
            sWriterAppend.Close()
            sbLog = Nothing
            fi = Nothing
            sWriterAppend = Nothing
        Catch e As Exception
            Return e.Message
            sbLog = Nothing
        End Try
        Return strLogEntryGUID
    End Function

    Public Function AddLogEntry(ByVal strLogEntryGUID As String, ByVal strLogEntryName As String,_
                                Optional ByVal strComment As String = "") As String
        If strLogEntryGUID <> strActiveGUID Then Throw New Exception("Log Entry GUID Mismatch.")
        If StartTicks = 0 Then
            Throw New Exception("Error: Timer not engaged!")
            Return "Error"
            Exit Function
        End If
        Dim lf As String
        If strLogFileName <> "" Then
            lf = "\" & strLogFileName & ".csv"
        Else
            lf = "\DefaultAppLog.csv"
        End If

        Dim strFullLogPathName As String = System.AppDomain.CurrentDomain.BaseDirectory.ToString & lf
        Dim strtime As String = DateTime.Now().ToShortDateString & ": " & DateTime.Now().ToShortTimeString
        If InterTicks <> 0 Then
            LastInterTicks = InterTicks ' set last entry time to holder var
        Else
            LastInterTicks = StartTicks
        End If
        InterTicks = DateTime.Now.Ticks ' set curent entry time
        Dim sbLog As New StringBuilder()
        sbLog.Append("Add Entry: ")
        sbLog.Append(",")
        sbLog.Append(strLogEntryGUID)
        sbLog.Append(",")
        sbLog.Append(strtime)
        sbLog.Append(",")
        sbLog.Append(strLogEntryName)
        sbLog.Append(",")
        sbLog.Append(strComment)
        sbLog.Append(",")
        ' intertime
        Dim strIntElapsed As String
        strIntElapsed = CType(((InterTicks - LastInterTicks) / 10000000), String)
        sbLog.Append(strIntElapsed)
        sbLog.Append(",")
        ' Total elapsed time
        strIntElapsed = CType(((InterTicks - StartTicks) / 10000000), String)
        sbLog.Append(strIntElapsed)
        sbLog.Append(vbCrLf)
        Try
            Dim fi As FileInfo = New FileInfo(strFullLogPathName)
            Dim sWriterAppend As FileStream = fi.Open(FileMode.Append, FileAccess.Write, FileShare.ReadWrite)
            sWriterAppend.Write(System.Text.Encoding.ASCII.GetBytes(sbLog.ToString), 0, sbLog.Length)
            sWriterAppend.Flush()
            sWriterAppend.Close()
            sbLog = Nothing
            fi = Nothing
            sWriterAppend = Nothing
        Catch e As Exception
            Return e.Message
            sbLog = Nothing
        End Try
        Return strLogEntryGUID
    End Function
    Public Function CloseLogEntry(ByVal strLogEntryGUID As String, ByVal strLogEntryName As String, _
                                  Optional ByVal strComment As String = "") As String
        If StartTicks = 0 Then
            Throw New Exception("Error: Timer not engaged!")
            Return "Error"
            Exit Function
        End If
        If strLogEntryGUID <> strActiveGUID Then Throw New Exception("Log Entry GUID Mismatch.")
        Dim lf As String
        If strLogFileName <> "" Then
            lf = "\" & strLogFileName & ".csv"
        Else
            lf = "\DefaultAppLog.csv"
        End If

        Dim strFullLogPathName As String = System.AppDomain.CurrentDomain.BaseDirectory.ToString & lf
        Dim strtime As String = DateTime.Now().ToShortDateString & ": " & DateTime.Now().ToShortTimeString
        EndTicks = DateTime.Now.Ticks
        Dim sbLog As New StringBuilder()
        sbLog.Append("Close Entry: ")
        sbLog.Append(",")
        sbLog.Append(strLogEntryGUID)
        sbLog.Append(",")
        sbLog.Append(strtime)
        sbLog.Append(",")
        sbLog.Append(strLogEntryName)
        sbLog.Append(",")
        sbLog.Append(strComment)
        sbLog.Append(",")
        ' inter time
        Dim strIntElapsed As String
        strIntElapsed = CType(((EndTicks - InterTicks) / 10000000), String)
        sbLog.Append(strIntElapsed)
        sbLog.Append(",")
        ' Total elapsed time
        strIntElapsed = CType(((EndTicks - StartTicks) / 10000000), String)
        sbLog.Append(strIntElapsed)
        sbLog.Append(vbCrLf)
        Try
            Dim fi As FileInfo = New FileInfo(strFullLogPathName)
            Dim sWriterAppend As FileStream = fi.Open(FileMode.Append, FileAccess.Write, FileShare.ReadWrite)
            sWriterAppend.Write(System.Text.Encoding.ASCII.GetBytes(sbLog.ToString), 0, sbLog.Length)
            sWriterAppend.Flush()
            sWriterAppend.Close()
            sbLog = Nothing
            fi = Nothing
            sWriterAppend = Nothing
            StartTicks = 0
            InterTicks = 0
            EndTicks = 0
        Catch e As Exception
            Return e.Message
            sbLog = Nothing
        End Try
        Return strLogEntryGUID
    End Function
    Public Sub New(ByVal strFileName As String)
        strLogFileName = strFileName
    End Sub
End Class

The class has three public functions - StartLogEntry, AddLogEntry, and CloseLogEntry. The concept that prompted me to create this type of flow revolves around the idea that when you want to time an "event" in your code, you want to be able to begin a log entry that describes the event, tells where it originated (the calling assembly name, and has a unique Id - in this case, a GUID. In order to maintain this continuity and allow for the fact that other processes may actually be writing to the same log file, we return the GUID as the return value from the StartLogEntry method. This allows the calling process to hold on to this value, and submit it to the class in subsequent "AddLogEntry" calls. In this manner we can load the resultant log file and sort it by GUID in order to keep multiple entries properly grouped.

The StartLogEntry method creates the log file if it doesn't already exist, and writes a human-readable date and time, a log entry name of your choosing, a comment of your choosing (and appends the name of the calling assembly) and of course the starting tick count is stored in the public StartTicks variable. At this point you have kicked off a logging "event" and so we'll need the GUID that's returned in any subsequent AddLogEntry or CloseLogEntry method calls.

The AddLogEntry method does some checking to make sure you're not attempting to do something you aren't allowed to do (such as adding a log entry before opening a new event with StartLogEntry first), and it logs the intermediate time in seconds (DateTime.Now.Ticks has resolution of 100 nanoseconds, or 1 / ten - millionth of a second) and also the cumulative elapsed time.

Finally , CloseLogEntry does the same thing, and represents the last entry of a logging "event". You can do AddLogEntry as many times as you want to log various milestones in your code before "closing out" a specific log entry, and you can open additional instances of the class with new log file names or the same log file name and open and write to separate log entry events each of which is identified by a new unique GUID.

The constructor to the class is overloaded to provide a custom log file name if desired, or one can pass in a null string to get the default log file name. The log file is writted in comma-delimited .CSV format, which provides the convenience of double-click loading into Excel, and easy import into a SQL Server or other database table.

This is the concept that I came up with, it's really very simple but its also extensible and there are many other things that can be done with it. What I do is have an AppSettings key <add key name="Logging" value ="true" /> in web.config, and global.asax reads this and stores the setting in System.AppDomain.CurrentDomain.SetData("Logging"), making it available to any assembly running in the same AppDomain (which would normally be all assemblies in an ASP.NET app). Each assembly has a global variable "blnLogging" and the logging code for all the methods you want to track would check for this to be True and logging would be effected application - wide.

Of course if you wanted to be really sophisticated you could evaluate the average overhead for a logging call and build this in as a timing adjustment, but the component is so fast, I doubt it would be worth the extra effort.

I hope this helps you on your way to tracking, logging and timing the methods in your .NET applications!

Download the code that accompanies this article

Peter Bromberg is an independent consultant specializing in distributed .NET solutions Inc. in Orlando and a co-developer of the NullSkull.com developer website. He can be reached at info@eggheadcafe.com