TIP #62: Add Support for Command Tracing
_____________________________________________________________________________
TIP:	62
Title:	Add Support for Command Tracing
Version:	$Revision: 1.11 $
Authors:	Hemang Lavana <HemangLavana@users.sourceforge.net>
	Vince Darley <vince.darley@eurobios.com>
State:	Final
Type:	Project
Tcl-Version:	8.4
Vote:	Done
Created:	Tue Sep 18 00:00:00 UTC 2001
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.
_____________________________________________________________________________
Colophon
TIP AutoGenerator - written by Donal K. Fellows