** 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 [http://www.apple.com/macosx/leopard/technology/unix.html], a
port to [FreeBSD] is underway [http://dtrace.what-creek.com/]. For more details
on OS Support, see
[http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_OSes].
** 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:''' **
* 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
[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 [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.
I gave a talk on ''Profiling and Debugging Tcl with DTrace'' at the
[7th European Tcl/Tk Users Meeting Conference], c.f. slides at
[http://www.eurotcl.org/2008/Download/Friday/EuroTcl2008-Steffen_DTrace.pdf].
----
*** Probes ***
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''. 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
[http://docs.sun.com/app/docs/doc/817-6223/chp-aggs?a=view] 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/
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: [http://blogs.sun.com/levon/entry/python_and_dtrace_in_build] [http://cvs.opensolaris.org/source/xref/jds/spec-files/trunk/patches/Python-07-dtrace.diff]
Ruby: [https://dtrace.joyent.com/projects/ruby-dtrace/wiki/Ruby+DTrace] [http://svn.joyent.com/opensource/dtrace/ruby/patches/ruby-dtrace-1.8.6.diff] [http://blogs.sun.com/bmc/entry/dtrace_and_ruby] [http://blogs.sun.com/bmc/entry/dtrace_on_rails] [http://blogs.sun.com/bmc/resource/ruby-1.8.2-dtrace-isenabled.diff]
Perl: [http://blogs.sun.com/alanbur/entry/dtrace_and_perl] [http://richdawe.livejournal.com/1090.html] [http://rich.phekda.org/perl-dtrace/perl-5.8.8-dtrace-20070720.patch]
PHP: [http://blogs.sun.com/bmc/entry/dtrace_and_php] [http://blogs.sun.com/bmc/entry/dtrace_and_php_demonstrated]
Lua: [http://www.maciel.org/luadtrace/index.lua] [http://www.maciel.org/luadtrace/luadtrace-1.0.1a.diff.gz]
JavaScript: [http://blogs.sun.com/brendan/entry/dtrace_meets_javascript] [http://www.opensolaris.org/os/project/mozilla-dtrace/JavaScript/] [http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_JavaScript]
sh: [http://www.opensolaris.org/os/community/dtrace/shells/sh.html] [http://www.opensolaris.org/os/community/dtrace/shells/sh-20070820.diffs.txt]
Java: [http://blogs.sun.com/kamg/entry/built_in_dtrace_probes_in] [http://www.solarisinternals.com/wiki/index.php/DTrace_Topics_Java]
----
*** Discussion ***
* [dgp] asked on the chat about access to the full ''Tcl_GetReturnOptions'' dict from the ''proc-return'' probe.
* '''sdeasey''' asks in [http://sourceforge.net/support/tracker.php?aid=1793984] 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.
<<categories>> Debugging | Internals | Mac