Simple Profile for Your Tcl Script

The Problem

You want to profile your Tcl script to determine which functions need optimization, but profiling seems to be a complicated process.

The Overview

Profiling in Tcl is very simple, so simple that it does not take more than five lines of code. What’s more, you don’t have to modify your script. In a series of three articles, I will show you how to profile your Tcl scripts. The first part (this article) will show the “lazy-man” approach: a five-liner profiler tool. The second article will go a little more in depth to customize the profiler’s output in about 30 lines of code. Finally, the third article exports the profiler’s information to CSV format for use with other programs such as Microsoft Excel.

The Solution

We begin our journey by creating a profiler tool. This tools is written also in Tcl and about five lines long. Save the following lines in a file called profile_me:

#!/usr/bin/env tclsh

# File: profile_me
package require profiler
profiler::init

# Call the script
source $::argv

# Display profiler info
puts "\n[string repeat - 40]"
puts [::profiler::print]

The next step is to make it executable:

chmod +x profile_me

Finally, copy this tool to a directory in your path to make it accessible from any where. Now you are ready to profile your script.

Let’s assume that you have a Tcl script called example_script.tcl:

#!/usr/bin/env tclsh

proc test1 {} {
    puts "This is test1"
}

proc test2 {} {
    puts "This is test2"
}

proc call_all_tests {} {
    test1
    test2
}

# main
for {set i 0} {$i < 5} {incr i} { test1 }
for {set i 0} {$i < 10} {incr i} { test2 }
call_all_tests

To start profiling your Tcl script, issue the following command:

profile_me example_script.tcl

The output:

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

----------------------------------------
Profiling information for ::call_all_tests
============================================================
            Total calls:  1
    Caller distribution:
  GLOBAL:  1
           Compile time:  143706
          Total runtime:  143706
        Average runtime:  0
          Runtime StDev:  0
         Runtime cov(%):  0
  Total descendant time:  50718
Average descendant time:  50718
Descendants:
  ::test1:  1
  ::test2:  1

Profiling information for ::tcl::clock::add
============================================================
            Total calls:  0

Profiling information for ::tcl::clock::format
============================================================
            Total calls:  0

Profiling information for ::tcl::clock::scan
============================================================
            Total calls:  0

Profiling information for ::test1
============================================================
            Total calls:  6
    Caller distribution:
  ::call_all_tests:  1
  GLOBAL:  5
           Compile time:  150958
          Total runtime:  269793
        Average runtime:  44965
          Runtime StDev:  51950
         Runtime cov(%):  115.5
  Total descendant time:  0
Average descendant time:  0
Descendants:
  none

Profiling information for ::test2
============================================================
            Total calls:  11
    Caller distribution:
  ::call_all_tests:  1
  GLOBAL:  10
           Compile time:  26261
          Total runtime:  454414
        Average runtime:  41310
          Runtime StDev:  46538
         Runtime cov(%):  112.7
  Total descendant time:  0
Average descendant time:  0
Descendants:
  none

Conclusion

Profiling a Tcl script is very simple. Our tool, profile_me, demonstrates that you don’t have write a lot of code to accomplish your objective. The output of profile_me is useful right away: it shows the total runtime for each function, along with the number of times the function was called. Based on this information, you can prioritize which function to optimize.

Due to its simplicity, profile_me does not display summary of information, such as which function takes the longest to run, which function is called the most. In part two, I will address these issues.

5 thoughts on “Simple Profile for Your Tcl Script

  1. Pingback: Profiling Your Tcl – Show Profiler’s Summary « Hai’s Blog

  2. 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