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

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.

About the Author

Paul Kimmel is the VB Today columnist for www.codeguru.com and has written several books on object-oriented programming and .NET. Check out his new book, UML DeMystified, from McGraw-Hill/Osborne. Paul is an architect for Tri-State Hospital Supply Corporation. You may contact him for technology questions at pkimmel@softconcepts.com.

If you are interested in joining or sponsoring a .NET Users Group, check out www.glugnet.org.

Copyright © 2006 by Paul T. Kimmel. All Rights Reserved.