Build a Versatile .NET Code Execution Timer / Logger

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

Peter Bromberg

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