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

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

Further Reading

ETW is a similar facility provided by Windows (XP or later) accessible with TWAPI.

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) : "");
}

output after running dtrace.tcl:

CPU FUNCTION
  0 | DTraceObjCmd:tcl-probe                  start tracing
  0  <- TclEvalObjvInternal                   tcl::dtrace
  0  -> TclEvalObjvInternal                   proc
  0  <- TclEvalObjvInternal                   proc
  0  -> TclEvalObjvInternal                   eval
  0    -> TclEvalObjvInternal                 main
  0      -> TclObjInterpProcCore              main
  0        -> TclEvalObjvInternal             tcl::dtrace
  0         | DTraceObjCmd:tcl-probe          loop 0
  0        <- TclEvalObjvInternal             tcl::dtrace
  0        -> TclEvalObjvInternal             tcl::dtrace
  0         | DTraceObjCmd:tcl-probe          loop 1
  0        <- TclEvalObjvInternal             tcl::dtrace
  0        -> TclEvalObjvInternal             tcl::dtrace
  0         | DTraceObjCmd:tcl-probe          loop 2
  0        <- TclEvalObjvInternal             tcl::dtrace
  0      <- TclObjInterpProcCore              main
  0    <- TclEvalObjvInternal                 main
  0  <- TclEvalObjvInternal                   eval
  0  -> TclEvalObjvInternal                   exit
  • Trace command flow and bytecode execution with the following D script:
#!/usr/sbin/dtrace -s

enum {maxstrlen = 50};

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

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

output after running dtrace.tcl:

CPU FUNCTION
  0  <- TclEvalObjvInternal                   tcl::dtrace
  0  -> TclEvalObjvInternal                   proc
  0  <- TclEvalObjvInternal                   proc
  0  -> TclEvalObjvInternal                   eval
  0    -> TclEvalObjvInternal                 main
  0     | TclExecuteByteCode:inst-start       push1
  0     | TclExecuteByteCode:inst-done        push1
  0     | TclExecuteByteCode:inst-start       storeScalar1
  0     | TclExecuteByteCode:inst-done        storeScalar1
  0     | TclExecuteByteCode:inst-start       jump1
  0     | TclExecuteByteCode:inst-done        jump1
  0     | TclExecuteByteCode:inst-start       loadScalar1
  0     | TclExecuteByteCode:inst-done        loadScalar1
  0     | TclExecuteByteCode:inst-start       push1
  0     | TclExecuteByteCode:inst-done        push1
  0     | TclExecuteByteCode:inst-start       lt
  0     | TclExecuteByteCode:inst-done        lt
  0     | TclExecuteByteCode:inst-start       push1
  0     | TclExecuteByteCode:inst-done        push1
  0     | TclExecuteByteCode:inst-start       push1
  0     | TclExecuteByteCode:inst-done        push1
  0     | TclExecuteByteCode:inst-start       loadScalar1
  0     | TclExecuteByteCode:inst-done        loadScalar1
  0     | TclExecuteByteCode:inst-start       invokeStk1
  0      -> TclEvalObjvInternal               tcl::dtrace
  0      <- TclEvalObjvInternal               tcl::dtrace
  0     | TclExecuteByteCode:inst-done        invokeStk1
  0     | TclExecuteByteCode:inst-start       startCommand
  0     | TclExecuteByteCode:inst-done        startCommand
  0     | TclExecuteByteCode:inst-start       incrScalar1Imm
  0     | TclExecuteByteCode:inst-done        incrScalar1Imm
....
  0     | TclExecuteByteCode:inst-start       loadScalar1
  0     | TclExecuteByteCode:inst-done        loadScalar1
  0     | TclExecuteByteCode:inst-start       push1
  0     | TclExecuteByteCode:inst-done        push1
  0     | TclExecuteByteCode:inst-start       lt
  0     | TclExecuteByteCode:inst-done        lt
  0     | TclExecuteByteCode:inst-start       push1
  0     | TclExecuteByteCode:inst-done        push1
  0     | TclExecuteByteCode:inst-start       done
  0     | TclExecuteByteCode:inst-done        done
  0    <- TclEvalObjvInternal                 main
  0  <- TclEvalObjvInternal                   eval
  0 | TclExecuteByteCode:inst-start           push1
  0 | TclExecuteByteCode:inst-done            push1
  0 | TclExecuteByteCode:inst-start           push1
  0 | TclExecuteByteCode:inst-done            push1
  0 | TclExecuteByteCode:inst-start           invokeStk1
  0  -> TclEvalObjvInternal                   exit
  • Trace command flow and bytecode execution with object stack: (the top two objects on the stack are printed)
#!/usr/sbin/dtrace -s

enum {maxstrlen = 50};

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

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

