ariya.io About Collections Archives

Tracking JavaScript execution during startup

6 min read

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!

Related posts:

♡ this article? Explore more, check the archives, or follow me Twitter.

Share this on Twitter Facebook Google+

comments powered by Disqus