Version 14 of DTrace

DTrace

DTrace is a comprehensive dynamic tracing framework created by Sun. It provides a powerful infrastructure to permit administrators, developers, and service personnel to concisely answer arbitrary questions about the behavior of the operating system and user programs.

DTrace is available starting with Solaris 10 3/05, OpenSolaris build 43 and MacOS X Leopard [L1 ], a port to FreeBSD is underway [L2 ]. For more details on OS Support, see [L3 ].

Further Reading:

Tcl DTrace provider

DAS Tcl releases 8.4.16 and 8.5b1 introduce a Tcl DTrace provider, c.f. Patch 1793984 [L4 ].

This uses the DTrace USDT facility (user-land statically defined tracing) [L5 ], and is-enabled probes [L6 ] to reduce the cost of probe-sites to a branch and a few noops when tracing is not enabled.

The information available for tracing is similar to the existing TCL_COMPILE_DEBUG and TCL_MEM_DEBUG facilities, but with the big advantage that DTrace probes have essentially zero cost when not in use, so DTrace support can be enabled in production builds, with no performance penalty when not tracing.

There are many other advantages, such as simultaneous tracing of all processes using Tcl on a system, integration with syscall tracing, control over exactly what & when to trace, stats collection via aggregations, etc.

DTrace support is enabled via the --enable-dtrace configure option, it is disabled by default and will only enable if DTrace is present on the system.

The following probes are made available by the tcl* provider (c.f. tclDTrace.d [L7 ] for more details):

tcl*:::proc-entry
    triggered immediately before proc bytecode execution
	arg0: proc name			 (string)
	arg1: number of arguments	       (int)
	arg2: array of proc argument objects    (Tcl_Obj**)

tcl*:::proc-return
    triggered immediately after proc bytecode execution
	arg0: proc name			 (string)
	arg1: return code		       (int)

tcl*:::proc-result
    triggered after proc-return probe and result processing
	arg0: proc name			 (string)
	arg1: return code		       (int)
	arg2: proc result		       (string)
	arg3: proc result object		(Tcl_Obj*)

tcl*:::proc-args
    triggered before proc-entry probe, gives access to string
    representation of proc arguments
	arg0: proc name			 (string)
	arg1-arg9: proc arguments or NULL       (strings)

tcl*:::proc-info
    triggered before proc-entry probe, gives access to TIP 280
    information for the proc invocation (i.e. [info frame 0])
	arg0: TIP 280 cmd		       (string)
	arg1: TIP 280 type		      (string)
	arg2: TIP 280 proc		      (string)
	arg3: TIP 280 file		      (string)
	arg4: TIP 280 line		      (int)
	arg5: TIP 280 level		     (int)


tcl*:::cmd-entry
    triggered immediately before commmand execution
	arg0: command name		      (string)
	arg1: number of arguments	       (int)
	arg2: array of command argument objects (Tcl_Obj**)

tcl*:::cmd-return
    triggered immediately after commmand execution
	arg0: command name		      (string)
	arg1: return code		       (int)

tcl*:::cmd-result
    triggered after cmd-return probe and result processing
	arg0: command name		      (string)
	arg1: return code		       (int)
	arg2: command result		    (string)
	arg3: command result object	     (Tcl_Obj*)

tcl*:::cmd-args
    triggered before cmd-entry probe, gives access to string
    representation of command arguments
	arg0: command name		      (string)
	arg1-arg9: command arguments or NULL    (strings)

tcl*:::cmd-info
    triggered before cmd-entry probe, gives access to TIP 280
    information for the command invocation (i.e. [info frame 0])
	arg0: TIP 280 cmd		       (string)
	arg1: TIP 280 type		      (string)
	arg2: TIP 280 proc		      (string)
	arg3: TIP 280 file		      (string)
	arg4: TIP 280 line		      (int)
	arg5: TIP 280 level		     (int)


tcl*:::inst-start
    triggered immediately before execution of a bytecode
	arg0: bytecode name		     (string)
	arg1: depth of stack		    (int)
	arg2: top of stack		      (Tcl_Obj**)

tcl*:::inst-done
    triggered immediately after execution of a bytecode
	arg0: bytecode name		     (string)
	arg1: depth of stack		    (int)
	arg2: top of stack		      (Tcl_Obj**)