tcl*:::inst-start, tcl*:::inst-done /!self->tracing/ {
    this->stack = arg1 ? ((Tcl_Obj**)copyin((user_addr_t)(((Tcl_Obj**)arg2) - (arg1 - 1)),
        sizeof(Tcl_Obj*) * arg1)) + (arg1 - 1) : NULL;
    this->i = 0;
    this->o = arg1 > this->i && *(this->stack - this->i) ?
        (Tcl_Obj*)copyin((user_addr_t)*(this->stack - this->i), sizeof(Tcl_Obj)) : NULL;
    this->s0 = this->o ? (this->o->bytes ? copyinstr((user_addr_t)this->o->bytes, maxstrlen) :
        lltostr(this->o->internalRep.longValue)) : "";
    this->i = 1;
    this->o = arg1 > this->i && *(this->stack - this->i) ?
        (Tcl_Obj*)copyin((user_addr_t)*(this->stack - this->i), sizeof(Tcl_Obj)) : NULL;
    this->s1 = this->o ? (this->o->bytes ? copyinstr((user_addr_t)this->o->bytes, maxstrlen) :
        lltostr(this->o->internalRep.longValue)) : "";
    printf("%s depth: %d stack: \"%s\" \"%s\"", arg0 ? copyinstr(arg0, maxstrlen) : "",
        arg1, this->s0, this->s1);
}

output after running dtrace.tcl:

CPU FUNCTION
  0  <- TclEvalObjvInternal                   tcl::dtrace
  0  -> TclEvalObjvInternal                   proc
  0  <- TclEvalObjvInternal                   proc
  0  -> TclEvalObjvInternal                   eval
  0    -> TclEvalObjvInternal                 main
  0     | TclExecuteByteCode:inst-start       push1 depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-done        push1 depth: 1 stack: "0" ""
  0     | TclExecuteByteCode:inst-start       storeScalar1 depth: 1 stack: "0" ""
  0     | TclExecuteByteCode:inst-done        storeScalar1 depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-start       jump1 depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-done        jump1 depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-start       loadScalar1 depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-done        loadScalar1 depth: 1 stack: "0" ""
  0     | TclExecuteByteCode:inst-start       push1 depth: 1 stack: "0" ""
  0     | TclExecuteByteCode:inst-done        push1 depth: 2 stack: "3" "0"
  0     | TclExecuteByteCode:inst-start       lt depth: 2 stack: "3" "0"
  0     | TclExecuteByteCode:inst-done        lt depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-start       push1 depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-done        push1 depth: 1 stack: "tcl::dtrace" ""
  0     | TclExecuteByteCode:inst-start       push1 depth: 1 stack: "tcl::dtrace" ""
  0     | TclExecuteByteCode:inst-done        push1 depth: 2 stack: "loop" "tcl::dtrace"
  0     | TclExecuteByteCode:inst-start       loadScalar1 depth: 2 stack: "loop" "tcl::dtrace"
  0     | TclExecuteByteCode:inst-done        loadScalar1 depth: 3 stack: "0" "loop"
  0     | TclExecuteByteCode:inst-start       invokeStk1 depth: 3 stack: "0" "loop"
  0      -> TclEvalObjvInternal               tcl::dtrace
  0      <- TclEvalObjvInternal               tcl::dtrace
  0     | TclExecuteByteCode:inst-done        invokeStk1 depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-start       startCommand depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-done        startCommand depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-start       incrScalar1Imm depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-done        incrScalar1Imm depth: 0 stack: "" ""
....
  0     | TclExecuteByteCode:inst-start       loadScalar1 depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-done        loadScalar1 depth: 1 stack: "3" ""
  0     | TclExecuteByteCode:inst-start       push1 depth: 1 stack: "3" ""
  0     | TclExecuteByteCode:inst-done        push1 depth: 2 stack: "3" "3"
  0     | TclExecuteByteCode:inst-start       lt depth: 2 stack: "3" "3"
  0     | TclExecuteByteCode:inst-done        lt depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-start       push1 depth: 0 stack: "" ""
  0     | TclExecuteByteCode:inst-done        push1 depth: 1 stack: "" ""
  0     | TclExecuteByteCode:inst-start       done depth: 1 stack: "" ""
  0     | TclExecuteByteCode:inst-done        done depth: 1 stack: "" ""
  0    <- TclEvalObjvInternal                 main
  0  <- TclEvalObjvInternal                   eval
  0 | TclExecuteByteCode:inst-start           push1 depth: 0 stack: "" ""
  0 | TclExecuteByteCode:inst-done            push1 depth: 1 stack: "exit" ""
  0 | TclExecuteByteCode:inst-start           push1 depth: 1 stack: "exit" ""
  0 | TclExecuteByteCode:inst-done            push1 depth: 2 stack: "0" "exit"
  0 | TclExecuteByteCode:inst-start           invokeStk1 depth: 2 stack: "0" "exit"
  0  -> TclEvalObjvInternal                   exit
  • Trace proc & command flow, arguments, return values and info:
#!/usr/sbin/dtrace -s

enum {maxstrlen = 50};

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

