\documentclass[]{article}
\usepackage{amsmath,graphicx,supertabular,hyperref,tabularx,ifthen}
\title{TIP \#447: Execution Time Verbosity Levels in tcltest::configure}
\date{April 20, 2016}
\author{Pietro Cerutti}
\urlstyle{sf}
\setlength{\parskip}{1ex}
\setlength{\parindent}{0pt}
\def\tipversion$#1${\texttt{\$#1\$}}
\def\tiplangle#1{\ensuremath{<}}
\def\tiprangle#1{\ensuremath{>}}
\def\tipbar#1{\ensuremath{|}}
\def\tipmail#1#2{\(\langle\){\small\expandafter\url{#1@#2}}\(\rangle\)}
\ifx\pdfoutput\undefined
\newcommand{\tipimage}[2]{\typeout{Make sure you download #1.eps}\ifthenelse{\lengthtest{0.8\textwidth>#2}\and\lengthtest{0pt<#2}}{\includegraphics{#1.eps}}{\includegraphics[width=0.8\textwidth]{#1.eps}}}
\newcommand{\tipxref}[1]{}
\newcommand{\tipxrefend}{}
\else
\newcommand{\tipimage}[2]{\typeout{Make sure you create #1.pdf}\ifthenelse{\lengthtest{0.8\textwidth>#2}\and\lengthtest{0pt<#2}}{\includegraphics{#1.pdf}}{\includegraphics[width=0.8\textwidth]{#1.pdf}}}
\pdfcatalog{/PageMode /UseOutlines}
\newcommand{\tipxref}[1]{\pdfannotlink attr {/C [0.5 0.5 1.0] /Border [0 0 1]} goto name {#1}}
\newcommand{\tipxrefend}{\pdfendlink}
\fi
\newenvironment{tipabstract}{\begin{abstract}}{\end{abstract}}
\begin{document}\maketitle
\begin{center}\begin{tabularx}{\linewidth}{|r@{: }X|}\hline
\textbf{TIP \#447}&\textbf{Execution Time Verbosity Levels in tcltest::configure}\\\hline
Author&

Pietro Cerutti \tipmail{gahr}{gahr.ch}
\\
Created&Wednesday, \(\text{20}^{\text{th}}\) April 2016\\
Type&Project\\
Tcl Version&\(8.7\)\\
State&Final\\
Vote&Done\\
Version&\tipversion$Revision: 1.6 $\\
Keywords&Tcl, tcltest\\
Post History&\\
\hline\end{tabularx}\end{center}
\thispagestyle{empty}\pagestyle{empty}
\begin{tipabstract}

The \textbf{-verbose} option of the \textbf{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.
\end{tipabstract}
\tableofcontents\setcounter{page}{0}\clearpage\pagestyle{plain}

\section{Rationale}

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 \textbf{tcltest} infrastructure is the testing framework used both by Tcl/Tk and a number of extensions. The \textbf{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 \textbf{-verbose} option of the \textbf{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.

\section{Proposal}

The \textbf{-verbose} option of the \textbf{tcltest::configure} command is modified to accept the following new verbosity levels:
\begin{description}
\item[usec (u)]
Report execution time of each test, in microseconds.
\item[msec (m)]
Report the execution time of each test, in milliseconds.
\end{description}

\section{Example}

This example demonstrates running a subset of the Tcl test suite with verbosity level \textbf{usec} (\textbf{u}):
\begingroup\small\begin{verbatim}
$ make TESTFLAGS="-verbose u -match lsearch-1.*" test
...
lsearch.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
\end{verbatim}
\endgroup

\section{Discussion}

\subsection{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 \textbf{time:usec}, \textbf{time:msec}, and \textbf{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.

\subsection{When Timing Should be Displayed?}

The current implementation dumps timing information before any reports of success / failure. Example:
\begingroup\small\begin{verbatim}
---- tsv-lmdb-1.5 start
++++ tsv-lmdb-1.5 took 828 us


==== tsv-lmdb-1.5 tsv::exists - previously set exists FAILED
---- Result was:
1
---- Result should have been (exact matching):
0
==== tsv-lmdb-1.5 FAILED
\end{verbatim}
\endgroup

This allows for a simpler implementation that doesn't need to account for the different code paths taken by \textbf{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.

\subsection{What to Print?}

The current implementation decision to print ``\tiplangle{}testname\tiprangle{} took \tiplangle{}amount\tiprangle{} \tiplangle{}unit\tiprangle{}'' is arbitrary. Again, the author has no strong opinion on the subject.

\subsection{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 \textbf{msec} and \textbf{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\tipbar{}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.

\section{Reference Implementation}

In the gahr-tip-447 branch.

\section{Copyright}

This document has been placed in the public domain.

\section{Colophon}

\textit{TIP AutoGenerator --- written by Donal K. Fellows}
\end{document}
