Tuesday 15 May 2012

Debugging tips - continued

After my post about the excellent tutorial by Thomas Tempelmann (previous post), I decided to play around with a simple profiling class. I have commented the source, so it should be fairly self explanatory, but I will explain how to use it after the source code:


Class Profiler

    Sub Constructor(name as String)
  
        ' This should only be executed in debug mode
        #if DebugBuild

            ' First create the indent string, this will save time later on
            mIndent=""
  
            Dim Index As Integer=0
            While Index<mDepth
                mIndent=mIndent+"    "
                Index=Index+1
            Wend
  
            ' Store the name of the method
            mName = name
  
            ' Increase the indent depth for the next instance
            mDepth=mDepth+1
  
            ' Display the 'Entered" method
            System.DebugLog mIndent + "<"+name+"> Entered"
  
            ' Store off the time the constructor finished creation.
            ' We do this at the end of the constructor so that the rest of the 
            ' constructor has minimal impact on the time calculations
            mStart=Microseconds

        #EndIf

    End Sub

    Sub Destructor()
        
        ' This should only be executed in debug mode
        #if DebugBuild

            'Calculate the time the methhod took to execute
            'This is done straight away for a more accurate value
            Dim ExecTime As Double=Microseconds-mStart
  
            'Display the "Exited" message and the execution time of the method
            System.DebugLog mIndent + "<"+mName+"> Exited"
            System.DebugLog mIndent + "<"+mName+"> Execution Time = " + Str(ExecTime) + " Micro Seconds"
  
            'Reduce the indent depth for the next instance
            mDepth=mDepth-1
        
        #Endif

    End Sub

    Private mIndent As String
    Private mName As String
    Private mStart As Double

    Private Shared mDepth As Integer

End Class


To use this class to see how well your methods perform, all you need to do is place the following line at the beginning of the method you wish to test:

Dim p As New Profiler(MethodName)

Replace MethodName with the name of your method.

As the instance of the class is destroyed when it goes out of scope, there is not need to call manually call a destructor.

Now, whenever the method is executed, it will send entries to the system log.
On OS X, these can be viewed in the Console and should look something like this:


15/05/2012 17:58:05 [0x0-0x91091].My Application.debug[4452] <BevelButton Action> Entered 
15/05/2012 17:58:05 [0x0-0x91091].My Application.debug[4452]     <Test> Entered 
15/05/2012 17:58:05 [0x0-0x91091].My Application.debug[4452]     <Test> Exited 
15/05/2012 17:58:05 [0x0-0x91091].My Application.debug[4452]     <Test> Execution Time = 12 Micro Seconds 
15/05/2012 17:58:05 [0x0-0x91091].My Application.debug[4452]     <Test> Entered 
15/05/2012 17:58:05 [0x0-0x91091].My Application.debug[4452]     <Test> Exited 
15/05/2012 17:58:05 [0x0-0x91091].My Application.debug[4452]     <Test> Execution Time = 11 Micro Seconds 
15/05/2012 17:58:05 [0x0-0x91091].My Application.debug[4452] <BevelButton Action> Exited 
15/05/2012 17:58:05 [0x0-0x91091].My Application.debug[4452] <BevelButton Action> Execution Time = 141 Micro Seconds 

Note, the method Test was called from within BevelButton Action, therefore, the log is indented automatically for readability.

As a little side note, I have used conditional compilation, so that the log entries are only generated if the application is executed from within the Real Studio IDE, this means that it would be safe to leave the calls in when deploying the application, however, it would be better if they were removed before release.

If you wish to download this class, I have made it available here.

No comments:

Post a Comment