I originally posted this at http://blogs.sun.com/brendan/entry/dtrace_meets_javascript.
I've recently been developing a DTrace provider for JavaScript, using the User Statically Defined Tracing interface (USDT). The codename for this project is Helper Monkey.
My DTrace provider adds USDT probes to the Spider Monkey JavaScript Engine, which is used by the Mozilla family of browsers including Firefox. Since Solaris Nevada ships with Firefox, the DTrace JavaScript provider can be used by running a script that preloads a DTrace enhanced version of libmozjs.so, and runs the shipped version of Firefox.
So far I've added several probes to observe JavaScript function calls, object creation and destruction (garbage collection), and script execution. I've also written several DTrace scripts to report probe activity. While I have more probes planned, this provider has already reached a point where it may be useful to people, and so we are making the first (very alpha) version available.
DTrace meeting JavaScript may sound like an odd combination, especially if you grew impressions of JavaScript when it was first used to make buttons change colour, or to make temperature converters. But now JavaScript, as part of AJAX, is driving new and serious Web 2.0 applications. Google Maps is one of what may be many new (and very cool) applications to embrace these technologies.
Ways already exist to fetch debug information from JavaScript, such as running a debug build of the browser. However, with DTrace people can run a normal browser build, with USDT probes, and dynamically enable debug information as needed. Without stopping or starting the browser. The following demonstrations should convey some of the advantages of DTracing JavaScript.
JavaScript: clock.html
This is the source to clock.html, a website with JavaScript code to print a clock with the format HH:MM:SS:
<HTML>
<HEAD>
<TITLE>Clock, JavaScript</TITLE>
<SCRIPT type="text/javascript">
function padZero(i)
{
if (i < 10) return "0" + i
return i
}
function startTime()
{
var now = new Date
var time = padZero(now.getHours()) + ":" +
padZero(now.getMinutes()) + ":" +
padZero(now.getSeconds());
document.getElementById('clock').innerHTML = "time: " + time + "<br>"
var timeout = setTimeout('startTime()', 1000)
}
</SCRIPT>
</HEAD>
<BODY onload="startTime()">
<DIV id="clock"></DIV>
</BODY>
</HTML>
While this clock is running in my browser, the following DTrace scripts are used for analysis.
DTrace/JavaScript: Function Calls
The js_funccalls.d DTrace script counts JavaScript function calls as it is running. Here I run it for 9 seconds then hit Ctrl-C:
# ./js_funccalls.d Tracing... Hit Ctrl-C to end. ^C FILE FUNC CALLS clock.html getElementById 9 clock.html getHours 9 clock.html getMinutes 9 clock.html getSeconds 9 clock.html setTimeout 9 clock.html startTime 9 clock.html padZero 27
The FUNC column lists JavaScript functions, and the FILE column is where they were called from (their context). DTrace captured 9 updates to the clock, with most of the functions called 9 times. padZero() was called 27 times, as it is called three times during each clock update.
The source to js_funccalls.d is straightforward:
#!/usr/sbin/dtrace -Zs
/*
* js_funccalls.d - measure JavaScript function calls using DTrace.
* Written for the Solaris Nevada DTrace JavaScript provider.
*
* 12-Sep-2006, ver 0.90
*
* USAGE: js_calls.d # hit Ctrl-C to end
*
* FIELDS:
* FILE Filename that contained the function
* FUNC JavaScript function name
* CALLS Function calls during this sample
*/
#pragma D option quiet
dtrace:::BEGIN
{
printf("Tracing... Hit Ctrl-C to end.\n");
}
javascript*:::function-entry
{
@funcs[basename(copyinstr(arg0)), copyinstr(arg2)] = count();
}
dtrace:::END
{
printf(" %-32s %-36s %8s\n", "FILE", "FUNC", "CALLS");
printa(" %-32s %-36s %@8d\n", @funcs);
}
The probe javascript*:::function-entry fires when a JavaScript function begins to execute. There is another probe, javascript*:::function-return for when the function completes. I'm still designing the probe arguments: for now, arg0 is a the file pathname, arg1 is a classname (if available), and arg2 is the function name.
DTrace/JavaScript: Function Flow
Now I will use both the entry and return probes to trace the flow of the JavaScript, with indentation as we enter and exit functions. My js_funcflow.d script does this.
# ./js_funcflow.d C TIME FILE -- FUNC 1 2006 Sep 18 12:03:28 clock.html -> startTime 1 2006 Sep 18 12:03:28 clock.html -> getHours 1 2006 Sep 18 12:03:28 clock.html <- getHours 1 2006 Sep 18 12:03:28 clock.html -> padZero 1 2006 Sep 18 12:03:28 clock.html <- padZero 1 2006 Sep 18 12:03:28 clock.html -> getMinutes 1 2006 Sep 18 12:03:28 clock.html <- getMinutes 1 2006 Sep 18 12:03:28 clock.html -> padZero 1 2006 Sep 18 12:03:28 clock.html <- padZero 1 2006 Sep 18 12:03:28 clock.html -> getSeconds 1 2006 Sep 18 12:03:28 clock.html <- getSeconds 1 2006 Sep 18 12:03:28 clock.html -> padZero 1 2006 Sep 18 12:03:28 clock.html <- padZero 1 2006 Sep 18 12:03:28 clock.html -> getElementById 1 2006 Sep 18 12:03:28 clock.html <- getElementById 1 2006 Sep 18 12:03:28 clock.html -> setTimeout 1 2006 Sep 18 12:03:28 clock.html <- setTimeout 1 2006 Sep 18 12:03:28 clock.html <- startTime ...
The above output is repeated every second, as the clock is updated. We can see that each of the functions is called within startTime, which was called by the timeout. The arrows denote as we enter (->) or leave (<-) functions.
While this output makes for a great demo, it may not be that practical for larger JavaScript applications, where the output can run into thousands of lines, making it difficult to browse. That output my also be shuffled on multi-CPU clients if the JavaScript engine skips between CPUs; for this reason the first column has been printed – C for CPU-id – if this changes then the output may be out of order.
DTrace/JavaScript: Object Creation
The following DTrace script tallies newly created objects:
# ./js_objnew.d Tracing... Hit Ctrl-C to end. ^C FILE LINENO CLASS COUNT clock.html 13 Date 5
I ran the script for five seconds then hit Ctrl-C. The output shows that five Date objects were created, caused by line 13 of clock.html. If you count to line 13 on clock.html listed earlier, you will see that it was "var now = new Date". Great!
DTrace/JavaScript: Object Leakage
Apart from tracing object creation, we can also trace object destruction from the garbage collector. My js_objgcx.d script does this, providing tallys of the objects in memory and their origin, every five seconds:
# ./js_objgcx.d Tracing... Hit Ctrl-C to end. FILE LINENO CLASS TOTAL clock.html 13 Date 5 FILE LINENO CLASS TOTAL clock.html 13 Date 10 FILE LINENO CLASS TOTAL clock.html 13 Date 15 FILE LINENO CLASS TOTAL clock.html 13 Date 20 ...
As objects are created, their tally is increased; as they are garbage collected, their tally is decreased.
Every five seconds we find that there is an additional five Date objects in memory, and another summary is printed out. At the end of this output there were 20 Date objects in memory. If I were to leave this running for a long time, eventually the garbage collector would kick in and trim the number down (to, say, 1000), which we could see happen in our output. For more complex JavaScript which creates objects faster, this will naturally happen sooner.
If the JavaScript program created objects that were not garbage collected, their count would continue increasing, as seen using js_objgcx.d, and the browser would consume more and more RAM.
DTrace/JavaScript: Function Time
Since we can trace function entry and return, we can also measure the elapsed time for functions to execute. This can be useful to identify if there is a slow function whose code could be improved. The js_functime.d script provides several experimental metrics for function calls:
# ./js_functime.d
Tracing... Hit Ctrl-C to end.
^C
ELAPSED TIME DISTRIBUTION,
getSeconds
value ------------- Distribution ------------- count
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 12
16384 | 0
padZero
value ------------- Distribution ------------- count
2048 | 0
4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@ 23
8192 |@@@@@@@@@@@@@@ 13
16384 | 0
getElementById
value ------------- Distribution ------------- count
16384 | 0
32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 12
65536 | 0
getHours
value ------------- Distribution ------------- count
16384 | 0
32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 12
65536 | 0
getMinutes
value ------------- Distribution ------------- count
16384 | 0
32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 12
65536 | 0
setTimeout
value ------------- Distribution ------------- count
16384 | 0
32768 |@@@@@@@@@@ 3
65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 9
131072 | 0
startTime
value ------------- Distribution ------------- count
524288 | 0
1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 12
2097152 | 0
___ OVERLAP TIMES: ___ ______ ELAPSED _____
FILE FUNCTION COUNT AVG(us) SUM(us)
clock.html getSeconds 12 8 104
clock.html padZero 36 7 275
clock.html getMinutes 12 45 548
clock.html getElementById 12 53 640
clock.html getHours 12 59 714
clock.html setTimeout 12 67 807
clock.html startTime 12 1219 14637
These function times are overlapping, such that the time for startTime() contains both the startTime() instructions, and any sub functions called, such as padZero(), etc.
What I found interesting from the output was that getHours() (average 59 us) was much slower than getSeconds() (average 8 us). Wouldn't they have equivalent times? Some digging with DTrace shows what other userland library functions occured during getHours() and getSeconds():
getHours()
DTracing PID: 278562, "firefox-bin" CPU FUNCTION 0 -> js_Interpret getHours 0 -> js_Invoke libmozjs.so.1 0 -> JS_GetPrivate libmozjs.so.1 0 <- JS_GetPrivate libmozjs.so.1 0 -> js_ComputeThis libmozjs.so.1 0 <- js_ComputeThis libmozjs.so.1 0 -> date_getHours libmozjs.so.1 0 -> date_getProlog libmozjs.so.1 0 -> JS_InstanceOf libmozjs.so.1 0 <- JS_InstanceOf libmozjs.so.1 0 <- date_getProlog libmozjs.so.1 0 -> DaylightSavingTA libmozjs.so.1 0 -> PRMJ_DSTOffset libmozjs.so.1 0 -> jsll_udivmod libmozjs.so.1 0 -> CountLeadingZeros libmozjs.so.1 0 <- CountLeadingZeros libmozjs.so.1 0 -> norm_udivmod32 libmozjs.so.1 0 <- norm_udivmod32 libmozjs.so.1 0 <- jsll_udivmod libmozjs.so.1 0 -> PRMJ_basetime libmozjs.so.1 0 -> PRMJ_ToExtendedTime libmozjs.so.1 0 -> PRMJ_LocalGMTDifference libmozjs.so.1 0 -> memset libc.so.1 0 <- memset libc.so.1 0 -> mktime libc.so.1 0 -> ___errno libc.so.1 0 <- ___errno libc.so.1 0 -> getsystemTZ libc.so.1 0 -> assert_no_libc_locks_held libc.so.1 0 <- assert_no_libc_locks_held libc.so.1 0 -> getenv libc.so.1 0 -> findenv libc.so.1 ... [175 lines in total]
getSeconds()
DTracing PID: 278562, "firefox-bin" CPU FUNCTION 0 -> js_Interpret getSeconds 0 -> js_Invoke libmozjs.so.1 0 -> JS_GetPrivate libmozjs.so.1 0 <- JS_GetPrivate libmozjs.so.1 0 -> js_ComputeThis libmozjs.so.1 0 <- js_ComputeThis libmozjs.so.1 0 -> date_getUTCSeconds libmozjs.so.1 0 -> date_getProlog libmozjs.so.1 0 -> JS_InstanceOf libmozjs.so.1 0 <- JS_InstanceOf libmozjs.so.1 0 <- date_getProlog libmozjs.so.1 0 -> SecFromTime libmozjs.so.1 0 -> floor libm.so.2 0 <- floor libm.so.2 0 -> fmod libm.so.2 0 <- fmod libm.so.2 0 <- SecFromTime libmozjs.so.1 0 -> js_NewNumberValue libmozjs.so.1 0 <- js_NewNumberValue libmozjs.so.1 0 <- date_getUTCSeconds libmozjs.so.1 0 -> PR_AtomicIncrement libnspr4.so 0 <- PR_AtomicIncrement libnspr4.so 0 -> memset libc.so.1 0 <- memset libc.so.1 0 <- js_Invoke libmozjs.so.1 0 -> JS_GetPrivate libmozjs.so.1 0 <- JS_GetPrivate libmozjs.so.1 0 -> JS_GetStringBytes libmozjs.so.1 0 -> js_GetStringBytes libmozjs.so.1 0 -> PR_Lock libnspr4.so 0 -> mutex_lock libc.so.1 ... [59 lines in total]
Tracing getSeconds() produced 59 lines of output (from about 28 function calls), however, getHours() produced 175 lines of output (from about 86 function calls). The output has been trimmed, but enough has been included to see the difference: getHours() looks up the timezone, getSeconds() does not!
Probes and Arguments so far
- javascript*:::function-entry (filename, classname, funcname)
- javascript*:::function-return (filename, classname, funcname)
- javascript*:::object-create-start (filename, classname)
- javascript*:::object-create (filename, classname, *object, lineno)
- javascript*:::object-create-done (filename, classname)
- javascript*:::object-finalize (NULL, classname, *object)
- javascript*:::execute-start (filename, lineno)
- javascript*:::execute-done (filename, lineno)
More probes will be added, and the arguments are likely to change (improve).
What's next
The DTrace scripts, the modified Spider Monkey source (for Firefox 1.5.0.4), and a precompiled Firefox 1.5.0.4 libmozjs.so for Solaris Nevada x86, are available in this tar file. This is very much an alpha release for the super-keen (you'll need the latest Solaris Nevada at least, and compilation skills); it even contains code comment tags for debugging that will be dropped ("BDG"). I'll be spending time finding out how best deliver this, such as making it easier for people to get running, and asking the Mozilla folks for help on how best to distrubite it.