TIP: 62 Title: Add Support for Command Tracing Version: $Revision: 1.11 $ Author: Hemang Lavana Author: Vince Darley 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: 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.