Author: Hemang Lavana <HemangLavana@users.sourceforge.net>
Author: Vince Darley <vince.darley@eurobios.com>
State: Final
Type: Project
Vote: Done
Created: 18-Sep-2001
Post-History:
Tcl-Version: 8.4
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:
enter - Invoke command whenever the command name is executed, just before the actual execution takes place.
leave - Invoke command whenever the command name is executed, just after the actual execution takes place.
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.
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:
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.
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.
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.
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:
modify the number of arguments passed to name
modify the value of arguments passed to name
modify the result value and result code returned by name
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.