Performance analysis

Fibonacci

I cannot share the code that inspired this article. Instead we take a closer look at a simple Express server with an endpoint that returns the nth result from the Fibonacci sequence. The Fibonacci sequence is a sequence of numbers where each number is the sum of the two numbers before it. The first two numbers are 0 and 1.

The code we use for our test is a naive method where we recursively calculate all terms starting from the initial values 0 and 1. The result is that for relatively small values of n, the program takes minutes to arrive at an answer.

In practice, performance problems can have all kinds of causes. A naive implementation of an algorithm is one such cause. In the code that inspired this article, copying large data structures was the biggest culprit. Ultimately we look for pieces of code that take longer than we would expect and try to find alternatives for them that perform better.

// index.js
const { fibo } = require('./fibo.js');

const express = require('express');
const app = express();
const port = 3000;

app.get('/*', handleRequest);

app.listen(port, () => {
  console.log(`Example app listening on port ${port}`);
});

function handleRequest(req, res) {
    const url = req.url;
    const split = url.split('/');
    let result;

    // Note: Unsafe: Length is unguarded
    switch (split[1]) {
        case 'fibo':
            result = fibo(parseInt(split[2]));
            break;
        default:
            result = 'Unknown url';
    }

    res.send(`${result}`);
}

// fibo.js
var exports = (module.exports = {});
exports.fibo = fibo;

function fibo(n) {
    if (n === 0 || n === 1) {
        return n;
    }

    return fibo(n-1) + fibo(n-2);
}

Chrome Dev Tools

Chrome Dev Tools has a separate version in which NodeJS applications can be debugged. It also has a profiler. A profiler looks at when instructions are executed and then aggregates this into a handy overview. To reach the devtools, first open the normal devtools. Then start the application in debug mode with node -inspect index.js. If you want to debug externally, you need to explicitly bind to localhost with node --inspect=0.0.0.0:9229 index.js.

To use the profiler effectively, you start the profiler just before the code you want to profile runs, and stop the profiler just after. This can, for example, be before and after an API call, as we have done in this example.

The profiler in Chrome Dev Tools automatically shows the “Heavy (Bottom Up)” table, sorted by Self Time. Self Time is the time spent in the function itself, without the time in functions it calls (figure 1). Figure 2 shows this for a call to the fibonacci function with a relatively low value of n. In this case we spend 4.5 seconds in the fibo function, but almost no time in the handle function that is called every time an API call is made. Total Time is the time between the start and end of a function call, including functions called within that function. For nested function calls such as our fibonacci function, this time and the underlying percentage can add up considerably, because we are effectively counting a lot of execution time twice.

Both Self Time and Total Time are useful. A high Self Time can indicate that a function is inefficient, or that an efficient function is called very often. After all, a helper function that runs in 1ns but is called 3 million times still has a total execution time of 3 seconds. A high Total Time can show that it takes a function a long time to arrive at an answer, regardless of whether this shows up in the Self Time of itself or of the individual functions it calls, whether the function is executed often, or whether the function is often nested within itself.

The “Tree (Top Down)” table (figure 3) shows the call stack of an application, with the previously mentioned Self Time and Total Time. The information you can get from this is often easier to read visually via the “Chart” (figure 4), which shows time horizontally and the nested function calls vertically.

Information from this tool

From the table sorted by Self Time we can conclude that the program spends most of its time in the fibo function. From the code we can tell that this function is very simple. The execution time does not match our expectation. The Total Time, and a single glance at the Chart, tells us that a great deal of nesting is taking place.

This information says nothing about how we should solve this problem. It does give us a starting point for which code to examine further. One question we should ask about this piece of code, for example, is whether it is actually necessary to calculate the result of the two preceding numbers in the sequence for every call to the fibo function.

Dev Tools in VS Code

VS Code comes with a JavaScript debugger by default, but at the time of writing (March 2022) performance-related tools are still only available in the nightly build. Search for @id:ms-vscode.js-debug-nightly in the extensions tab for instructions on how to install this.

With the “Debug: Take Performance Profile” option, we can generate the same tables and charts as in Chrome Dev Tools. The advantage over Chrome Dev Tools is that performance information also appears next to functions in the code itself (figure 4), and that we can click through to the definition of the function in VS Code. Here we can edit directly.

Debug package

In cases where multiple processes run alongside each other, or where we do not necessarily want to pick apart a CPU profile, the lightweight debug package can also be used. This package allows you to log messages and keeps track of the elapsed time between two messages. This makes it easy to build a timeline. This package also uses namespaces, so workers, for example, can get different names and be timed independently of each other.

A package like this also helps you test different alternatives for an identified performance problem in a test project. By testing the different alternatives one after another and comparing the timings between them, you can build up a picture of how the alternatives perform.

In the following piece of code we test, for example, several alternatives for a possible fix for our fibo function. We have identified that the fibo function is a so-called pure function, and that every call with the same parameters gives the same result. We want to know what the best way is to cache those values and return them.

// analysis.js
const debug = require('debug')('analysis');

// We are figuring out if it is faster to cache the result of fibo(n) using an
// object or an array.

// We want the tests to be as similar as possible, so we will prepare the work they will do here
const numberOfTests = 500;
const maximumNumber = 100000;
const numberOfFunctionCalls = 1000000;
const arguments = [maximumNumber];
for (let i = 1; i < numberOfFunctionCalls; i++) {
    arguments.push(Math.floor(Math.random() * maximumNumber));
}

// The first test uses an object
debug('---')
for (let i = 0; i < numberOfTests; i++) {
    const test1CacheObject = {};
    function test1(argument) {
        if (test1CacheObject[argument] !== undefined) {
            return test1CacheObject[argument];
        }

        const value = argument * 2.5;

        test1CacheObject[argument] = value;

        return value;
    }

    for (const argument of arguments) {
        test1(argument);
    }
}
debug('>>>> Test 1: object cache');

// The second test uses an array
debug('---')
for (let i = 0; i < numberOfTests; i++) {
    const test2CacheObject = [];
    function test2(argument) {
        if (test2CacheObject[argument] !== undefined) {
            return test2CacheObject[argument];
        }

        const value = argument * 2.5;

        test2CacheObject[argument] = value;

        return value;
    }

    for (const argument of arguments) {
        test2(argument);
    }
}
debug('>>>> Test 2: array cache');

// The third test uses an array with a fixed length
debug('---')
for (let i = 0; i < numberOfTests; i++) {
    const test3CacheObject = new Array(maximumNumber);
    function test3(argument) {
        if (test3CacheObject[argument] !== undefined) {
            return test3CacheObject[argument];
        }

        const value = argument * 2.5;

        test3CacheObject[argument] = value;

        return value;
    }

    for (const argument of arguments) {
        test3(argument);
    }
}
debug('>>>> Test 3: array cache with fixed length');

The goal with this code is to have a representative situation, without spending a lot of time actually building it. After running this code (figure 8) we can conclude that in this case objects are slightly faster than arrays if we want to cache around 100,000 results and expect to make around 1,000,000 function calls.

Result

A possible improvement to our earlier code is to build in the caching mentioned earlier. This gives us something along these lines.

// fibo.js
var exports = (module.exports = {});
exports.fibo = fibo;

var fiboCache = {};
function fibo(n) {
    if (fiboCache[n]) {
        return fiboCache[n];
    }

    if (n === 0 || n === 1) {
        return n;
    }

    const result = fibo(n-1) + fibo(n-2);

    fiboCache[n] = result;

    return result;
}