#pragma D option flowindent
tcl*:::proc-entry, tcl*:::cmd-entry /self->tracing/ {
    this->args = arg1 ? (Tcl_Obj**)copyin(arg2, sizeof(Tcl_Obj*) * arg1) : NULL;
    this->i = 0;
    this->o = arg1 > this->i && *(this->args + this->i) ?
        (Tcl_Obj*)copyin((user_addr_t)*(this->args + this->i), sizeof(Tcl_Obj)) : NULL;
    this->s0 = this->o ? (this->o->bytes ? copyinstr((user_addr_t)this->o->bytes, maxstrlen) :
        lltostr(this->o->internalRep.longValue)) : "";
    this->i = 1;
    this->o = arg1 > this->i && *(this->args + this->i) ?
        (Tcl_Obj*)copyin((user_addr_t)*(this->args + this->i), sizeof(Tcl_Obj)) : NULL;
    this->s1 = this->o ? (this->o->bytes ? copyinstr((user_addr_t)this->o->bytes, maxstrlen) :
        lltostr(this->o->internalRep.longValue)) : "";
    this->i = 2;
    this->o = arg1 > this->i && *(this->args + this->i) ?
        (Tcl_Obj*)copyin((user_addr_t)*(this->args + this->i), sizeof(Tcl_Obj)) : NULL;
    this->s2 = this->o ? (this->o->bytes ? copyinstr((user_addr_t)this->o->bytes, maxstrlen) :
        lltostr(this->o->internalRep.longValue)) : "";
    printf("%s objc: %d objv: \"%s\" \"%s\" \"%s\"", arg0 ? copyinstr(arg0, maxstrlen) : "",
        arg1, this->s0, this->s1, this->s2);
}
tcl*:::proc-return, tcl*:::cmd-return /self->tracing/ {
    printf("%s %d", arg0 ? copyinstr(arg0, maxstrlen) : "", arg1);
}

tcl*:::proc-args, tcl*:::cmd-args /self->tracing/ {
    printf("%s \"%s\" \"%s\" \"%s\" \"%s\" \"%s\" \"%s\" \"%s\" \"%s\" \"%s\"",
            arg0 ? copyinstr(arg0, maxstrlen) : "",
            arg1 ? copyinstr(arg1, maxstrlen) : "",
            arg2 ? copyinstr(arg2, maxstrlen) : "",
            arg3 ? copyinstr(arg3, maxstrlen) : "",
            arg4 ? copyinstr(arg4, maxstrlen) : "",
            arg5 ? copyinstr(arg5, maxstrlen) : "",
            arg6 ? copyinstr(arg6, maxstrlen) : "",
            arg7 ? copyinstr(arg7, maxstrlen) : "",
            arg8 ? copyinstr(arg8, maxstrlen) : "",
            arg9 ? copyinstr(arg9, maxstrlen) : "");
}

tcl*:::proc-info, tcl*:::cmd-info /self->tracing/ {
    printf("cmd: \"%s\" type: \"%s\" proc: \"%s\" file: \"%s\" line: %d level: %d",
            arg0 ? copyinstr(arg0, maxstrlen) : "",
            arg1 ? copyinstr(arg1, maxstrlen) : "",
            arg2 ? copyinstr(arg2, maxstrlen) : "",
            arg3 ? basename(copyinstr(arg3, 255)) : "",
            arg4, arg5);
}

tcl*:::proc-result, tcl*:::cmd-result /self->tracing/ {
    printf("%s %d \"%s\"", arg0 ? copyinstr(arg0, maxstrlen) : "", arg1,
        arg2 ? copyinstr(arg2, maxstrlen) : "");
}

output after running dtrace.tcl:

CPU FUNCTION
  1 | TclEvalObjvInternal:cmd-args            eval "main" "" "" "" "" "" "" "" ""
  1 | TclEvalObjvInternal:cmd-info            cmd: "eval main $argv" type: "source" proc: "" file: "dtrace.tcl" line: 7 level: 0
  1  -> TclEvalObjvInternal                   eval objc: 2 objv: "main" "" ""
  1   | TclEvalObjvInternal:cmd-args          main "" "" "" "" "" "" "" "" ""
  1   | TclEvalObjvInternal:cmd-info          cmd: "main" type: "eval" proc: "" file: "" line: 1 level: 0
  1    -> TclEvalObjvInternal                 main objc: 0 objv: "" "" ""
  1     | TclObjInterpProcCore:proc-args      main "" "" "" "" "" "" "" "" ""
  1     | TclObjInterpProcCore:proc-info      cmd: "main" type: "eval" proc: "" file: "" line: 1 level: 1
  1      -> TclObjInterpProcCore              main objc: 0 objv: "" "" ""
  1       | TclEvalObjvInternal:cmd-args      tcl::dtrace "loop" "0" "" "" "" "" "" "" ""
  1       | TclEvalObjvInternal:cmd-info      cmd: "tcl::dtrace loop $i" type: "source" proc: "::main" file: "dtrace.tcl" line: 4 level: 0
  1        -> TclEvalObjvInternal             tcl::dtrace objc: 2 objv: "loop" "0" ""
  1        <- TclEvalObjvInternal             tcl::dtrace 0
  1       | TclEvalObjvInternal:cmd-result    tcl::dtrace 0 ""
  1       | TclEvalObjvInternal:cmd-args      tcl::dtrace "loop" "1" "" "" "" "" "" "" ""
  1       | TclEvalObjvInternal:cmd-info      cmd: "tcl::dtrace loop $i" type: "source" proc: "::main" file: "dtrace.tcl" line: 4 level: 0
  1        -> TclEvalObjvInternal             tcl::dtrace objc: 2 objv: "loop" "1" ""
  1        <- TclEvalObjvInternal             tcl::dtrace 0
  1       | TclEvalObjvInternal:cmd-result    tcl::dtrace 0 ""
  1       | TclEvalObjvInternal:cmd-args      tcl::dtrace "loop" "2" "" "" "" "" "" "" ""
  1       | TclEvalObjvInternal:cmd-info      cmd: "tcl::dtrace loop $i" type: "source" proc: "::main" file: "dtrace.tcl" line: 4 level: 0
  1        -> TclEvalObjvInternal             tcl::dtrace objc: 2 objv: "loop" "2" ""
  1        <- TclEvalObjvInternal             tcl::dtrace 0
  1       | TclEvalObjvInternal:cmd-result    tcl::dtrace 0 ""
  1      <- TclObjInterpProcCore              main 0
  1     | TclObjInterpProcCore:proc-result    main 0 ""
  1    <- TclEvalObjvInternal                 main 0
  1   | TclEvalObjvInternal:cmd-result        main 0 ""
  1  <- TclEvalObjvInternal                   eval 0
  1 | TclEvalObjvInternal:cmd-result          eval 0 ""
  1 | TclEvalObjvInternal:cmd-args            exit "0" "" "" "" "" "" "" "" ""
  1 | TclEvalObjvInternal:cmd-info            cmd: "exit 0" type: "eval" proc: "" file: "" line: 1 level: 0
  1  -> TclEvalObjvInternal                   exit objc: 1 objv: "0" "" ""
  • Trace command flow and object creation & destruction:
#!/usr/sbin/dtrace -s

enum {maxstrlen = 50};

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

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

tcl*:::obj-create, tcl*:::obj-free /self->tracing/ {
    printf("0x%p", arg0);
}

output after running dtrace.tcl:

CPU FUNCTION
  1  <- TclEvalObjvInternal                   tcl::dtrace
  1 | TclFreeObj:obj-free                     0x189830
  1 | TclFreeObj:obj-free                     0x189818
  1 | Tcl_NewStringObj:obj-create             0x189818
  1 | Tcl_SetObjResult:obj-free               0x1892f0
  1 | Tcl_NewStringObj:obj-create             0x1892f0
  1 | Tcl_NewStringObj:obj-create             0x189830
  1 | Tcl_NewStringObj:obj-create             0x1897b8
  1 | ResetObjResult:obj-create               0x1897a0
  1  -> TclEvalObjvInternal                   proc
  1  <- TclEvalObjvInternal                   proc
  1 | TclFreeObj:obj-free                     0x189818
  1 | TclFreeObj:obj-free                     0x1892f0
  1 | TclFreeObj:obj-free                     0x189830
  1 | Tcl_NewStringObj:obj-create             0x189830
  1 | Tcl_SetObjResult:obj-free               0x1897a0
  1 | Tcl_NewStringObj:obj-create             0x1897a0
  1 | Tcl_NewStringObj:obj-create             0x1892f0
  1 | Tcl_NewStringObj:obj-create             0x189818
  1 | TclFreeObj:obj-free                     0x189818
  1 | TclFreeObj:obj-free                     0x1892f0
  1 | ResetObjResult:obj-create               0x1892f0
  1  -> TclEvalObjvInternal                   eval
  1   | Tcl_ConcatObj:obj-create              0x189818
  1   | Tcl_NewStringObj:obj-create           0x189488
  1   | Tcl_SetObjResult:obj-free             0x1892f0
  1   | ResetObjResult:obj-create             0x1892f0
  1    -> TclEvalObjvInternal                 main
  1     | TclCreateLiteral:obj-create         0x189308
  1     | TclCreateLiteral:obj-create         0x189368
  1     | Tcl_NewObj:obj-create               0x189290
  1     | Tcl_NewObj:obj-create               0x189920
  1     | Tcl_NewObj:obj-create               0x188990
  1     | TclCreateLiteral:obj-create         0x1898a8
  1     | TclFreeObj:obj-free                 0x188990
  1     | TclFreeObj:obj-free                 0x189920
  1     | TclFreeObj:obj-free                 0x189290
  1     | TclCreateLiteral:obj-create         0x189290
  1     | TclCreateLiteral:obj-create         0x189920
  1     | TclCreateLiteral:obj-create         0x188990
  1     | Tcl_NewListObj:obj-create           0x189cc8
  1      -> TclEvalObjvInternal               tcl::dtrace
  1      <- TclEvalObjvInternal               tcl::dtrace
  1     | TclExecuteByteCode:obj-create       0x188960
  1      -> TclEvalObjvInternal               tcl::dtrace
  1      <- TclEvalObjvInternal               tcl::dtrace
  1      -> TclEvalObjvInternal               tcl::dtrace
  1      <- TclEvalObjvInternal               tcl::dtrace
  1     | Tcl_SetObjResult:obj-free           0x1892f0
  1     | UnsetVarStruct:obj-free             0x189cc8
  1     | UnsetVarStruct:obj-free             0x188960
  1    <- TclEvalObjvInternal                 main
  1   | TclFreeObj:obj-free                   0x189488
  1   | TclEvalObjEx:obj-free                 0x189818
  1  <- TclEvalObjvInternal                   eval
  1 | TclFreeObj:obj-free                     0x189830
  1 | TclFreeObj:obj-free                     0x1897a0
  1 | TclFreeObj:obj-free                     0x189848
  1 | Tcl_NewObj:obj-create                   0x189848
  1 | Tcl_NewObj:obj-create                   0x1897a0
  1 | Tcl_NewLongObj:obj-create               0x189830
  1 | Tcl_NewObj:obj-create                   0x189818
  1 | Tcl_NewLongObj:obj-create               0x189488
  1 | TclFreeObj:obj-free                     0x189488
  1 | TclFreeObj:obj-free                     0x189818
  1 | TclFreeObj:obj-free                     0x1897a0
  1 | TclFreeObj:obj-free                     0x189830
  1 | ResetObjResult:obj-create               0x1897a0
  1 | TclCreateLiteral:obj-create             0x189830
  1  -> TclEvalObjvInternal                   exit