tcl*:::obj-create
    triggered immediately after a new Tcl_Obj has been created
	arg0: object created		    (Tcl_Obj*)

tcl*:::obj-free
    triggered immediately before a Tcl_Obj is freed
	arg0: object to be freed		(Tcl_Obj*)


tcl*:::tcl-probe
    triggered when the ::tcl::dtrace command is called
	arg0-arg9: command arguments	    (strings)

Notes:

the -entry and -return probes are cheap to use and are triggered immediately before and after proc resp. command execution, so they are suitable for timing measurements e.g. using vtimestamp.
while similar to -entry and -return, the -args and -result probes are triggered somewhat earlier (resp. later) and are more expensive to use (because they retrieve/compute string representations).
the -info probes returning TIP 280 information are unavailable in Tcl 8.4 (currently, this is the case even in 8.4 with TIP 280 support enabled); they are fairly expensive to use (mainly because they are currently implemented by retrieving the full TIP280 dict object, extracting information from it and throwing it away).
the arg2 argument of the inst- probes points to the top of the object stack, i.e. the last element of an array of TclObj*s of length arg1; in contrast to the arg2 argument of the -entry probes, which points to the first element of an array of TclObj*s of length arg1.
it is currently quite tedious to retrieve information from Tcl_Obj**-typed probe arguments (c.f. examples below), work is underway on a DTrace translator for Tcl_Obj* that will make this easier.

Examples

A few sample experiments to illustrate the tcl*::: probes; note that these are very much baby-examples, a real investigation would want to take advantage of other DTrace providers such as syscall. For more featureful examples, see the DTraceToolkit section below.

All examples were run against Tcl 8.5b1 on MacOS X Leopard. DTrace output has been trimmed for brevity.

The first few examples trace the following script dtrace.tcl:

tcl::dtrace "start tracing"
proc main args {
    for {set i 0} {$i < 3} {incr i} {
	tcl::dtrace loop $i
    }
}
eval main $argv

List all tcl*::: probes:

# dtrace -l -P "tcl*"

	   ID   PROVIDER	    MODULE			  FUNCTION NAME
	21377     tcl717	   tcltest	       TclEvalObjvInternal cmd-args
	21378     tcl717	   tcltest	       TclEvalObjvInternal cmd-entry
	21379     tcl717	   tcltest	       TclEvalObjvInternal cmd-info
	21380     tcl717	   tcltest	       TclEvalObjvInternal cmd-result
	21381     tcl717	   tcltest	       TclEvalObjvInternal cmd-return
	21382     tcl717	   tcltest		TclExecuteByteCode inst-done
	21383     tcl717	   tcltest		TclExecuteByteCode inst-start
	21384     tcl717	   tcltest		      NewOSTypeObj obj-create
....
	21489     tcl717	   tcltest		  Tcl_CreateInterp obj-create
	21490     tcl717	   tcltest		 FreeParsedVarName obj-free
....
	21577     tcl717	   tcltest		  TclRenameCommand obj-free
	21578     tcl717	   tcltest	      TclObjInterpProcCore proc-args
	21579     tcl717	   tcltest	      TclObjInterpProcCore proc-entry
	21580     tcl717	   tcltest	      TclObjInterpProcCore proc-info
	21581     tcl717	   tcltest	      TclObjInterpProcCore proc-result
	21582     tcl717	   tcltest	      TclObjInterpProcCore proc-return
	21583     tcl717	   tcltest		      DTraceObjCmd tcl-probe

Trace proc and command flow with the following D script: (setting self->tracing from the first call to ::tcl::dtrace is used to avoid tracing tcl initialization)

#!/usr/sbin/dtrace -s

enum {maxstrlen = 50};

tcl*:::tcl-probe /!self->tracing/ {
    self->tracing = 1;
}

tcl*:::tcl-probe {
    printf("%s %s",
	    arg0 ? copyinstr(arg0, maxstrlen) : "",
	    arg1 ? copyinstr(arg1, maxstrlen) : "");
}

#pragma D option flowindent
tcl*:::proc-entry, tcl*:::proc-return, tcl*:::cmd-entry, tcl*:::cmd-return /self->tracing/ {
    printf("%s", arg0 ? copyinstr(arg0, maxstrlen) : "");
}