Performance analyse

Fibonacci

De code die dit artikel inspireerde kan ik niet delen. In plaats daarvan nemen we een simpele Express server met een endpoint onder de loep dat het n-de resultaat uit de Fibonacci-reeks retourneert. De Fibonacci-reeks is een reeks getallen waarbij ieder getal de som is van de twee getallen ervoor. De eerste twee getallen zijn 0 en 1.

De code die we gebruiken voor onze test is een naïeve methode waarbij we recursief alle termen berekenen vanaf de beginwaarden 0 en 1. Het resultaat is dat het programma bij relatief kleine waarden van n minuten nodig heeft om tot een antwoord te komen.

In de praktijk kunnen performanceproblemen allerlei oorzaken hebben. Een naïeve implementatie van een algoritme is zo’n oorzaak. In de code die dit artikel inspireerde was het kopiëren van grote datastructuren de grootste boosdoener. Uiteindelijk zoeken we naar stukken code die langer duren dan we zouden verwachten en proberen we daar alternatieven voor te vinden die beter presteren.

// 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 heeft een aparte versie waarin NodeJS-applicaties kunnen worden gedebugd. Deze heeft ook een profiler. Een profiler kijkt wanneer instructies worden uitgevoerd en voegt dit vervolgens samen in een handig overzicht. Om bij de devtools te komen open je eerst de normale devtools. Start daarna de applicatie in debug mode met node -inspect index.js. Als je extern wilt debuggen, dan moet je expliciet binden op localhost met node --inspect=0.0.0.0:9229 index.js.

Om de profiler effectief te gebruiken, start je de profiler vlak voordat de code draait die je wilt profilen, en stop je de profiler vlak erna. Dit kan bijvoorbeeld voor en na een API call, zoals we in dit voorbeeld hebben gedaan.

De profiler in Chrome Dev Tools toont automatisch de “Heavy (Bottom Up)”-tabel, gesorteerd op Self Time. Self Time is de tijd die wordt besteed in de functie zelf, zonder de tijd in functies die deze aanroept (figuur 1). Figuur 2 toont dit voor een aanroep van de fibonaccifunctie met een relatief lage waarde van n. In dit geval besteden we 4,5 seconde in de functie fibo, maar bijna geen tijd in de functie handle die wordt aangeroepen iedere keer dat een API call wordt gedaan. Total Time is de tijd tussen het begin en het eind van een functieaanroep, inclusief functies die binnen die functie worden aangeroepen. Voor geneste functieaanroepen, zoals bij onze fibonaccifunctie, kunnen deze tijd en het onderliggende percentage flink oplopen, omdat we feitelijk veel executietijd dubbel tellen.

Zowel Self Time als Total Time zijn nuttig. Een hoge Self Time kan erop duiden dat een functie inefficiënt is, of dat een efficiënte functie heel vaak wordt aangeroepen. Een helperfunctie die in 1ns wordt uitgevoerd, maar 3 miljoen keer wordt aangeroepen, heeft immers nog steeds een totale executietijd van 3 seconden. Een hoge Total Time kan tonen dat het lang duurt voordat een functie tot een antwoord komt, ongeacht of dit zichtbaar is in de Self Time van zichzelf of van de individuele functies die deze aanroept, of de functie vaak wordt uitgevoerd, of dat de functie vaak in zichzelf is genest.

De “Tree (Top Down)”-tabel (figuur 3) toont de call stack van een applicatie, met de eerder genoemde Self Time en Total Time. De informatie die je hieruit kunt halen is vaak visueel beter leesbaar via de “Chart” (figuur 4), die horizontaal de tijd toont en verticaal de geneste functieaanroepen.

Informatie uit deze tool

Uit de tabel gesorteerd op Self Time kunnen we concluderen dat het programma de meeste tijd besteedt in de fibo-functie. Uit de code kunnen we halen dat deze functie heel simpel is. De executietijd komt niet overeen met onze verwachting. De Total Time, en een enkele blik op de Chart, vertelt ons dat er veel nesting plaatsvindt.

Deze informatie zegt niets over hoe we dit probleem moeten oplossen. Het geeft ons wel een beginpunt voor welke code we verder moeten onderzoeken. Een vraag die we bij dit stuk code moeten stellen, bijvoorbeeld, is of het daadwerkelijk noodzakelijk is om voor iedere aanroep van de fibo-functie het resultaat te berekenen van de twee voorgaande getallen uit de reeks.

Dev Tools in VS Code

VS Code komt standaard met een JavaScript debugger, maar op het moment van schrijven (maart 2022) zijn performancegerelateerde tools alleen nog beschikbaar in de nightly build. Zoek op @id:ms-vscode.js-debug-nightly in de extensies-tab voor instructies om dit te installeren.

Met de optie “Debug: Take Performance Profile” kunnen we dezelfde tabellen en charts genereren als in Chrome Dev Tools. Het voordeel ten opzichte van Chrome Dev Tools is dat performance-informatie ook naast functies in de code zelf komt te staan (figuur 4), en dat we kunnen doorklikken naar de definitie van de functie in VS Code. Hier kunnen we direct bewerken.

Debug package

In gevallen waar meerdere processen naast elkaar draaien, of waar we niet per se een CPU profile willen uitpluizen, kan ook het lightweight debug package worden gebruikt. Met dit package kun je berichten loggen en wordt de verlopen tijd tussen twee berichten bijgehouden. Daarmee bouw je eenvoudig een tijdlijn. Dit package gebruikt ook namespaces, waardoor workers bijvoorbeeld verschillende namen kunnen krijgen en onafhankelijk van elkaar kunnen worden getimed.

Een package als dit helpt je ook om in een testproject verschillende alternatieven te testen voor een geïdentificeerd performanceprobleem. Door de verschillende alternatieven na elkaar te testen en de timings ertussen te vergelijken, kun je een beeld vormen van hoe de alternatieven presteren.

In het volgende stuk code testen we bijvoorbeeld verschillende alternatieven voor een mogelijke fix voor onze fibo-functie. We hebben geïdentificeerd dat de fibo-functie een zogenoemde pure functie is, en dat iedere aanroep met dezelfde parameters hetzelfde resultaat geeft. We willen weten wat de beste manier is om die waarden te cachen en terug te geven.

// 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');

Het doel met deze code is om een representatieve situatie te hebben, zonder veel tijd te besteden aan het daadwerkelijk bouwen ervan. Na het uitvoeren van deze code (figuur 8) kunnen we concluderen dat in dit geval objecten iets sneller zijn dan arrays als we ongeveer 100.000 resultaten willen cachen en verwachten ongeveer 1.000.000 functieaanroepen te doen.

Resultaat

Een mogelijke verbetering van onze eerdere code is om de eerder genoemde caching in te bouwen. We krijgen dan iets in deze vorm.

// 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;
}