Aggregations

Aggregations are one of the most interesting features of DTrace. They allow powerful statistics collection in a lightweight & performant fashion (see [L9 ] for more details).

The following examples trace the tcl testsuite run as follows:

make test TESTFLAGS='-singleproc 1 -notfile clock.test'
  • Count number of times a given procedure, command or bytecode is called, and number of times an object was allocated of freed in a given core function:
#!/usr/sbin/dtrace -s

enum {maxstrlen = 20};

tcl*:::proc-entry {
    @proc[copyinstr(arg0, maxstrlen)] = count();
}

tcl*:::cmd-entry {
    @cmd[copyinstr(arg0, maxstrlen)] = count();
}

tcl*:::inst-start {
    @inst[copyinstr(arg0, maxstrlen)] = count();
}

tcl*:::obj-create, tcl*:::obj-free {
    @alloc[probefunc,probename] = count();
}

END {
    printf("\n *** proc  ***"); trunc(@proc,  50); printa(@proc);
    printf("\n *** cmd   ***"); trunc(@cmd,   50); printa(@cmd);
    printf("\n *** inst  ***"); trunc(@inst,  50); printa(@inst);
    printf("\n *** alloc ***"); trunc(@alloc, 50); printa(@alloc);
}

output after running testsuite:

 *** proc  ***
  AcceptList                                                      687
  OptGetPrgCounter                                                705
  note                                                            740
  OptInstr                                                        816
  OptIsPrg                                                        816
  tclInit                                                         917
  AddToSkippedBecause                                             965
  AcceptAll                                                       993
  recurse                                                         998
  echo                                                           1017
  foo                                                            1019
  convertToDouble                                                1026
  TestDesc                                                       1052
  TestNum                                                        1052
  ::tcltest::test                                                1053
  FillFilesExisted                                               1090
  mainThread                                                     1090
  auto_qualify                                                   1093
  Default                                                        1241
  Option                                                         1314
  outputChannel                                                  1634
  temporaryDirectory                                             1756
  readit                                                         2015
  Lget                                                           2212
  debug                                                          2268
  Set                                                            2336
  InterpStateName                                                2449
  Toplevel                                                       2555
  readlittle                                                     2742
  PathToken                                                      3586
  a                                                              4714
  gen-jisx0208-cp932                                             6684
  gen-jisx0208-euc-jp                                            6684
  limitConstraints                                               9622
  rand                                                          11175
  SafeFetch                                                     14649
  test                                                          14840
  CompareStrings                                                14890
  ::tcltest::Eval                                               14891
  ::tcltest::RunTest                                            14891
  Skipped                                                       15887
  match                                                         15893
  skip                                                          15913
  DebugDo                                                       15926
  preserveCore                                                  29789
  IsVerbose                                                     30817
  DebugPuts                                                     65542
  Configure                                                     76229
  MatchingOption                                                76345
  12days                                                       139212

 *** cmd   ***
  eof                                                            4438
  package                                                        4504
  a                                                              4864
  interp                                                         5001
  lrange                                                         5128
  trace                                                          5378
  catch                                                          6064
  gen-jisx0208-cp932                                             6684
  gen-jisx0208-euc-jp                                            6684
  limitConstraints                                               9622
  scan                                                           9793
  regexp                                                         9988
  if                                                            10567
  rand                                                          11175
  variable                                                      12715
  SafeFetch                                                     14649
  test                                                          14841
  CompareStrings                                                14890
  ::tcltest::Eval                                               14891
  ::tcltest::RunTest                                            14891
  Skipped                                                       15887
  match                                                         15893
  skip                                                          15913
  DebugDo                                                       15926
  ::tcl::Info_commands                                          16669
  ::namespace                                                   18842
  unset                                                         22662
  binary                                                        23085
  lappend                                                       23808
  proc                                                          25981
  set                                                           28059
  preserveCore                                                  29789
  IsVerbose                                                     30817
  puts                                                          32938
  file                                                          38741
  lsearch                                                       63582
  DebugPuts                                                     65542
  namespace                                                     73514
  Configure                                                     76229
  MatchingOption                                                76345
  array                                                         90468
  uplevel                                                       98712
  ::tcl::Info_level                                            111096
  format                                                       116454
  ::tcl::Info_exists                                           119262
  12days                                                       139212
  string                                                       183232
  gets                                                         221395
  list                                                         224646
  info                                                         252529

 *** inst  ***
  jump4                                                         31444
  incrArray1Imm                                                 32156
  listIndex                                                     35674
  break                                                         35695
  le                                                            39938
  streq                                                         45329
  bitor                                                         45883
  exprStk                                                       55050
  jumpFalse4                                                    58477
  strmatch                                                      58906
  bitand                                                        60905
  add                                                           66171
  jumpTable                                                     77879
  uminus                                                        77902
  neq                                                           86968
  foreach_start4                                                93811
  list                                                         104317
  jumpTrue4                                                    108719
  continue                                                     109965
  storeStk                                                     122426
  loadArray1                                                   149909
  strindex                                                     154036
  endCatch                                                     171591
  beginCatch4                                                  171593
  nsupvar                                                      185071
  not                                                          185698
  listIndexImm                                                 217261
  incrScalarStkImm                                             227718
  storeScalarStk                                               239274
  strcmp                                                       246829
  jumpTrue1                                                    275489
  foreach_step4                                                295285
  listLength                                                   309075
  ge                                                           313056
  concat1                                                      317770
  tryCvtToNumeric                                              439746
  variable                                                     561793
  jumpFalse1                                                   565578
  loadScalarStk                                                614973
  eq                                                           654179
  lt                                                           819184
  storeScalar1                                                 915483
  jump1                                                       1061800
  done                                                        1576516
  incrScalar1Imm                                              1580907
  pop                                                         1896961
  invokeStk1                                                  2085277
  loadScalar1                                                 4281620
  startCommand                                                5260375
  push1                                                      12554579

 *** alloc ***
  Tcl_GetIndexFromObjStruct                           obj-create                                                     1055
  Tcl_PkgRequireEx                                    obj-free                                                       1087
  TclGlob                                             obj-create                                                     1164
  TclDeleteExecEnv                                    obj-free                                                       1212
  TclCreateExecEnv                                    obj-create                                                     2138
  Tcl_CreateInterp                                    obj-create                                                     2138
  TclLookupVar                                        obj-free                                                       2169
  Tcl_Gets                                            obj-create                                                     2815
  GetKeys                                             obj-create                                                     2844
  Tcl_NewDictObj                                      obj-create                                                     3116
  Tcl_TraceObjCmd                                     obj-create                                                     3422
  TclCompileLindexCmd                                 obj-free                                                       4744
  NamespaceWhichCmd                                   obj-create                                                     5410
  NamespaceCodeCmd                                    obj-create                                                     6408
  Tcl_SplitObjCmd                                     obj-create                                                     8271
  Tcl_FSGetNormalizedPath                             obj-free                                                       8746
  Tcl_NewBignumObj                                    obj-create                                                     9602
  FreeFsPathInternalRep                               obj-free                                                       9988
  IndexTailVarIfKnown                                 obj-create                                                    11588
  TclEvalObjEx                                        obj-free                                                      16150
  Tcl_FSJoinPath                                      obj-free                                                      18906
  Tcl_NewUnicodeObj                                   obj-create                                                    18925
  Tcl_ConcatObj                                       obj-create                                                    19567
  DeleteDict                                          obj-free                                                      22757
  DeleteArray                                         obj-free                                                      23528
  TclInitInfoCmd                                      obj-create                                                    24587
  TclPtrSetVar                                        obj-free                                                      28376
  NamespaceOriginCmd                                  obj-create                                                    30343
  Tcl_NewLongObj                                      obj-create                                                    32761
  SetDictFromAny                                      obj-create                                                    34219
  TclDeleteLiteralTable                               obj-free                                                      35508
  TclCompileIfCmd                                     obj-free                                                      38328
  SetListFromAny                                      obj-create                                                    79802
  Tcl_ArrayObjCmd                                     obj-create                                                    86037
  Tcl_NewWideIntObj                                   obj-create                                                    90040
  TclObjLookupVarEx                                   obj-create                                                    90068
  Tcl_NewBooleanObj                                   obj-create                                                   154591
  UnsetVarStruct                                      obj-free                                                     251513
  Tcl_DuplicateObj                                    obj-create                                                   299570
  TclCreateLiteral                                    obj-create                                                   313519
  TclListObjCopy                                      obj-create                                                   601051
  Tcl_NewIntObj                                       obj-create                                                   617593
  Tcl_NewListObj                                      obj-create                                                   648323
  Tcl_NewObj                                          obj-create                                                  1092271
  ResetObjResult                                      obj-create                                                  1246966
  TclExecuteByteCode                                  obj-free                                                    1602643
  TclExecuteByteCode                                  obj-create                                                  2875523
  Tcl_SetObjResult                                    obj-free                                                    3108250
  Tcl_NewStringObj                                    obj-create                                                  4148812
  TclFreeObj                                          obj-free                                                    7175458
  • Determine distribution of object lifetime (microseconds elapsed between creation and destruction of an object):
