[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 [http://www.apple.com/macosx/leopard/technology/unix.html], a port to [FreeBSD ]is underway [http://dtrace.what-creek.com/]. See [http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_OSes] for more details on OS Support. ''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 ---- ** Tcl DTrace provider ** [DAS] Tcl releases 8.4.16 and 8.5b1 introduce a Tcl DTrace provider, c.f. Patch 1793984 [http://sourceforge.net/support/tracker.php?aid=1793984]. This uses the DTrace USDT facility (user-land statically defined tracing) [http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_USDT], and 'is-enabled' probes [http://blogs.sun.com/ahl/entry/user_land_tracing_gets_better] to reduce the cost of probe-sites to a branch and a few noops when tracing is not enabled. The information available for tracing is similar to the existing 'TCL_COMPILE_DEBUG' and 'TCL_MEM_DEBUG' facilities, but with the big advantage that DTrace probes have essentially zero cost when not in use, so DTrace support can be enabled in production builds, with no performance penalty when not tracing. There are many other advantages, such as simultaneous tracing of all processes using Tcl on a system, integration with syscall tracing, control over exactly what & when to trace, stats collection via aggregations, etc. DTrace support is enabled via the '--enable-dtrace' configure option, it is disabled by default and will only enable if DTrace is present on the system. The following probes are made available by the 'tcl*' provider (c.f. tclDTrace.d [http://tcl.cvs.sourceforge.net/tcl/tcl/generic/tclDTrace.d?view=markup] 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'). 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 data collection facilities in DTrace. They allow powerful statistics collection in a lightweight & performant fashion. 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 === ---- ''[[ [DAS] 22/09/07 ]]'' [[ [Category Core] | [Category Internals] ]]