.

Tags:

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 === 0) {
    phantom.exit();
} else {
    address = phantom.args[0];
    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!

  • http://twitter.com/lazywithclass Alberto Zaccagni

    Lots of interesting info, for sure there’s place for other use cases!

  • http://twitter.com/lazywithclass Alberto Zaccagni

    Lots of interesting info, for sure there’s place for other use cases!

  • Dave Methvin


    (surprisingly, everything is in the core jQuery library itself)

    Actually, not surprising since we’re just talking about number of function calls. Most jQuery Mobile functions probably make more than one call into jQuery core, so the counts are higher. The time spent in the function is a better indicator of bottlenecks, but of course that’s harder to get and requires a real browser to take rendering time into account. So as an automated method of sanity-checking performance (and performance regressions), I agree this is pretty darned good.

  • Dave Methvin


    (surprisingly, everything is in the core jQuery library itself)

    Actually, not surprising since we’re just talking about number of function calls. Most jQuery Mobile functions probably make more than one call into jQuery core, so the counts are higher. The time spent in the function is a better indicator of bottlenecks, but of course that’s harder to get and requires a real browser to take rendering time into account. So as an automated method of sanity-checking performance (and performance regressions), I agree this is pretty darned good.

  • Russ Sherk

    Is there a difference between this and Google Chrome -> f12 -> profiles (start cpu profile and hit refresh)? Not trying to knock your efforts.  It is a pretty decent starting technique.

    In my experience, it has been worth while to look at the whole system to find out where the slowdown is occurring before instrumenting and profiling.  Luckily there are some tools that give you the big picture very quickly. For example: Google Speed Tracer and Yahoo! Yslow are good tools.  They will tell you about other important areas to make improvements: number of resources loaded (this can have a major impact on speed), file sizes, summaries of problem areas.  

    Here is a big ol list of tools for overall optimization tools: http://code.google.com/speed/tools.html

    Anyhow, good work and a good read.  Thanks!

    • http://ariya.ofilabs.com/ Ariya Hidayat

      I’m pretty familiar with a lot of different web performance analysis tools. The approaches you mentioned above can’t be controlled programmatically, and thus can’t be automated as part of the smoke tests in the continuous integration systems.

      • Russ Sherk

        I know I’m gonna sound like a jerk but: http://code.google.com/p/speedtracer/wiki/HeadlessExtension.  Also googling ‘[your favourite performance analysis tool] automate’.

        Cheers.

        • http://ariya.ofilabs.com/ Ariya Hidayat

          JFYI few days ago someone proposed the same to PhantomJS and it’s filed as http://code.google.com/p/phantomjs/issues/detail?id=386.

        • http://ariya.ofilabs.com/ Ariya Hidayat

          Care to share your experience on setting up e.g. SpeedTracer via headless extension in a CI system? I often got dismissed when I propose that idea, either it’s too complicated or somebody hasn’t built an easy to use plugin for widely used CI. Would be lovely to hear some success stories about that.

  • Russ Sherk

    Is there a difference between this and Google Chrome -> f12 -> profiles (start cpu profile and hit refresh)? Not trying to knock your efforts.  It is a pretty decent starting technique.

    In my experience, it has been worth while to look at the whole system to find out where the slowdown is occurring before instrumenting and profiling.  Luckily there are some tools that give you the big picture very quickly. For example: Google Speed Tracer and Yahoo! Yslow are good tools.  They will tell you about other important areas to make improvements: number of resources loaded (this can have a major impact on speed), file sizes, summaries of problem areas.  

    Here is a big ol list of tools for overall optimization tools: http://code.google.com/speed/tools.html

    Anyhow, good work and a good read.  Thanks!

    • http://ariya.ofilabs.com/ Ariya Hidayat

      I’m pretty familiar with a lot of different web performance analysis tools. The approaches you mentioned above can’t be controlled programmatically, and thus can’t be automated as part of the smoke tests in the continuous integration systems.

      • Russ Sherk

        I know I’m gonna sound like a jerk but: http://code.google.com/p/speedtracer/wiki/HeadlessExtension.  Also googling ‘[your favourite performance analysis tool] automate’.

        Cheers.

        • http://ariya.ofilabs.com/ Ariya Hidayat

          JFYI few days ago someone proposed the same to PhantomJS and it’s filed as http://code.google.com/p/phantomjs/issues/detail?id=386.

        • http://ariya.ofilabs.com/ Ariya Hidayat

          Care to share your experience on setting up e.g. SpeedTracer via headless extension in a CI system? I often got dismissed when I propose that idea, either it’s too complicated or somebody hasn’t built an easy to use plugin for widely used CI. Would be lovely to hear some success stories about that.

  • http://chaiguy.myopenid.com/ Logan

    I can’t even load a web page in 3 seconds.

  • http://chaiguy.myopenid.com/ Logan

    I can’t even load a web page in 3 seconds.

  • Jeromeinsf

    Interesting concept yet I am not sure you are actually solving anything regarding the problem you originally stated in the intro.
    I’d be curious to see the ratio time downloading vs time executing these 4000ish methods call… For what masters about bootstrap feeling.

    • http://ariya.ofilabs.com/ Ariya Hidayat

      I’m not trying to solve the transport optimization problem.
      Please read also the linked article about the empirical analysis of run-time complexity to get more context on why this is important but often overlooked.

  • Jeromeinsf

    Interesting concept yet I am not sure you are actually solving anything regarding the problem you originally stated in the intro.
    I’d be curious to see the ratio time downloading vs time executing these 4000ish methods call… For what masters about bootstrap feeling.

    • http://ariya.ofilabs.com/ Ariya Hidayat

      I’m not trying to solve the transport optimization problem.
      Please read also the linked article about the empirical analysis of run-time complexity to get more context on why this is important but often overlooked.

  • http://twitter.com/___kafka franz kafka

    Your point is moot. You cannot simply take the number of functions invoked by a framework/ library – not even at start-up, but – simply to bootstrap itself into a workable state as a sign of performance issues.

    The chances are those 4000+ functions you mention took less than 20 milliseconds to execute and that most function execution times would probably range from between 0-1 millisecond. 

    The large number of function invokations at start-up is usually the sign of a heavily optimised framework/ library making use of recurring patterns by creating abstractions in the form of… reusable… functions/ methods! :D

    If it’s taking 3 seconds for jquery and jquery mobile to bootstrap itself, then that is a different story, but i would recommend simply adding a script tag on either side of your jquery scripts and inserting a console.profile( ‘jquery:init’ ) in the first and a console.profileEnd( ‘jquery:init’ ) in the second, then open up firefox & firebug and load your page, you will see a collapsable header with something like:

    jquery:init (11.968ms, 4640 calls) // <- note: not real data

    in it, along with a complete list of all functions invoked in the console, along with how many times they were called, how long each took to complete, the overall percentage of time for a specific function relative to the complete list, etc, etc.

    Also, it is the JSIT's job to optimise functions called – usually – 3 times or more. If you minimise the number of functions, you run the risk of increasing the file size of your codebase, increasing the margin for error, increasing the amount of test coverage needed and reducing overall performance.

    If you want to analyse this kind of data then you should at least include the time each function took to execute.

    • http://ariya.ofilabs.com/ Ariya Hidayat

      Thanks for the enlightenment! To be honest, when you say “Your point is moot”, I’m myself not sure which of my points actually you are referring to. Any further explanation will be appreciated.

      I would also like to use the opportunity to emphasize the sentence “it does give you some more data when analyzing the startup time performance”. I admit that it may not be so prominent and clear, I do hope my excuse as a non-native English speaker is acceptable to you.

      In addition, you also may find the previous topic, linked twice from the above post, titled “Scalable web apps: the complexity issue” giving some additional context. I do completely agree with you on the further use of console.profile. I just thought the blog post is already quite long and I didn’t want to put more burden to the reader. It may make for a nice follow-up. 

      Also, by “JSIT” do you mean “JIT” as in Just-in Time?

  • http://twitter.com/___kafka franz kafka

    Your point is moot. You cannot simply take the number of functions invoked by a framework/ library – not even at start-up, but – simply to bootstrap itself into a workable state as a sign of performance issues.

    The chances are those 4000+ functions you mention took less than 20 milliseconds to execute and that most function execution times would probably range from between 0-1 millisecond. 

    The large number of function invokations at start-up is usually the sign of a heavily optimised framework/ library making use of recurring patterns by creating abstractions in the form of… reusable… functions/ methods! :D

    If it’s taking 3 seconds for jquery and jquery mobile to bootstrap itself, then that is a different story, but i would recommend simply adding a script tag on either side of your jquery scripts and inserting a console.profile( ‘jquery:init’ ) in the first and a console.profileEnd( ‘jquery:init’ ) in the second, then open up firefox & firebug and load your page, you will see a collapsable header with something like:

    jquery:init (11.968ms, 4640 calls) // <- note: not real data

    in it, along with a complete list of all functions invoked in the console, along with how many times they were called, how long each took to complete, the overall percentage of time for a specific function relative to the complete list, etc, etc.

    Also, it is the JSIT's job to optimise functions called – usually – 3 times or more. If you minimise the number of functions, you run the risk of increasing the file size of your codebase, increasing the margin for error, increasing the amount of test coverage needed and reducing overall performance.

    If you want to analyse this kind of data then you should at least include the time each function took to execute.

    • http://ariya.ofilabs.com/ Ariya Hidayat

      Thanks for the enlightenment! To be honest, when you say “Your point is moot”, I’m myself not sure which of my points actually you are referring to. Any further explanation will be appreciated.

      I would also like to use the opportunity to emphasize the sentence “it does give you some more data when analyzing the startup time performance”. I admit that it may not be so prominent and clear, I do hope my excuse as a non-native English speaker is acceptable to you.

      In addition, you also may find the previous topic, linked twice from the above post, titled “Scalable web apps: the complexity issue” giving some additional context. I do completely agree with you on the further use of console.profile. I just thought the blog post is already quite long and I didn’t want to put more burden to the reader. It may make for a nice follow-up. 

      Also, by “JSIT” do you mean “JIT” as in Just-in Time?

  • Pingback: Mozilla Hacks Weekly, February 16th 2012 ✩ Mozilla Hacks – the Web developer blog

  • Ivan Jouikov

    I can totally see the benefit of tracking just the # of function calls for startup, within a CI system.

    Imagine if for every build you have 4000-5000 functions on startup. As app grows, this becomes maybe 10,000. Then you hire an intern and the next build comes back with a million function calls on startup! Maybe only 1 second extra load time that cannot be caught by manual testing, but you get the red flag right away, right where you need it!

    Nice one, Ariya!

    • http://ariya.ofilabs.com/ Ariya Hidayat

      It doesn’t need to be the intern, even a seasoned developer can make a mistake in a large code base :)

  • Pingback: Performance Calendar » JavaScript Performance Analysis: Keeping the Big Picture