Index: dtrace/README =================================================================== diff -u -rb14118b7068e3c1e903b9a516eef0c86101b24d9 -rcbd6b858b9324c125b8b6aad66c85d3482bb8bd4 --- dtrace/README (.../README) (revision b14118b7068e3c1e903b9a516eef0c86101b24d9) +++ dtrace/README (.../README) (revision cbd6b858b9324c125b8b6aad66c85d3482bb8bd4) @@ -1,15 +1,109 @@ +DTrace provider for the Next Scripting Language -Run the script e.g. via the following command: +This is an implementation of a DTrace provider for the Next Scripting +Language (nsf). The nsf provider is designed to be used with and +without the DTrace support for Tcl. Therefore, nsf can be configured +with --enable-trace also in cases where Tcl was compiled without it. +To enable DTrace, run configure with the flag --enable-dtrace. The +DTrace support for nsf was developed under Mac OS X, other platforms +might require some fine tuning to get it running. Please report +improvements back to the nsf developers. + +Once DTrace support is compiled into nsf, one can run D scripts like +in the following example: + sudo dtrace -q -F -s dtrace/timestamps.d -c "./nxsh tests/object-system.test" -Hints: +DTrace requires normally that dtrace is run with root permissions. In +case the provided sample scrips in the dtrace directory don't work the +following hints might help: * Make sure that a "package require nx" works for root as well - (install nx, or provide a TCLLIBPATH, etc.). + (install nx, or provide a TCLLIBPATH, etc.). You might want + to add e.g. the following line + set auto_path [concat . $auto_path] + to the begin of the nxsh script * If dtrace compliation fails (e.g. "... nsf*:::method-entry does not match any probes", start an nxsh in a different window to make the - probes known to the kernel. + nsf provider and the probes known to the kernel. --gustaf neumann \ No newline at end of file +-gustaf neumann + +Examples + +% sudo dtrace -arch x86_64 -x bufsize=20m -F -s dtrace/execution-flow.d -c "./nxsh dtrace/sample.tcl" 2>&1 + +dtrace: script 'dtrace/execution-flow.d' matched 8 probes +dtrace: pid 65393 has exited +CPU FUNCTION + 0 -> MethodDispatchCsc ::nx::Object ::nx::Class.create (2) + 0 -> MethodDispatchCsc ::o ::nx::Object.public (4) + 0 -> MethodDispatchCsc ::o ::nx::Object.method (3) + 0 -> MethodDispatchCsc ::o ::nx::Object.__resolve_method_path (2) + 0 <- ObjectDispatch ::o ::nx::Object.__resolve_method_path -> 0 + 0 -> MethodDispatchCsc ::o ::nx::Object.__default_method_call_protection (0) + 0 <- ObjectDispatch ::o ::nx::Object.__default_method_call_protection -> 0 + 0 <- ObjectDispatch ::o ::nx::Object.method -> 0 + 0 <- ObjectDispatch ::o ::nx::Object.public -> 0 + 0 -> MethodDispatchCsc ::o ::nx::Object.init (0) + 0 <- ObjectDispatch ::o ::nx::Object.init -> 0 + 0 <- ObjectDispatch ::nx::Object ::nx::Class.create -> 0 + 0 -> MethodDispatchCsc ::o ::o.foo (2) + 0 -> MethodDispatchCsc ::o ::o.::incr (2) + 0 <- ObjectDispatch ::o ::o.::incr -> 0 + 0 <- ObjectDispatch ::o ::o.foo -> 0 + +% sudo dtrace -arch x86_64 -x bufsize=20m -F -s dtrace/execution-flow-args.d -c "./nxsh dtrace/sample.tcl" 2>&1 +dtrace: script 'dtrace/execution-flow-args.d' matched 8 probes +dtrace: pid 65419 has exited + +CPU FUNCTION + 1 -> MethodDispatchCsc ::nx::Object ::nx::Class.create (2) o + :public method foo {x y} { + [self] ::incr x + 1 -> MethodDispatchCsc ::o ::nx::Object.public (4) method foo + 1 -> MethodDispatchCsc ::o ::nx::Object.method (3) foo x y + 1 -> MethodDispatchCsc ::o ::nx::Object.__resolve_method_path (2) -per-object foo + 1 <- ObjectDispatch ::o ::nx::Object.__resolve_method_path -> 0 + 1 -> MethodDispatchCsc ::o ::nx::Object.__default_method_call_protection (0) + 1 <- ObjectDispatch ::o ::nx::Object.__default_method_call_protection -> 0 + 1 <- ObjectDispatch ::o ::nx::Object.method -> 0 + 1 <- ObjectDispatch ::o ::nx::Object.public -> 0 + 1 -> MethodDispatchCsc ::o ::nx::Object.init (0) + 1 <- ObjectDispatch ::o ::nx::Object.init -> 0 + 1 <- ObjectDispatch ::nx::Object ::nx::Class.create -> 0 + 1 -> MethodDispatchCsc ::o ::o.foo (2) 1 2 + 1 -> MethodDispatchCsc ::o ::o.::incr (2) x 1 + 1 <- ObjectDispatch ::o ::o.::incr -> 0 + 1 <- ObjectDispatch ::o ::o.foo -> 0 + + +% sudo dtrace F -s dtrace/timestamps.d -c "./nxsh tests/object-system.test" 2>&1 +CPU FUNCTION + 0 | :END +::C ::C class = 4249 +::M ::M class = 4347 +::o ::o class = 4435 +::m2 ::m2 class = 4444 +::M2 ::M2 class = 4462 +::C0 ::C0 class = 4501 +::c1 ::c1 class = 4611 +.... + +% sudo dtrace -F -s dtrace/timestamps-q.d -c "./nxsh tests/object-system.test" 2>&1 +.... + ::nx::Object info + value ------------- Distribution ------------- count + 4096 | 0 + 8192 |@@@@@@@@@@@@@@@@@@@@@@@@@ 16 + 16384 |@@@@@@@@@@@@@@@ 10 + 32768 | 0 + + ::nx::Object objectparameter + value ------------- Distribution ------------- count + 32768 | 0 + 65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4 + 131072 |@@@@@@@@ 1 + 262144 | 0 \ No newline at end of file Index: dtrace/execution-flow-args.d =================================================================== diff -u --- dtrace/execution-flow-args.d (revision 0) +++ dtrace/execution-flow-args.d (revision cbd6b858b9324c125b8b6aad66c85d3482bb8bd4) @@ -0,0 +1,100 @@ +/* + * Execution flow trace with arguments + * + * Display execution flow between + * ::nsf::configure dtrace on + * and + * ::nsf::configure dtrace off + * + * Since this D script accesses the C data structures it is sensitive + * to the representation sizes of the data structures (e.g. pointers). + * Make sure to call the script with the appropriate architecture flag + * on Mac OS X, on SunOS, there is apparently a -32 or -64 flag. + * + * Example: + * + * sudo dtrace -arch x86_64 -x bufsize=20m -F -s dtrace/execution-flow-args.d \ + * -c "./nxsh dtrace/sample.tcl" + * + * -gustaf neumann + */ + +enum {maxstrlen = 50}; + +/* + * Needed data structures to access the content of Tcl_Objs. + */ +typedef struct Tcl_Obj Tcl_Obj; + +typedef struct Tcl_ObjType { + char *name; + void *freeIntRepProc; + void *dupIntRepProc; + void *updateStringProc; + void *setFromAnyProc; +} Tcl_ObjType; + +struct Tcl_Obj { + int refCount; + char *bytes; + int length; + Tcl_ObjType *typePtr; + union { + long longValue; + double doubleValue; + void *otherValuePtr; + int64_t wideValue; + struct { + void *ptr1; + void *ptr2; + } twoPtrValue; + struct { + void *ptr; + unsigned long value; + } ptrAndLongRep; + } internalRep; +}; + +/* + * Handling "nsf::configure dtrace on|off". + */ +nsf*:::configure-probe /!self->tracing && copyinstr(arg0) == "dtrace" / { + self->tracing = (arg1 && copyinstr(arg1) == "on") ? 1 : 0; +} + +nsf*:::configure-probe /self->tracing && copyinstr(arg0) == "dtrace" / { + self->tracing = (arg1 && copyinstr(arg1) == "off") ? 0 : 1; +} + +/* + * Output object, class, method, number of arguments and first two + * arguments upon method invocation. + */ +nsf*:::method-entry /self->tracing/ { + + this->objv = arg3 ? ((Tcl_Obj**)copyin((user_addr_t)((Tcl_Obj**)arg4), + sizeof(Tcl_Obj*) * arg3)) : NULL; + + this->i = 0; + this->o = arg3 > this->i && *(this->objv + this->i) ? + (Tcl_Obj*)copyin((user_addr_t)*(this->objv + 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 = arg3 > this->i && *(this->objv + this->i) ? + (Tcl_Obj*)copyin((user_addr_t)*(this->objv + 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 %s.%s (%d) %s %s", + copyinstr(arg0), copyinstr(arg1), copyinstr(arg2), arg3, + this->s0, this->s1); +} + +/* + * Output object, class, method and return code upon method return. + */ +nsf*:::method-return /self->tracing/ { + printf("%s %s.%s -> %d", copyinstr(arg0), copyinstr(arg1), copyinstr(arg2), arg3); +} Index: dtrace/execution-flow.d =================================================================== diff -u -rb14118b7068e3c1e903b9a516eef0c86101b24d9 -rcbd6b858b9324c125b8b6aad66c85d3482bb8bd4 --- dtrace/execution-flow.d (.../execution-flow.d) (revision b14118b7068e3c1e903b9a516eef0c86101b24d9) +++ dtrace/execution-flow.d (.../execution-flow.d) (revision cbd6b858b9324c125b8b6aad66c85d3482bb8bd4) @@ -1,9 +1,34 @@ -nsf*:::method-entry -{ - printf("%s %s.%s\n", copyinstr(arg0), copyinstr(arg1), copyinstr(arg2)); +/* + * Execution flow trace without arguments + * + * Display execution flow between + * ::nsf::configure dtrace on + * and + * ::nsf::configure dtrace off + * + */ + +nsf*:::configure-probe /!self->tracing && copyinstr(arg0) == "dtrace" / { + self->tracing = (arg1 && copyinstr(arg1) == "on") ? 1 : 0; } -nsf*:::method-return -{ - printf("%s %s.%s\n", copyinstr(arg0), copyinstr(arg1), copyinstr(arg2)); -} \ No newline at end of file +nsf*:::configure-probe /self->tracing && copyinstr(arg0) == "dtrace" / { + self->tracing = (arg1 && copyinstr(arg1) == "off") ? 0 : 1; +} + +/* + * Output object, class, method and number of arguments upon method + * invocation. + */ + +nsf*:::method-entry /self->tracing/ { + printf("%s %s.%s (%d)", + copyinstr(arg0), copyinstr(arg1), copyinstr(arg2), arg3); +} + +/* + * Output object, class, method and return code upon method return. + */ +nsf*:::method-return /self->tracing/ { + printf("%s %s.%s -> %d", copyinstr(arg0), copyinstr(arg1), copyinstr(arg2), arg3); +} Index: dtrace/sample.tcl =================================================================== diff -u --- dtrace/sample.tcl (revision 0) +++ dtrace/sample.tcl (revision cbd6b858b9324c125b8b6aad66c85d3482bb8bd4) @@ -0,0 +1,13 @@ +package require nx + +::nsf::configure dtrace on + +nx::Object create o { + :public method foo {x y} { + [self] ::incr x 1 + return [expr {$x + $y}] + } +} +o foo 1 2 + +::nsf::configure dtrace off Index: dtrace/timestamps-q.d =================================================================== diff -u -rb14118b7068e3c1e903b9a516eef0c86101b24d9 -rcbd6b858b9324c125b8b6aad66c85d3482bb8bd4 --- dtrace/timestamps-q.d (.../timestamps-q.d) (revision b14118b7068e3c1e903b9a516eef0c86101b24d9) +++ dtrace/timestamps-q.d (.../timestamps-q.d) (revision cbd6b858b9324c125b8b6aad66c85d3482bb8bd4) @@ -1,12 +1,26 @@ -nsf*:::method-entry -/copyinstr(arg1) == "::nx::Object"/ -{ +/* + * Quantize time between method-entry and method-returns for calls on ::nx::Object + * + * Display execution flow between + * ::nsf::configure dtrace on + * and + * ::nsf::configure dtrace off + * + */ + +nsf*:::configure-probe /!self->tracing && copyinstr(arg0) == "dtrace" / { + self->tracing = (arg1 && copyinstr(arg1) == "on") ? 1 : 0; +} + +nsf*:::configure-probe /self->tracing && copyinstr(arg0) == "dtrace" / { + self->tracing = (arg1 && copyinstr(arg1) == "off") ? 0 : 1; +} + +nsf*:::method-entry /self->tracing && copyinstr(arg1) == "::nx::Object"/ { self->start = timestamp; } -nsf*:::method-return -/copyinstr(arg1) == "::nx::Object" && self->start/ -{ +nsf*:::method-return /self->tracing && copyinstr(arg1) == "::nx::Object" && self->start/ { @[copyinstr(arg1), copyinstr(arg2)] = quantize(timestamp - self->start); self->start = 0; -} \ No newline at end of file +} Index: dtrace/timestamps.d =================================================================== diff -u -rb14118b7068e3c1e903b9a516eef0c86101b24d9 -rcbd6b858b9324c125b8b6aad66c85d3482bb8bd4 --- dtrace/timestamps.d (.../timestamps.d) (revision b14118b7068e3c1e903b9a516eef0c86101b24d9) +++ dtrace/timestamps.d (.../timestamps.d) (revision cbd6b858b9324c125b8b6aad66c85d3482bb8bd4) @@ -1,11 +1,30 @@ -nsf*:::method-entry -{ +/* + * Measure time btween method-entry and method-returns + * + * Display execution flow between + * ::nsf::configure dtrace on + * and + * ::nsf::configure dtrace off + * + */ + +nsf*:::configure-probe /!self->tracing && copyinstr(arg0) == "dtrace" / { + self->tracing = (arg1 && copyinstr(arg1) == "on") ? 1 : 0; +} + +nsf*:::configure-probe /self->tracing && copyinstr(arg0) == "dtrace" / { + self->tracing = (arg1 && copyinstr(arg1) == "off") ? 0 : 1; +} + +nsf*:::method-entry /self->tracing/ { self->start = timestamp; } -nsf*:::method-return -/self->start/ -{ +nsf*:::method-return /self->tracing && self->start/ { @[copyinstr(arg0), copyinstr(arg1), copyinstr(arg2)] = avg(timestamp - self->start); self->start = 0; -} \ No newline at end of file +} + +END { + printa("\n%-35s %-35s %-40s = %@d", @); +}