#!/usr/sbin/dtrace -s

#pragma D option dynvarsize=100m

tcl*:::obj-create {
    self->ts[arg0] = vtimestamp;
}

tcl*:::obj-free /self->ts[arg0]/ {
    @["obj lifetime in us"] = quantize((vtimestamp - self->ts[arg0])/1000);
    self->ts[arg0] = 0;
}

output after running testsuite:

  obj lifetime in us
           value  ------------- Distribution ------------- count
               1 |                                         0
               2 |@@@@@@@@@@@                              3346100
               4 |@@@                                      871149
               8 |@@@@@@@                                  2309541
              16 |@@@@@@@                                  2209845
              32 |@@@@                                     1211125
              64 |@@                                       630321
             128 |@                                        371665
             256 |@                                        221164
             512 |@                                        155176
            1024 |@                                        187451
            2048 |                                         132903
            4096 |                                         152072
            8192 |                                         108423
           16384 |                                         77928
           32768 |                                         125644
           65536 |                                         53587
          131072 |                                         24400
          262144 |                                         15306
          524288 |                                         20803
         1048576 |                                         32471
         2097152 |                                         63030
         4194304 |                                         85745
         8388608 |                                         1799
        16777216 |                                         1272
        33554432 |                                         909
        67108864 |                                         588
       134217728 |                                         0

