Find Out What's Taking Your .NET Code So Long to Run

Share |

Profiling generally is learning about your code's behavior. A big part of profiling is knowing where your code spends a lot of its time. Although I don't encourage profiling in early development, it can become critical when debugging subsystems that are too slow. It also is a useful technique near the end of a significant subsystem's development, especially if that subsystem performs outside of an acceptable range.

Visual Studio .NET 2005—especially Team Test—has some great tools for profiling, but they are designed to run in the IDE. An auto profiler that stays with your code would allow you to decide when to turn it off and on, even after deployment. This article demonstrates how to employ some useful .NET features like hashtables to build an easy-to-use auto profiler that can time a single statement or your entire application.

Implementing the Timestamp Class

The first step is building a class that tracks start and stop times. You need to know when you began profiling a block of code and the elapsed time since. You can use the DateTime class for start and stop times and incorporate the elapsed-time calculation into this class. Listing 1 shows the Stamp class.

Listing 1: The Stamp Class Contains Start and Stop Times

Friend Class Stamp
   Private start As DateTime
   Public Sub New()
      start = DateTime.Now
   End Sub

   Public ReadOnly Property ElapsedTimeString() As String
      Get
         Return ElapsedTime.ToString()
      End Get
   End Property

   Public ReadOnly Property StartTime()
      Get
         Return start.ToLongTimeString()
      End Get
   End Property

   Public ReadOnly Property ElapsedTime() As TimeSpan
      Get
         Return DateTime.Now.Subtract(start)
      End Get
   End Property
End Class

Implementing the MarkTime Class

To keep the class easy to consume, place most of the work on yourself—the producer. The next class, MarkTime, uses a generic tack of Stamp objects. It constructs the Stamp objects, places them in a Stack, and returns the time stamp. You need something like a Stack here to handle recursion. For example, you could recurse 10 times in the same method, adding 10 starts to the MarkTime stack, before you pop and calculate any of the end times. Listing 2 shows the MarkTime class.

Listing 2: The MarkTime Class Contains a Stack to Handle Recursion

Friend Class MarkTime<o:p>
   Private stack As Stack(Of Stamp) = Nothing
   Public Sub New()
      stack = New Stack(Of Stamp)()
   End Sub

   Public Function AddStart() As String
      Dim start As Stamp = New Stamp()
      stack.Push(start)
      Return start.StartTime
   End Function

   Public Function RemoveStart() As String
      If (stack.Peek() Is Nothing = False) Then
         Return stack.Pop().ElapsedTimeString
      Else
         Return ""
      End If

   End Function
End Class

Building the AutoProfiler with a Hashtable

Finally, the AutoProfiler contains a shared constructor, Sub New, and two shared methods, Stopp and Start. (Stopp with a double-p is used because Stop is a reserved word in VB.) Start calls a shared method, GetKey, that uses a StackTrace and Reflection to obtain the fully qualified name of the calling method. This name becomes the key into the hashtable. Hence, the consumer does not need to determine which method is being profiled. The hashtable takes care of that. Should a method be called multiple times, an entry already will exist in the hashtable and additional stops and starts will be handled by the same MarkTime object in the hashtable.

All a consumer of the AutoProfiler needs do is call AutoProfiler.Start and AutoProfiler.Stopp. The class tracks start and stop times and the caller. Listing 3 contains the implementation of the MarkTime class.

Listing 3: The Implementation of the AutoProfiler Class

Public Class AutoProfiler
   Private Shared hash As Hashtable = Nothing
   Private Shared output As OutputType = OutputType.Console

   Shared Sub New()
      hash = New Hashtable
   End Sub

   Private Shared Function GetKey() As String
      Const mask As String = "{0}.{1}"
      Dim trace As StackTrace = New StackTrace
      Dim method As MethodBase = trace.GetFrame(2).GetMethod()
      Return String.Format(mask, _
         method.ReflectedType.FullName, method.Name)
   End Function

   Public Shared Property OutputTo() As OutputType
      Get
         Return output
      End Get
      Set(ByVal value As OutputType)
         output = value
      End Set
   End Property

   <Conditional("DEBUG")> _
   Public Shared Sub Start()
      Dim marker As MarkTime = Nothing
      Dim key As String = GetKey()
      If (hash(key) Is Nothing) Then
         marker = New MarkTime()
         hash.Add(key, marker)
      Else
         marker = CType(hash(key), MarkTime)
      End If
      WriteLine("Started {0} at {1}", key, marker.AddStart())
   End Sub

   <Conditional("DEBUG")> _
   Public Shared Sub Stopp()
      Dim marker As MarkTime = Nothing
      Dim key As String = GetKey()
      If (hash(key) Is Nothing) Then
         Throw New ArgumentOutOfRangeException(key, _
            "Can't find start time entry")
      End If
      marker = CType(hash(key), MarkTime)
      WriteLine("Stopped: {0}, elapsed time {1}", _
         key, marker.RemoveStart())
   End Sub

   Private Shared Sub WriteLine(ByVal format As String, _
      ByVal ParamArray args() As Object)
      If (output = OutputType.Console) Then
         System.Console.WriteLine(String.Format(format, args))
      Else    ' debug
         System.Diagnostics.Debug.WriteLine( _
            String.Format(format, args))
      End If
   End Sub

