Using DTrace for javascript debug on OS X in firefox
This post aims at introducing the DTrace debugging tool in the scope of a javascript application. It won’t get too deep in the wide field of DTrace functions but I hope it will give you an overview of how DTrace can help to solve performance and debugging issues in your javascript applications.
Latest versions of Mozilla codebase had included a dtrace patch to enable javascript providers. Which is nice but unfortunately still not included in version pre-compiled for osx. So your first task is either- to compile the Mozilla code from source and enable dtrace provider by adding “—enable-dtrace” to the configure script
- get the binary I’ve compiled
hellmac:firefox vincent$ sudo dtrace -P 'javascript*' -l
ID PROVIDER MODULE FUNCTION NAME
19273 javascript1352 libmozjs.dylib js_Execute execute-done
19274 javascript1352 libmozjs.dylib jsdtrace_execute_done execute-done
19275 javascript1352 libmozjs.dylib js_Execute execute-start
19276 javascript1352 libmozjs.dylib jsdtrace_execute_start execute-start
19277 javascript1352 libmozjs.dylib js_Interpret function-args
19278 javascript1352 libmozjs.dylib jsdtrace_function_args function-args
19279 javascript1352 libmozjs.dylib js_Interpret function-entry
19280 javascript1352 libmozjs.dylib jsdtrace_function_entry function-entry
19281 javascript1352 libmozjs.dylib js_Interpret function-info
19282 javascript1352 libmozjs.dylib jsdtrace_function_info function-info
19283 javascript1352 libmozjs.dylib js_Interpret function-return
19284 javascript1352 libmozjs.dylib jsdtrace_function_return function-return
19285 javascript1352 libmozjs.dylib js_Interpret function-rval
19286 javascript1352 libmozjs.dylib jsdtrace_function_rval function-rval
19287 javascript1352 libmozjs.dylib js_NewObjectWithGivenProto object-create
19288 javascript1352 libmozjs.dylib jsdtrace_object_create object-create
19289 javascript1352 libmozjs.dylib js_NewObjectWithGivenProto object-create-done
19290 javascript1352 libmozjs.dylib jsdtrace_object_create_done object-create-done
19291 javascript1352 libmozjs.dylib js_NewObjectWithGivenProto object-create-start
19292 javascript1352 libmozjs.dylib jsdtrace_object_create_start object-create-start
19293 javascript1352 libmozjs.dylib js_FinalizeObject object-finalize
19294 javascript1352 libmozjs.dylib jsdtrace_object_finalize object-finalize
Which shows that you have 22 new probes
Ok let’s first start with a quick example: Christophe Porteneuve stated in Paris on Rails on his speech about prototype, that for repetitive operations on Elements using Enumerable functions, it was better to use pluck rather than collect. let’s see that on a (quite) real example:
1 <!DOCTYPE html PUBLIC "-//W3C//DTD HTML 4.01//EN">
2 <html>
3 <head>
4 <title>
5 Testing pluck
6 </title>
7 <script src="http://www.prototypejs.org/javascripts/prototype.js" type="text/javascript">
8 </script>
9 </head>
10 <body>
11 <script type="text/javascript">
12 //<![CDATA[
13 function pluck_me(){
14 return ['hello', 'world', 'this', 'is', 'nice'].pluck('length');
15 }
16 function collect_me(){
17 return ['hello', 'world', 'this', 'is', 'nice'].collect(function(s){
18 return s.length;
19 })
20 }
21 //]]>
22 </script>
23 <p>
24 <a href="#" onclick="javascript: pluck_me();">pluck!</a><br>
25 <a href="#" onclick="javascript: collect_me();">collect!</a>
26 </p>
27 </body>
28 </html>
29
Create the file and save it under pluck.html.
Let’s write a dtrace script (written in D) (adapted from scripts provided by SUN) to explore this statement:
#!/usr/sbin/dtrace -Zs
#pragma D option quiet
dtrace:::BEGIN
{
printf("Tracing... Hit Ctrl-C to end.\n");
}
javascript*:::function-entry
/basename(copyinstr(arg0))=="pluck.html#"/
{
self->depth++;
self->exclude[self->depth] = 0;
self->function[self->depth] = timestamp;
}
javascript*:::function-return
/self->function[self->depth] && basename(copyinstr(arg0))=="pluck.html#"/
{
this->elapsed_incl = timestamp - self->function[self->depth];
this->elapsed_excl = this->elapsed_incl - self->exclude[self->depth];
self->function[self->depth] = 0;
self->exclude[self->depth] = 0;
this->file = basename(copyinstr(arg0));
this->name = copyinstr(arg2);
@num[this->file, "func", this->name] = count();
@num["-", "total", "-"] = count();
@types_incl[this->file, "func", this->name] = sum(this->elapsed_incl);
@types_excl[this->file, "func", this->name] = sum(this->elapsed_excl);
@types_excl["-", "total", "-"] = sum(this->elapsed_excl);
self->depth--;
self->exclude[self->depth] += this->elapsed_incl;
}
dtrace:::END
{
normalize(@types_excl, 1000);
printf("\nExclusive function elapsed times (us),\n");
printf(" %-20s %-10s %-32s %8s\n", "FILE", "TYPE", "NAME", "TOTAL");
printa(" %-20.20s %-10s %-32s %@8d\n", @types_excl);
normalize(@types_incl, 1000);
printf("\nInclusive function elapsed times (us),\n");
printf(" %-20s %-10s %-32s %8s\n", "FILE", "TYPE", "NAME", "TOTAL");
printa(" %-20.20s %-10s %-32s %@8d\n", @types_incl);
}
Without explaining too much this script ( Sun’s wiki is fairly good)
this code instanciate four probes:
- the first one displays a message “Tracing… Hit Ctrl-C to end.”
- the second one: javascript*:::function-entry is being executed while entering in a function. It is setting the beginning time (self->function[self->depth] = timestamp;) and the stack depth of the function
- the third one: javascript*:::function-return is being executed while exiting the function . It computes the time spend in the function
- the last one: dtrace:::END displays the results computed earlier
Now let’s open our test page and first push the pluck! link, the results are the following;
hellmac:JavaScript vincent$ sudo ./pluck_vs_collect.d
Tracing... Hit Ctrl-C to end.
^C
Exclusive function elapsed times (us),
FILE TYPE NAME TOTAL
- total - 3509
pluck.html# func pluck_me 3509
Inclusive function elapsed times (us),
FILE TYPE NAME TOTAL
pluck.html# func pluck_me 6995
now with the collect! link:
hellmac:JavaScript vincent$ sudo ./js_calltime.d
Tracing... Hit Ctrl-C to end.
^C
Exclusive function elapsed times (us),
FILE TYPE NAME TOTAL
pluck.html# func <null> 1046
pluck.html# func collect_me 3347
- total - 4393
Inclusive function elapsed times (us),
FILE TYPE NAME TOTAL
pluck.html# func <null> 1909
pluck.html# func collect_me 9114
It appears that Christophe was right! While the functions pluck_me and collect_me take roughtly the same time 3347us vs 3509us whithout counting the time spend by the inner functions, the total time is way higher when summing inner functions: for collect 9114us than for pluck 6995us. (note that the anonymous function used in collect was also reported with null name)
This was just a little example of how dtrace can be usefull for debugging javascript. But Dtrace can go further, like tracing ajax calls, displaying stacks of functions calls.
example: the stack trace of prototype Element.toggle function (line numbers refers to the 1.5.2_pre0 version of prototype):
C TIME(us) FILE -- FUNC
1 15910175958 prototype.js:3231 -> toggle
1 15910175995 prototype.js:3231 -> toggle
1 15910176043 prototype.js:1342 -> $
1 15910176066 prototype.js:1342 -> $
1 15910176114 prototype.js:1279 -> getElementById
1 15910176139 prototype.js:1279 -> getElementById
1 15910176209 prototype.js:1279 <- getElementById
1 15910176237 prototype.js:1279 <- getElementById
1 15910176270 prototype.js:1279 -> extend
1 15910176295 prototype.js:1279 -> extend
1 15910176333 prototype.js:31 <- extend
1 15910176356 prototype.js:31 <- extend
1 15910176384 prototype.js:31 <- $
1 15910176408 prototype.js:31 <- $
1 15910176440 prototype.js:31 -> visible
1 15910176464 prototype.js:31 -> visible
1 15910176502 prototype.js:1338 -> $
1 15910176525 prototype.js:1338 -> $
1 15910176562 prototype.js:1279 -> extend
1 15910176590 prototype.js:1279 -> extend
1 15910176632 prototype.js:31 <- extend
1 15910176654 prototype.js:31 <- extend
1 15910176682 prototype.js:31 <- $
1 15910176705 prototype.js:31 <- $
1 15910176776 prototype.js:31 <- visible
1 15910176801 prototype.js:31 <- visible
1 15910176832 prototype.js:31 -> <null>
1 15910176856 prototype.js:31 -> <null>
1 15910176893 prototype.js:1348 -> $
1 15910176916 prototype.js:1348 -> $
1 15910176953 prototype.js:1279 -> extend
1 15910176978 prototype.js:1279 -> extend
1 15910177016 prototype.js:31 <- extend
1 15910177039 prototype.js:31 <- extend
1 15910177067 prototype.js:31 <- $
1 15910177089 prototype.js:31 <- $
1 15910177172 prototype.js:31 <- <null>
1 15910177197 prototype.js:31 <- <null>
1 15910177227 prototype.js:31 <- toggle
1 15910177250 prototype.js:31 <- toggle
And DTrace can not only trace javascript but almost every language running on osx, ie: ruby and rails. (we’ll see that in another post)