DTraceToolkit

Brendan Gregg has added support for the Tcl DTrace provider to his DTraceToolkit in version 0.99:

it has the following D scripts for tracing Tcl activity:

tcl_calldist.d
tcl_calls.d
tcl_calltime.d
tcl_cpudist.d
tcl_cputime.d
tcl_flow.d
tcl_flowtime.d
tcl_ins.d
tcl_insflow.d
tcl_proccalls.d
tcl_procflow.d
tcl_stat.d
tcl_syscalls.d
tcl_syscolors.d
tcl_who.d

DTraceToolkit contains sample output for all of its scripts, e.g. the following for one of the most interesting tcl_*.d scripts (no colors on the wiki of course):

The following are examples of tcl_syscolors.d.

This is a simple script to trace the flow of Tcl processes, Tcl commands and
system calls made, and renders the output in color ("colour") using terminal
escape sequences (which you can tweak by modifying the script).

Here it traces the example program, Code/Tcl/func_abc.tcl.

# tcl_syscolors.d -c './tclsh func_abc.tcl
Function A
  C    PID DELTA(us) TYPE     -- NAME
  0  16624         2 syscall  -> munmap
  0  16624        31 syscall  <- munmap
  0  16624        52 syscall  -> mmap
  0  16624        21 syscall  <- mmap
  0  16624        38 syscall  -> setcontext
  0  16624         8 syscall  <- setcontext
....
  0  16624        94 syscall  -> uname
  0  16624         8 syscall  <- uname
  0  16624        47 syscall  -> ioctl
  0  16624        35 syscall  <- ioctl
  0  16624        73 cmd      -> if
  0  16624        89 cmd        -> info
  0  16624        25 cmd        <- info
  0  16624        46 cmd        -> proc
  0  16624        11 syscall      -> brk
  0  16624         7 syscall      <- brk
  0  16624         7 syscall      -> brk
  0  16624         9 syscall      <- brk
  0  16624        23 cmd        <- proc
  0  16624         9 cmd      <- if
  0  16624        18 cmd      -> tclInit
  0  16624       223 proc       -> tclInit
