Profiling Your Tcl – Show Profiler’s Summary

Introduction

This is the second part of my three-part series showing how simple it is to profile a Tcl script. If you have not done so, please read part one before continuing with this article.

In part one, I created a simple profiler tool which offer immediate usefulness. The output of this tool, while useful, leave much to be desired. In this article, I will update my tool to answer these questions:

  • Which functions take the most time to run?
  • Which functions was called the most?
  • Which functions which was defined, but never get called?

The Solution

Below is the version 2 of the profiler tool, save it to a file called profile_me_v2, make it executable and copy it to a directory in the path:

#!/usr/bin/env tclsh

# File: profile_me_v2

namespace eval profiler_utils {
    proc printProfilerInfo {sortKey} {
        puts "\nFunctions that are sorted by $sortKey:"
        set list [lsort -decreasing -integer -index 1 \
            [::profiler::sortFunctions $sortKey]]
        
        foreach entry $list {
            set functionName [lindex $entry 0]
            set functionInfo [lindex $entry 1]
            puts [format "- %10d - %s" $functionInfo $functionName]
        }
    }
    
    proc reportStatistics {} {
        printProfilerInfo totalRuntime
        printProfilerInfo avgRuntime
        printProfilerInfo exclusiveRuntime
        printProfilerInfo avgExclusiveRuntime
        printProfilerInfo calls
    }
}

package require profiler
profiler::init

# Call the script
set scriptName [lindex $::argv 0]
set ::argv [lrange $::argv 1 end]
source $scriptName

# Lastly, display profiler info
puts "\n[string repeat - 40]"
profiler_utils::reportStatistics

Discussion

This script introduces two functions: reportStatistics and printProfilerInfo. Function reportStatistics, called at the end of the script, prints lists of functions, sorted by a few criteria such as total run time, average run time, or number of calls. Function printProfilerInfo does the actual reporting work.

Lines 8-9 obtains a list of functions and measurements (such as total run time). Since this list is sorted in ascending order, I re-sort it in decreasing order to suit my purpose.

Lines 11-15 show these functions, along with their measurements

Using the Tool

You can run profile_me_v2 as follow:

profile_me_v2 example_script.tcl

One interesting note: if example_script.tcl takes on command-line parameters, you can specify them as followed:

profile_me_v2 example_script.tcl argument1 argument2 ...

The output:

$ profile_me_v2 example_script.tcl 
This is test1
This is test1
This is test1
This is test1
This is test1
This is test2
This is test2
This is test2
This is test2
This is test2
This is test2
This is test2
This is test2
This is test2
This is test2
This is test1
This is test2

----------------------------------------

Functions that are sorted by totalRuntime:
-     393935 - ::test1
-     229716 - ::test2
-     134194 - ::call_all_tests
-          0 - ::tcl::clock::scan
-          0 - ::tcl::clock::format
-          0 - ::tcl::clock::add

Functions that are sorted by avgRuntime:
-      78787 - ::test1
-      22971 - ::test2

Functions that are sorted by exclusiveRuntime:
-     393935 - ::test1
-     229716 - ::test2
-      88286 - ::call_all_tests
-          0 - ::tcl::clock::add
-          0 - ::tcl::clock::format
-          0 - ::tcl::clock::scan

Functions that are sorted by avgExclusiveRuntime:
-      88286 - ::call_all_tests
-      65655 - ::test1
-      20883 - ::test2

Functions that are sorted by calls:
-         11 - ::test2
-          6 - ::test1
-          1 - ::call_all_tests
-          0 - ::tcl::clock::scan
-          0 - ::tcl::clock::format
-          0 - ::tcl::clock::add

Conclusion

Version two offers some improvements over the first version. For example, it shows that function ::test1 takes the longest runtime, or function ::tcl::clock::add never gets called.

The output from this version is much more useful than that of version one. However, a CSV output will be most useful, especially when coupled with other analysis tools such as Microsoft Excel. In part three of the series, I will create the CSV output.

One thought on “Profiling Your Tcl – Show Profiler’s Summary

  1. Pingback: Profiling Your Tcl – Output to CSV « Hai’s Blog

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s