End Class

Listing 4 contains the complete AutoProfiler implementation, including a sample console application (a simple enum to redirect profiler output and a test console application) that shows how easy it is to profile with this technique.

Listing 4: The Complete AutoProfiler Implementation with a Sample Console App

Imports System
Imports System.Collections
Imports System.Collections.Generic
Imports System.Diagnostics
Imports System.IO
Imports System.Reflection
Imports System.Text


Module Module1

   Sub Main()
      Test()
   End Sub

   Sub Test()
      Profiler.AutoProfiler.Start()
      System.Threading.Thread.Sleep(5000)
      Profiler.AutoProfiler.Stopp()
      Console.ReadLine()
   End Sub

End Module

Namespace Profiler

   Public Enum OutputType
      Console
      Debug
      Window
   End Enum

   Public Class AutoProfiler
      Private Shared hash As Hashtable = Nothing
      Private Shared output As OutputType = OutputType.Console

      Shared Sub New()
         hash = New Hashtable
      End Sub

      Private Shared Function GetKey() As String
         Const mask As String = "{0}.{1}"
         Dim trace As StackTrace = New StackTrace
         Dim method As MethodBase = trace.GetFrame(2).GetMethod()
         Return String.Format(mask, _
            method.ReflectedType.FullName, method.Name)
      End Function

      Public Shared Property OutputTo() As OutputType
         Get
            Return output
         End Get
            Set(ByVal value As OutputType)
            output = value
         End Set
      End Property

      <Conditional("DEBUG")> _
      Public Shared Sub Start()
         Dim marker As MarkTime = Nothing
         Dim key As String = GetKey()
         If (hash(key) Is Nothing) Then
            marker = New MarkTime()
            hash.Add(key, marker)
         Else
            marker = CType(hash(key), MarkTime)
         End If
         WriteLine("Started {0} at {1}", key, marker.AddStart())
      End Sub

      <Conditional("DEBUG")> _
      Public Shared Sub Stopp()
         Dim marker As MarkTime = Nothing
         Dim key As String = GetKey()
         If (hash(key) Is Nothing) Then
            Throw New ArgumentOutOfRangeException(key, _
               "Can't find start time entry")
         End If
         marker = CType(hash(key), MarkTime)
         WriteLine("Stopped: {0}, elapsed time {1}", _
               key, marker.RemoveStart())
      End Sub

      Private Shared Sub WriteLine(ByVal format As String, _
         ByVal ParamArray args() As Object)
         If (output = OutputType.Console) Then
            System.Console.WriteLine(String.Format(format, args))
         Else    ' debug
            System.Diagnostics.Debug.WriteLine( _
               String.Format(format, args))
         End If
      End Sub

   End Class

   Friend Class MarkTime
      Private stack As Stack(Of Stamp) = Nothing
      Public Sub New()
         stack = New Stack(Of Stamp)()
      End Sub

      Public Function AddStart() As String
         Dim start As Stamp = New Stamp()
         stack.Push(start)
         Return start.StartTime
      End Function

      Public Function RemoveStart() As String
         If (stack.Peek() Is Nothing = False) Then
            Return stack.Pop().ElapsedTimeString
         Else
            Return ""
         End If

      End Function
   End Class

   Friend Class Stamp
      Private start As DateTime
      Public Sub New()
         start = DateTime.Now
      End Sub

      Public ReadOnly Property ElapsedTimeString() As String
         Get
            Return ElapsedTime.ToString()
         End Get
      End Property

      Public ReadOnly Property StartTime()
         Get
            Return start.ToLongTimeString()
         End Get
      End Property

      Public ReadOnly Property ElapsedTime() As TimeSpan
         Get
            Return DateTime.Now.Subtract(start)
         End Get
      End Property
   End Class
End Namespace

Put Your Code on the Clock

You just created an AutoProfiler that enables a consumer to time any statement, multiple statement, method, or larger block of code only by calling AutoProfiler.Start and AutoProfiler.Stopp. This technique employs generics, hashtables, reflection, and the knowledge of the StackTrace class. You will find it useful whenever you encounter code running slower than desired.

My father taught me that a craftsman is known by the quality of his tools. Writing high-quality .NET code depends on knowing which .NET tools exist and crafting those that are absent. I hope you find the AutoProfiler helpful and easy to use.