TIP 447: Execution Time Verbosity Levels in tcltest::configure

Author:         Pietro Cerutti <[email protected]>
State:          Final
Type:           Project
Vote:           Done
Created:        20-Apr-2016
Keywords:       Tcl,tcltest
Tcl-Version:    8.7
Tcl-Branch:     gahr-tip-447


The -verbose option of the tcltest::configure command accepts a set of verbosity levels to specify what pieces of information about tests the user wants reported. This TIP proposes the addition of two new verbosity levels to report information about the execution time of tests.


When doing test-driven development, working on the refinement of a new feature, or fixing a bug, it is very important to be able to measure the effect of code changes on execution time.

The tcltest infrastructure is the testing framework used both by Tcl/Tk and a number of extensions. The tcltest infrastructure is highly configurable and allows the user to choose which information on the tests being run are reported. This can be done with the -verbose option of the tcltest::configure command. Verbosity levels allow to report, e.g., when a test passes, is skipped, or fails.

A proper way to measure the time spent running each test is currently missing. Scope of this TIP is to address this issue by extending the set of verbosity levels accepted.


The -verbose option of the tcltest::configure command is modified to accept the following new verbosity levels:

usec (u): Report execution time of each test, in microseconds.

msec (m): Report the execution time of each test, in milliseconds.


This example demonstrates running a subset of the Tcl test suite with verbosity level usec (u):

$ make TESTFLAGS="-verbose u -match lsearch-1.*" test
++++ lsearch-1.1 took 521 us
++++ lsearch-1.2 took 156 us
++++ lsearch-1.3 took 187 us
++++ lsearch-1.4 took 120 us


Additional Time Units

The implementation of additional verbosity levels to track execution times in seconds, minutes, hours, and so on is trivial, but has been discarded as unit or functional test are often meant to be fast. Another approach would be to introduce a configurable verbosity level to carry information on the time unit to be used. Examples could be time:usec, time:msec, and time:sec. This option has also been discarded because it clashes with the current approach of having verbosity level strings that can be shortened to a single character. It is the author's opinion that milliseconds and microseconds should address most use cases.

When Timing Should be Displayed?

The current implementation dumps timing information before any reports of success / failure. Example:

---- tsv-lmdb-1.5 start
++++ tsv-lmdb-1.5 took 828 us

==== tsv-lmdb-1.5 tsv::exists - previously set exists FAILED
---- Result was:
---- Result should have been (exact matching):
==== tsv-lmdb-1.5 FAILED

This allows for a simpler implementation that doesn't need to account for the different code paths taken by tcltest when reporting success or failure. The author doesn't have a strong opinion on this matter and is open to discussion, should anybody have any counter-proposal.

What to Print?

The current implementation decision to print " took " is arbitrary. Again, the author has no strong opinion on the subject.

On the Goodness of the Times Reported

FV, DGP, and and DKF have raised concerns on the mailing lists on the goodness of the time values reported by the msec and usec verbosity levels. In particular, the problem of repeatibility of the results has been mentioned, and it has been noted that while the idea is good, this might not be the right tool for (the|every) job.

My opinion is that the tool can be useful, given that its scope is made clear. I followed DGP's suggestion and added [checkin 2b96ef] an explicit note in the documentation about the "modest ambitions" of this enhancement.

Reference Implementation

In the gahr-tip-447 branch.


This document has been placed in the public domain.