DTrace edit
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 [1], a port to FreeBSD is underway [2]. For more details on OS Support, see [3].Further Reading:- http://docs.sun.com/app/docs/doc/817-6223
- http://www.opensolaris.org/os/community/dtrace/
- http://www.sun.com/bigadmin/content/dtrace/
- http://www.genunix.org/wiki/index.php/DTrace_FAQ
- http://www.solarisinternals.com/wiki/index.php/DTrace_Topics
- http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_Intro
- http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_Internals
- http://blogs.sun.com/jonh/resource/DTraceAfterS10.pdf
- http://www.sun.com/bigadmin/jsp/descFile.jsp?url=descAll/learning_dtrace__pa - tutorial for learning dtrace
- http://developers.sun.com/solaris/articles/dtrace_tutorial.html
Tcl DTrace provider edit
DAS Tcl releases 8.4.16 and 8.5b1 introduce a Tcl DTrace provider, c.f. Patch 1793984 [4].This uses the DTrace USDT facility (user-land statically defined tracing) [5], and is-enabled probes [6] 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 [7].Probes
The following probes are made available by the tcl* provider (c.f. tclDTrace.d [8] 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 [9] 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:- http://bdgregg.blogspot.com/2007/10/dtracetoolkit-ver-099.html
- http://www.opensolaris.org/os/community/dtrace/dtracetoolkit/
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.dDTraceToolkit 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
- [10] [11]
- Ruby
- [12] [13] [14] [15] [16]
- Perl
- [17] [18] [19]
- PHP
- [20] [21]
- Lua
- [22] [23]
- JavaScript
- [24] [25] [26]
- sh
- [27] [28]
- Java
- [29] [30]
Discussion
- dgp asked on the chat about access to the full Tcl_GetReturnOptions dict from the proc-return probe.
- sdeasey asks in [31] 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.