Simple Class for Code Profiling

Did you ever want to measure the time it takes a piece of code to execute during runtime?

I did, and that saved me from releasing code that could be further optimized. This approach in fact saved me not only from that, but because of the logging feature that works with profiling, I caught some lines of code that were being repeatedly called (that's a complex piece of software, I must say) and optimizing them had a huge impact in the final product.

While debugging, the latest versions of Visual Studio give some tips about the duration a piece of code takes to complete. This is a neat feature, and is very useful most of the debugging time.

But during runtime, and especially in release versions, adding profiling lines can easily clutter the main code.

Instead of dealing with logs and stopwatches intermixed with the main code, a cleaner solution would be to wrap the code to measure in some way, so one has clear start and end measuring points, and don't repeat code by creating stopwatches, logging, and so on.

What I present you here is a simple class that is used to wrap the code to be profiled inside a using block, and upon disposal, the results are recorded in a target log.

How the Profiler Class Works

The profiler class implements the well-known dispose pattern (IDisposable interface) in combination with a new compiler feature added in .NET 4.5, which is an attribute that makes a function parameter the receiver of the caller's method name. This attribute is called CallerMemberNameAttribute and when it's applied to a function parameter, the compiler fills it in with the name of the caller's method name.

The profiler class is in fact very simple. It has:

• A constructor that takes an ILogger object. In my project, this interface has a single method called LogEvent, which logs the profiling events in a predefined target (could be a file, the windows event log or whatever you want). The idea is to abstract the logging repository from the profiling task itself. You could define your own logger, by implementing the LogEvent method, or even write your own signature of the ILogger interface. This constructor also creates a stopwatch and starts it. The second parameter of the constructor is an optional message that is added to the log after the measurement ends.
• An IDisposable.Dispose method implementation. The only purpose of this is to allow the class to be used with the Using...End Using blocks, so you can wrap code to be profiled. The dispose method calls another internal method that stops the stopwatch created in the constructor and then logs the elapsed time.
• A shared (static in C#) switch called "Profiler", so you can enable or disable profiling globally for an application by using configuration file switches.

This is the class' code:

Imports System.Runtime.CompilerServices
Imports System.Text
Public Class Profiler
    Implements IDisposable
    Private _logger As ILogger
    Private _caller As String
    Private _logInfo As String
    Private _sw As New Stopwatch
    Private Shared _profileSwitch As New TraceSwitch("Profiler", "Switch for profiling")
    Public Sub New(logger As ILogger, Optional logInfo As String = Nothing, _
                   <CallerMemberName> Optional methodName As String = "")
        If _profileSwitch.Level = TraceLevel.Off Then
            Return
        End If
        If logger Is Nothing Then
            Throw New NullReferenceException("logger cannot be null")
        End If
        _logger = logger
        If logInfo Is Nothing Then
            logInfo = ""
        End If
        _logInfo = logInfo '// saves the additional message for use upon disposal.
        _caller = methodName '// saves the name of the method that called this constructor
        Dim sb As New StringBuilder
        sb.Append("Profiling STARTED @ ")
        sb.Append(_caller)
        If _logInfo <> String.Empty Then
            sb.Append(": ")
            sb.Append(_logInfo)
        End If
        _logger.LogEvent(sb.ToString) '// logs the start of measurement
        _sw.Start()
    End Sub
    Public Shared Property ProfileEnabled As Boolean
        Get
            Return _profileSwitch.Level > TraceLevel.Off
        End Get
        Set(value As Boolean)
            If value Then
                _profileSwitch.Level = TraceLevel.Verbose
            Else
                _profileSwitch.Level = TraceLevel.Off
            End If
        End Set
    End Property
    Private Sub LogTime()
        _sw.Stop()
        If _profileSwitch.Level = TraceLevel.Off Then
            Return
        End If
        Dim sb As New StringBuilder
        sb.Append("Profiling COMPLETED @ ")
        sb.Append(_caller)
        If _logInfo <> String.Empty Then
            sb.Append(": ")
            sb.Append(_logInfo)
        End If
        sb.Append(". Time ellapsed: ")
        sb.Append(_sw.ElapsedMilliseconds)
        sb.Append("ms.")
        _logger.LogEvent(sb.ToString)
    End Sub
#Region "IDisposable Support"
    Private disposedValue As Boolean ' To detect redundant calls
    ' IDisposable
    Protected Overridable Sub Dispose(disposing As Boolean)
        If Not disposedValue Then
            LogTime()
        End If
        disposedValue = True
    End Sub
    ' TODO: override Finalize() only if Dispose(disposing As Boolean) 
    ' above has code to free unmanaged resources.
    'Protected Overrides Sub Finalize()
    '    ' Do not change this code.  Put cleanup code in Dispose(disposing As Boolean) above.
    '    Dispose(False)
    '    MyBase.Finalize()
    'End Sub
    ' This code added by Visual Basic to correctly implement the disposable pattern.
    Public Sub Dispose() Implements IDisposable.Dispose
        ' Do not change this code.  Put cleanup code in Dispose(disposing As Boolean) above.
        Dispose(True)
        ' TODO: uncomment the following line if Finalize() is overridden above.
        ' GC.SuppressFinalize(Me)
    End Sub
#End Region
End Class

Example

Public Class ProfileTest
    Private myLogger as New Logger    '// Logger is a class that implements the ILogger interface.
    Public Sub New()
        IntensiveTask()
    End Sub
    Private Sub IntensiveTask()
        Using p As New Profiler(myLogger, "Profiling code") '// 2nd and 3rd ctor parameters 
        '//are optional. Here we're using the 2nd one to add an additional message to the log line.
            Threading.Thread.Sleep(500) '// Simulate an intensive task.
        End Using    '// Upon disposing the profiler, a message is added to the log target 
                     '// defined in the constructor (myLogger). The line contains the name of the method 
                     '// where the measurement was made (IntensiveTask) and the time it took 
                     '// to complete the block of code.
    End Sub
End Class

Caveats

The profiler class was not tested on obfuscated code. Although compiling is a first step and obfuscating comes later - meaning the method names were already resolved, I didn't have the chance to test it.

Please feel free to leave any comments.