....
  0  16624        10 proc       <- tclInit
  0  16624        17 cmd      <- tclInit
  0  16624        35 syscall  -> resolvepath
  0  16624        31 syscall  <- resolvepath
  0  16624        13 syscall  -> stat64
  0  16624        24 syscall  <- stat64
  0  16624         9 syscall  -> open64
  0  16624        23 syscall  <- open64
  0  16624         8 syscall  -> fcntl
  0  16624         7 syscall  <- fcntl
  0  16624         9 syscall  -> ioctl
  0  16624         7 syscall  <- ioctl
  0  16624        12 syscall  -> read
  0  16624        21 syscall  <- read
  0  16624        10 syscall  -> read
  0  16624         7 syscall  <- read
  0  16624         9 syscall  -> close
  0  16624         8 syscall  <- close
  0  16624        12 cmd      -> proc
  0  16624        11 cmd      <- proc
  0  16624        11 cmd      -> proc
  0  16624         9 cmd      <- proc
  0  16624        11 cmd      -> proc
  0  16624         9 cmd      <- proc
  0  16624         9 cmd      -> func_a
  0  16624        17 proc       -> func_a
  0  16624        10 cmd          -> puts
  0  16624        25 syscall        -> llseek
  0  16624         9 syscall        <- llseek
  0  16624         9 syscall        -> ioctl
  0  16624         6 syscall        <- ioctl
  0  16624        13 syscall        -> getsockname
  0  16624         8 syscall        <- getsockname
  0  16624        18 syscall        -> llseek
  0  16624         8 syscall        <- llseek
  0  16624         7 syscall        -> ioctl
  0  16624        86 syscall        <- ioctl
  0  16624       184 syscall        -> ioctl
  0  16624        17 syscall        <- ioctl
  0  16624        14 syscall        -> llseek
  0  16624         7 syscall        <- llseek
  0  16624         7 syscall        -> ioctl
  0  16624        13 syscall        <- ioctl
  0  16624         8 syscall        -> ioctl
  0  16624        12 syscall        <- ioctl
  0  16624        24 syscall        -> write
  0  16624       108 syscall        <- write
  0  16624        10 cmd          <- puts
  0  16624        11 cmd          -> after
  0  16624        23 syscall        -> pollsys
Function B
  0  16624   1009593 syscall        <- pollsys
  0  16624        24 cmd          <- after
  0  16624        23 cmd          -> func_b
  0  16624        37 proc           -> func_b
  0  16624        12 cmd              -> puts
  0  16624        17 syscall            -> write
  0  16624        74 syscall            <- write
  0  16624         8 cmd              <- puts
  0  16624         9 cmd              -> after
  0  16624        10 syscall            -> pollsys
Function C
  0  16624   1009748 syscall            <- pollsys
  0  16624        24 cmd              <- after
  0  16624        23 cmd              -> func_c
  0  16624        35 proc               -> func_c
  0  16624        12 cmd                  -> puts
  0  16624        17 syscall                -> write
  0  16624        75 syscall                <- write
  0  16624         8 cmd                  <- puts
  0  16624         9 cmd                  -> after
  0  16624        10 syscall                -> pollsys
  0  16624   1009831 syscall                <- pollsys
  0  16624        24 cmd                  <- after
  0  16624        23 proc               <- func_c
  0  16624        13 cmd              <- func_c
  0  16624         9 proc           <- func_b
  0  16624         8 cmd          <- func_b
  0  16624         8 proc       <- func_a
  0  16624         8 cmd      <- func_a
  0  16624        30 cmd      -> exit
....
  0  16624        68 syscall    -> rexit

DTrace Providers for other dynamic languages

Python
[L10 ] [L11 ]
Ruby
[L12 ] [L13 ] [L14 ] [L15 ] [L16 ]
Perl
[L17 ] [L18 ] [L19 ]
PHP
[L20 ] [L21 ]
Lua
[L22 ] [L23 ]
JavaScript
[L24 ] [L25 ] [L26 ]
sh
[L27 ] [L28 ]
Java
[L29 ] [L30 ]

Discussion

  • dgp asked on the chat about access to the full Tcl_GetReturnOptions dict from the proc-return probe.
  • sdeasey asks in [L31 ] about a tcl C interface to dtrace probes, and about systemtap support.

Ideas for additional probes:

obj-shimmer
unclear if possible to implement in an ObjType-independent fashion, might be able to hook into TclFreeIntRep macro, but that is only used by the core, not extensions...
event-entry, event-return
ideally would surround the call to evPtr->proc in Tcl_ServiceEvent, problem is how to do introspection from D at that level; also not every call to evPtr->proc actually ends up handling an event (depending on flags).
lock-*
for Tcl_MutexLock/Tcl_MutexUnlock in threaded Tcl, questionable usefulness given availability of lockstat provider?

Getting Your Feet Wet With DTrace, an article at http://sun.systemnews.com/ :

Jim Laurent uses an illuminating metaphor in writing about DTrace in his blog, where he likens the facility to a CAT scan that in turn allows users to see things as doctors, who heal the sick, rather than as coroners, who search for causes of death. His blog highlights a number of tools that can make using DTrace somewhat less formidable than starting with only the 400 page instruction manual.