CodeGuru content and product recommendations are editorially independent. We may make money when you click on links to our partners. Learn More.
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.
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.
