# TIP 62: Add Support for Command Tracing
Author: Hemang Lavana <[email protected]>
Author: Vince Darley <[email protected]>
State: Final
Type: Project
Vote: Done
Created: 18-Sep-2001
Post-History:
Tcl-Version: 8.4
Implementation-URL: http://www.employees.org/~hlavana/tcl/
-----
# Abstract
This TIP proposes that the Tcl's trace command be extended to include
the following features:
1. tracing of command execution for the specified tcl command, and
2. step-wise tracing of any command execution within a specified procedure.
# Rationale
One of the main strengths of Tcl is the ability to trace _read_,
_write_ or _delete_ operations on variables. Moreover, Tcl8.4 has
already added support for tracing _rename_ or _delete_ operations
on Tcl commands. Addition of the proposed subcommand for tracing
executions will further improve the capabilities of Tcl without any loss
of performance \(see _Benchmark Results_ section below\).
I can see several applications of this feature, including:
* overloading/wrapping of Tcl commands, please see
<http://mini.net/tcl/1494.html>
* aid developer in debugging Tcl scripts
* profiler module in _tcllib_ can benefit from this feature
# Specification
This TIP proposes an enhancement to the trace command with the
following syntax:
trace add execution name ops command
The type _execution_ is used to arrange for _command_ to be executed
whenever the command _name_ is invoked for execution.
_Name_ may refer to any of the tcl commands or procedures that have been
previously defined. It is an error to create an _execution_ trace on a
non-existant command or a procedure.
The _ops_ argument can accept _enter_, _leave_, _enterstep_, and
_leavestep_ as valid operations:
1. _enter_ - Invoke _command_ whenever the command _name_ is
executed, just before the actual execution takes place.
2. _leave_ - Invoke _command_ whenever the command _name_ is
executed, just after the actual execution takes place.
3. _enterstep_ - Invoke _command_ for every tcl command which is
executed inside the procedure _name_, just before the actual
execution takes place. Setting a _enterstep_ trace on a _command_
will not result in an error and is simply ignored.
4. _leavestep_ - Invoke _command_ for every tcl command which is
executed inside the procedure _name_, just after the actual
execution takes place. Setting a _leavestep_ trace on a _command_
will not result in an error and is simply ignored.
When the trace triggers, depending on the operations being traced, a
number of arguments are appended to command so that the actual command
is as follows:
For _enter_ and _enterstep_ operations:
command command-string op
_command-string_ gives the complete current command being executed,
including all arguments in their fully expanded form.
_Op_ indicates what operation is being performed on the
variable, and is one of _enter_ or _enterstep_ here.
The trace operation can be used to stop the command from executing,
by deleting the command in question. Of course when the command is
subsequently executed, an 'invalid command' error will occur.
For _leave_ and _leavestep_ operations:
command command-string code result op
_command-string_ gives the complete current command being executed,
including all arguments in their fully expanded form. _code_ gives
the result code of that execution, and _result_ gives its result
string. _Op_ indicates what operation is being performed on the
variable, and is one of _leave_ or _leavestep_ here.
_Command_ executes in the same context as the code that invoked
the traced operation: thus the _command_, if invoked from a procedure,
will have access to the same local variables as code in the procedure.
This context may be different than the context in which the trace was
created. If _command_ invokes a procedure \(which it normally does\)
then the procedure will have to use upvar or uplevel commands if it
wishes to access the local variables of the code which invoked the
trace operation. Note that if the value of a local variable is passed
as an argument to the traced command _name_ and is modified by
the _command_ procedure, the traced command _name_ will still
be invoked with the old value of the local variable. This is because
the argument list to _name_ is formed before the traced _command_
is invoked. Please see the section on _Future Scope_ below on how
to modify the arguments passed to _name_.
While _command_ is executing during an _execution_ trace, traces
on _name_ are temporarily disabled. This allows the _command_ to
execute _name_ in its body without invoking any other traces
again. If an error occurs while executing the _command_ body,
then the command _name_ as a whole will return that same error.
Therefore, if _catch_ command is used for invocation of the
_name_ command, it will also ignore errors resulting from such traces.
When multiple traces are set on _name_, then the sequence of trace
command invocation is as follows:
1. For _enter_ and _enterstep_ operations, the traced
commands are invoked in the reverse order of how these
traces were created.
2. For _leave_ and _leavestep_ operations, the traced
commands are invoked in the same order as how these
traces were created.
For example, if we have two traces on proc foo:
trace add execution foo {enter leave} {barA}
trace add execution foo {enter leave} {barB}
then the trace commands _barA_ and _barB_ will be invoked in
the following sequence:
barB {foo x} {enter}
barA {foo x} {enter}
foo x
barA {foo x} 0 {} {leave}
barB {foo x} 0 {} {leave}
The creation of many _enterstep_ or _leavestep_ traces can lead
to unintuitive results, since the invoked commands from one trace
can themselves lead to further command invocations for other traces.
However, these unintuitive results are completely predictable and safe
\(and tested in the test suite\). Nevertheless the user will probably
only want to have one such trace active at a time.
Once created, the trace remains in effect either until the trace is
removed with the _trace remove execution_ command, until the _name_
is deleted or until the interpreter is deleted. Note that renaming the
command _name_ will not remove the execution traces.
To implement _enterstep_ and _leavestep_ traces, it is necessary
to invoke traces regardless of at what level the _command_ is being
traced. This means that the value for _level_ argument to
Tcl\_CreateTrace and Tcl\_CreateObjTrace APIs should also accept _0_.
A value of _0_ implies that commands at all levels will be traced.
# Examples
The following script defines a procedure _foo_ and illustrates
several cases as to how its execution can be traced.
# Define the proc foo
proc foo {var} {
return [string index $var [expr {$var*2}]]
}
# Command to invoke on trace activation
proc print {args} {
puts stdout "PRINT: $args"
}
proc main {} {
puts stdout "================CASE 1========================="
puts stdout "Trace proc foo only"
trace add execution foo {enter leave} {print exec}
foo 4
puts stdout "================CASE 2========================="
puts stdout "Trace proc foo as well as all commands within it"
trace add execution foo {enterstep leavestep} {print step}
foo 4
# Remove all traces
trace remove execution foo {enter leave} {print exec}
trace remove execution foo {enterstep leavestep} {print step}
puts stdout "================CASE 3========================="
puts stdout "Add a trace on string command"
trace add execution string {enter leave} {print exec}
foo 4
trace remove execution string {enter leave} {print exec}
}
main
The expected output of running the above script would be:
===================CASE 1========================
Trace proc foo only
PRINT: exec {foo 4} enter
PRINT: exec {foo 4} 0 {} leave
===================CASE 2=======================
Trace proc foo as well as all commands within it
PRINT: exec {foo 4} enter
PRINT: step {expr {$var*2}} enterstep
PRINT: step {expr {$var*2}} 0 8 leavestep
PRINT: step {string index 4 8} enterstep
PRINT: step {string index 4 8} 0 {} leavestep
PRINT: step {return {}} enterstep
PRINT: step {return {}} 2 {} leavestep
PRINT: exec {foo 4} 0 {} leave
===================CASE 3=======================
Add a trace on string command
PRINT: exec {string index 4 8} enter
PRINT: exec {string index 4 8} 0 {} leave
Case 1 specifies a enter and leave trace on proc foo.
Here the proc foo is fully byte-code-compiled.
Case 2 additionally invokes a enterstep and leavestep trace on
proc foo. This means that it will trace each command
that is inovked within the proc foo.
Here the proc foo is \*not\* byte-code-compiled. This is
implemented by setting the DONT\_COMPILE\_CMDS\_INLINE flag.
Case 3 specifies a trace on string command only.
Here all commands within proc foo, except string command,
is byte-code-compiled. This is implemented by modifying
compilation engine to check for CMD\_HAS\_EXEC\_TRACES flag
before generating any byte-code.
# Reference Implementation
This proposal was originally implemented by Vince Darley. Please see
Feature Request \#462580:
<http://sf.net/tracker/?func=detail&aid=462580&group\_id=10894&atid=360894>
The original patch from Vince Darley has been modified in the
following respects:
1. For _enter_ and _enterstep_ operations, the original patch
passed arguments to the _command_ in its unexpanded form.
This behavior has been changed to pass the arguments in its
fully expanded form since it should be more useful for debugging
scripts.
2. The original patch could not trace Tcl commands that were
invoked inside a procedure because tracing is currently not
possible for compiled commands. Therefore, the patch was
modified such that Tcl commands are no longer internally
compiled if a trace has been set on a command.
3. For multiple traces on same command, the original patch
invoked the traces in the same order as they were created.
This behavior was changed so that for _enter_ and _enterstep_
operations, the traces are invoked in the reverse order of
its creation. For _leave_ and _leavestep_, the traces are
still invoked in the original order.
4. The original patch was created on 2000-Sept-14. It was updated
to work with the current CVS head.
The latest patch for this tip 62 is available at:
<http://www.employees.org/~hlavana/tcl/>
The main changes for the patch are described in brief next.
Two new flags have been defined in tcl.h:
#define TCL_TRACE_ENTER_EXEC 1
#define TCL_TRACE_LEAVE_EXEC 2
These flag values are passed to Tcl\_CreateObjTrace and used by command
execution traces. More internal flags for slots 4, 8, 15, 16, 32 are
defined in tclCmdMZ.c file: TCL\_TRACE\_ENTER\_DURING\_EXEC,
TCL\_TRACE\_LEAVE\_DURING\_EXEC, TCL\_TRACE\_ANY\_EXEC, TCL\_TRACE\_EXEC\_IN\_PROGRESS
and TCL\_TRACE\_EXEC\_DIRECT.
A new function TclTraceExecutionObjCmd function implements the
_trace \{add\|remove\|list\} execution ..._ subcommands.
A new function TclCheckExecutionTraces is defined to check for traces added
by the execution subcommand. A new function TclCheckInterpTraces is defined
to check for global traces added by the Tcl\_CreateObjTrace command.
The TclEvalObjvInternal has been modified to call the above
two functions before as well as after the original command is executed.
A new function TraceExecutionProc is invoked, when necessary, to execute
the actual trace command in the interpreter.
A new structure ActiveInterpTrace has been defined for internal use so
that it behaves reasonably when traces are deleted while active.
In tclVar.c file, the function CallTraces has been renamed to CallVarTraces
and iPtr->activeTracePtr has been renamed to iPtr->activeTraceVarPtr.
An additional check for \(tracePtr->level == 0\) has been added in
Tcl\_EvalObjv and TclExecuteByteCode functions, so as to enable
command tracing at all levels.
# Benchmark Results
The benchmark results corresponds to _Version 1.1_ of the reference
implementation.
One potential objection to this TIP could be that it may affect the
performance of the Tcl-core. Therefore, I have run the
_runbench.tcl_ script from the tclbench module for comparison on a
Sun Ultra5, Solaris2.6 machine. The results have been posted at
<http://sf.net/tracker/?func=detail&aid=462580&group\_id=10894&atid=360894>
These results show that there is hardly any performance hit, if any,
by addition of this feature. Of course when you activate a trace on a
command, then you will see a performance hit, but since primary uses
of traces will be in profiling and debugging, that isn't an issue.
# Future Scope
This proposal does not allow for the trace invocation _command_
to do the following:
1. modify the number of arguments passed to _name_
2. modify the value of arguments passed to _name_
3. modify the result value and result code returned by _name_
4. skip invocation of _name_ altogether if desired.
Consider the example of adding a sub-command "string reverse ..."
as shown on <http://mini.net/tcl/1570.html.>
Instead of using the rename command, it should be possible to use
the trace command to do the same, as follows:
trace add execution string {enter} {::mylib::stringx}
proc ::mylib::stringx {subcmd args} {
switch -exact -- $subcmd {
"reverse" {
# Hmm ... this is my subcommand, process it here
set returnValue [code_to_reverse_string_value]
# We need a mechansim to return immediately here
# with the processed results and an appropriate
# code value and not invoke the original string command.
}
default {
# This is probably a vaild subcommand, so do nothing
# and let the original string command handle it
}
}
}
# Copyright
This document has been placed in the public domain.