Pages

Advertisement

Wednesday, July 11, 2007

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

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.

No comments: