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 ].

Accolades

DTrace itself is amazing. I once saw the DTrace author sit down with Andrew Tridgel in a pub in Sydney, and use DTrace on a Mac to diagnose a Samba problem Tridge had been chasing for ages.

: -- Steve Landers

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.

I gave a talk on Profiling and Debugging Tcl with DTrace at the 7th European Tcl/Tk Users Meeting Conference, c.f. slides at [L7 ].

Probes

The following probes are made available by the tcl* provider (c.f. tclDTrace.d [L8 ] 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) : "");
}