Application startup time gives the first perception of the overall performance. When your app launches in 3 seconds, your user may think twice before he runs it again. Optimizing the startup time involves a lot of investigation effort, covering areas from fast transport/delivery to compact (minified) contents.
For a JavaScript-heavy web application, tracking down the startup process is not always fun. Worse, this often can’t even be automated so that it can be used to prevent future performance regression. Let’s be honest, how many of us have systematic and reliable startup time checks in the continuous integration system?
Recently I wrote about empirical run-time analysis of application complexity using Esprima code modification feature to insert a prolog in every function. In this blog post, I will show you how to apply the same technique to achieve automatic application startup logging. As a test case, we will work on a dummy page based on jQuery Mobile. The same approach should apply to other frameworks as well, including Sencha Touch, Ember.js, and many others.
First, we need a test page, which could be very simple. The most important part is to load the necessary libraries. I took an example HTML file from jQuery Mobile demo and simplified it. It loads both jQuery and jQuery Mobile, nothing else. With some filler text, the page looks like the following screen capture:
Next step is to apply automatic instrumentation to the library. Since jQuery Mobile requires jQuery, we need to handle both of them. A simple utility which runs via Node.js will apply the instrumentation, here is the code for our script trace.js.
var fs = require('fs'),
esprima = require('./esprima'),
filename = process.argv[2],
content;
function customTracer(functionInfo) {
var trace = 'TRACE.enterFunction(';
trace += ''' + functionInfo.name + '', ';
trace += ''' + filename + '', ';
trace += functionInfo.loc.start.line + ', ';
trace += 'arguments);n';
return trace;
}
content = fs.readFileSync(filename, 'utf-8');
content = esprima.modify(content, esprima.Tracer.FunctionEntrance(customTracer));
fs.writeFileSync(filename.replace(/.js$/, '.traced.js'), content);
More detailed info on Esprima’s Tracer.FunctionEntrance is available in the API reference.
Here is how I run it:
node trace.js jquery.js
node trace.js jquery.mobile.js
which will produce a new file jquery.traced.js, the instrumented version of the input file. If you open this, every time there is a function you will find an additional logging line. For example, the original fcamelCase function looks like:
// Used by jQuery.camelCase as callback to replace()
fcamelCase = function( all, letter ) {
return ( letter + "" ).toUpperCase();
},
Inside jquery.traced.js, it becomes something like:
// Used by jQuery.camelCase as callback to replace()
fcamelCase = function( all, letter ) {
TRACE.enterFunction('fcamelCase', 'jquery.js', 74, arguments);
return ( letter + "" ).toUpperCase();
},
Note the addition of TRACE.enterFunction line with its parameters of function name, source file name, line number, and actual arguments, respectively. Having this prolog is very powerful since now we can record every single function call, fully armed with all the necessary information on the invocation.
After I got both jquery.traced.js and jquery.mobile.traced.js, it’s time to have some fun. The test page was modified to use these two files inside the script elements. In addition, I also include tracer.js which is an implementation of the TRACE object to be called from every function. One possible simplistic implementation looks like:
var TRACE = {};
TRACE.enterFunction = function(name, sourceName, lineNumber, args) {
console.log(sourceName, lineNumber, name);
};
I do however have a slightly more complicated version which aligns the fields into a fixed column position. This is just small details, the principle remains the same.
Since all the function execution is logged to the console, you can retrieve everything if you use Firebug or Web Inspector while opening the above test page. However, personally I would recommend using PhantomJS, the headless WebKit. It is very easy to install, usually doesn’t take more than 5 minutes. Create a simple script load.js with the following contents:
var page = require('webpage').create(),
address;
if (phantom.args.length === ) {
phantom.exit();
} else {
address = phantom.args[];
page.onConsoleMessage = function (msg) {
console.log(msg);
};
page.open(address, function (status) {
setTimeout(function() {
phantom.exit();
}, 4000);
});
}
and now it’s a matter of launching our test page:
/path/to/phantomjs load.js http://yourserver/test.htm > log
Because load.js redirects all console messages to stdout, it can be conveniently captured. The extra 4 seconds in the script is to merely ensure that any pending processing is finished.
The file log contains all recorded function call, neatly organized in four columns: source file, line number, function name, and call arguments. The following shows the last 10 calls:
jquery.js 26 jQuery
jquery.js 103 init undefined, undefined, [object Object]
jquery.js 274 each (Function)
jquery.js 631 each [object Object], (Function), undefined
jquery.js 495 isFunction [object Object]
jquery.js 512 type [object Object]
jquery.mobile.js 1857 [Anonymous]
jquery.mobile.js 642 [Anonymous]
jquery.mobile.js 624 enableMouseBindings
jquery.mobile.js 620 disableTouchBindings
Guess how many function calls were there? 4640. Yes, I’m not kidding. Over four thousands calls were invoked just to display a rather simple page. Fortunately not every call is expensive, most of them is harmless. For a full log, take a look at gist.github.com/1823129 (warning: it’s very long).
Should you try to focus on minimizing the calls, it’s important to find out which functions are called the most. A simple magical spell using various Unix tools is all we need:
cut -c 1-55 log | sort | uniq -c | sort -rn | head -n 10
That conveniently finds the ten most invoked function calls, as shown here (surprisingly, everything is in the core jQuery library itself). The first column denotes the number of call made for the corresponding function.
379 jquery.js 512 type 279 jquery.js 1651 acceptData 226 jquery.js 103 init 215 jquery.js 1445 data 185 jquery.js 518 isPlainObject 170 jquery.js 5149 Sizzle.isXML 168 jquery.js 1646 _data 154 jquery.js 26 jQuery 152 jquery.js 495 isFunction 106 jquery.js 4892 Sizzle
If you just want to find out the most invoked function in jQuery Mobile, change the magic spell:
cut -c 1-55 log | grep 'mobile' | sort | uniq -c | sort -rn | head -n 10
which would yield the following:
66 jquery.mobile.js 1976 $.find 22 jquery.mobile.js 1988 $.find.matchesSelector 22 jquery.mobile.js 1920 $.fn.jqmData 22 jquery.mobile.js 1868 nsNormalize 14 jquery.mobile.js 1984 $.find.matches 13 jquery.mobile.js 297 [Anonymous] 12 jquery.mobile.js 990 [Anonymous] 12 jquery.mobile.js 91 $.widget.bridge 12 jquery.mobile.js 47 $.widget 11 jquery.mobile.js 295 [Anonymous]
Basically the above data shows that $.find in line 1976 is executed the most, 66 times.
It is clear that having the above call log does not magically let you optimize everything. However, it does give you some more data when analyzing the startup time performance. Even better, the entire steps are easily automated. For example, you could have a simple check in the continuous integration system which monitor the ten most called function, this facilitates triggering the early warning system whenever there is a large deviation from the baseline reference. Make the startup slightly faster in every iteration, surely you will reach the intended world domination someday.
Last but not least, if this blog post does not convince you of the combined power of Esprima and PhantomJS, I don’t know what else to say!