Tuesday, 24 August 2010

Profiling Javascript Performance in Safari 5

We're currently in the process of building some pretty large and complex javascript apps here at Calvium. One of the parts of the system was running rather slower than it should have, so I took it upon myself to find out why. It turned out that all of the tools I needed to track down the performance problems were available right in the browser I was using - Safari 5 (and also Chrome, which shares the same engine) has an excellent Javascript Profiler available in the Inspector.
Using it is as simple as opening the page you want to profile, and in Safari, going to Develop / Web Inspector.
Once there, click the Profiles button and select 'enable profiling for this session'.

You can control the profiler by clicking the black circular 'record' button at the bottom left. When you stop recording you'll get a breakdown of the percentage of the time spent in each function. This can be handy, but often what you really want is to profile a very specific part of your app, for instance the process kicked off when a particular button is pressed.

Luckily there are some console commands you can insert into your Javascript to start and stop the profiler automatically.

Here's an extremely simple example. Here the goal is to find out which function is causing the slow operation of this script - is it slowFunction, or fastFunction? Guesses on a postcard please..

<html>
<head>
<script type="text/javascript">
setTimeout(function() {
// start profiling
console.profile("why so slow?");
slowFunction();
fastFunction();
// stop profiling
console.profileEnd();
}, 2000);

function slowFunction() {
for(var i=0; i < 100; i++) { stuff();}
}

function stuff() {
var count = 0;
for (var i=0; i < 1000; i++) {
for (var j=0; j < 1000; j++) {
count = count + 5;
}
}
}

function fastFunction() { var j = 23; }
</script>
</head>
</html>


When you open this page in Safari and run the profiler you get the following output:



The entries in the 'self' column shows the percentage of the profile time the execution of that particular function took - excluding time taken executing other sub-function calls made in that function. Here we can see that 'slowFunction' only took 0.02% itself, but 'stuff' took 99.93%. Looks like 'slowFunction' itself doesn't need any optimisation.
The 'total' column shows the time including any sub-function calls made, and here we can see that 'slowFunction' takes a massive 99.95% of the program execution. We can discover why this is easily using the Profiler tool. (I know its obvious in this case, but imagine with a huge complex app!).

You can change the way the results are displayed from the default 'Heavy (bottom up)', which shows each function individually, to the 'Tree (Top Down)' view. The tree view shows the call stack, and the time taken for each function along the way. Using this we can quickly drill down to discover that 'slowFunction' calls 'stuff', and that's why it takes so long. You can also see how many times each function is run.

Using this technique, you can easily discover the parts of your app that need optimisation. I manage to speed up the screen loading of a part of our application by a factor of six by identifying one particularly slow function that was called a huge number of times.

There's more info on using the 'console' javascript API on the apple developer site

No comments:

Post a Comment