I've recently been writing a
DTrace provider for JavaScript,
using the user statically defined tracing interface (USDT). The codename for this project
is Helper Monkey.
This was achieved by adding 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
The following is the source to clock.html, a simple website with
some 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. The probe arguments are still being designed, 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 we will use both the entry and return probes to trace the flow of the JavaScript,
with indentation as we enter and exit functions. The 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 thosands of lines.
The output can 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 tallys 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 5 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 trace object creation, we can also trace object destruction from the
garbage collector. The 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 5 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 our script created objects that were
not garbage collected, their count would continue increasing, 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 fore 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.
