Vous pensiez que j’avais arrêté la technique ? Que ma vie désormais allait se résumer à publier des articles rigolos sur le blog de D2SI ? Et bien non ! Ci dessous, je vous offre une petite étude de cas que j’ai rencontré en clientèle ce mois-ci, l’occasion de (re)découvrir AWS XRay, et comment ce service peut vous aider avec vos lambdas.

Mise en situation

Je suis actuellement en mission auprès d’un grand groupe, et j’ai l’occasion de travailler en ce moment sur la partie backend d’un projet très sympa qui a été monté initialement par des consultants de chez OCTO. Le projet est en Node.js, il tourne bien (il y a très peu de bugs) et il est déployé dans AWS. Il s’appuie sur les services Lambda + API Gateway pour la partie API, et S3 + CloudFront pour un site statique. Une architecture comme vous le voyez très classique, mis à part un custom authorizer pour des raisons de fédération avec l’outil d’identité du groupe. Une précision importante pour la suite : les lambdas sont dans un VPC car elles accèdent à une base RDS qui n’est pas ouverte vers l’extérieur.

Houston, we’ve had a problem here

C’était une belle matinée de juin. Le ciel bleu se reflétait insolemment sur nos écrans derrière les épaisses vitres de la tour, comme pour nous inviter à venir le rejoindre à l’extérieur. Tandis que nous l’ignorions sans empathie aucune en abaissant les stores électriques dans le désagréable bruit de voiture électrique des moteurs actionnant ces volets, ce fut l’heure du daily meeting. Parce que oui, on est une équipe agile et toutes ces sortes de choses, du coup on parle de nos vies debout le matin comme des alcooliques anonymes. Bref.

Entre deux histoires sur ce que chacun allait faire aujourd’hui, on nous partagea le retour d’utilisateurs qui trouvaient le site “lent”. En tant qu’informaticiens de base entraînés à répondre à ces problématiques par des “non mais, il sait pas cliquer lui ça compte pas” le sujet sorti assez vite des préoccupations du jour : on avait de la fonctionnalité à livrer.

Néanmoins, chacun garda en tête cette petite remarque dans un souci d’amélioration, mais aucun ne constata individuellement un tel ralentissement sur les environnements de développement ou bien en production.

Analyse de la situation

A la fin du sprint, la rétrospective arriva (parce qu’on est agile tavu), et j’ai proposé de passer un peu de temps à investiguer les problématiques de performance. La proposition acceptée, il fallait se mettre en marche, mais comme je dis souvent : pour aller quelque part, il faut savoir où on va (j’ai beaucoup de punchlines de ce genre, je vous ferai une liste un jour).

J’entrepris alors de mettre en place AWS XRay pour analyser la situation et je constata que cela avait déjà été fait par Jules, le développeur précédent. Sacré Jules. J’avais donc en fait des métriques à disposition depuis longtemps.

AWS XRay, qu’est-ce que c’est ?
AWS XRay est un service AWS permettant de collecter et afficher des métriques temporelles sur vos systèmes comme Lambda ou EC2. Ce service est capable de créer une “carte” des appels de chaque service, et si le code est correctement instrumenté, de voir les segments d’exécution des différentes parties de votre code.

Jules avait activé la collecte dans AWS XRay des métriques de lambdas, mais n’avait pas instrumenté le code en détail. J’entrepris alors d’ajouter à minima l’analyse des appels à RDS, parce que c’était vite fait et que -peut être- mes problèmes de performance venaient de la base de données. Je me trompais, mais nous allons y revenir.

Voici le code (très simple) que j’ai ajouté pour traquer RDS au moment de la création du client PostgreSQL dans le code :

const AWSXRay = require('aws-xray-sdk');
const pg = AWSXRay.capturePostgres(require('pg'));
const pool = new pg.Pool(conf); 

Une fois les requêtes en base de données traquées et les enregistrements activés côté API Gateway et Lambda, il suffit d’aller chercher dans AWS XRay les requêtes d’API les plus lentes, et le résultat dans la capture ci-dessous est sans appel :

Explications :

• AWS:APIGateway:Stage représente la durée totale d’exécution de la requête
• AWS:Lambda est le temps passé dans le service Lambda
• AWS:Lambda:Function est le temps passé pour exécuter la fonction

Dans mon diagramme, il y a deux lambda car la requête passe d’abord le filtre du custom l’authorizer pour valider que l’utilisateur a bien le droit d’appeler l’API, puis le “vrai” traitement est effectué dans la lambda métier qui fait appel à la BDD.

Un écart important entre AWS:Lambda et AWS:Lambda:Function est souvent lié au cold start. C’est grosso-modo le temps que met AWS à démarrer une microVM pour lancer votre code (pour le détail, allez-voir la section “aller plus loin”)

Je vous avais dit que les lambda étaient dans un VPC, et ce n’est pas anodin. A l’heure où j’écris cet article (juillet 2019) il y a un gros problème de performance lors du démarrage à froid des lambda lorsqu’elles sont dans un VPC. L’analyse de l’image ci-dessous le met bel et bien en évidence, et comme je vous l’ai dit un peu avant je me trompais en accusant la base de données (méchant Nicolas, méchant).

Vous avez sans doute constaté sur ma capture d’écran, le délai au cold start frappe uniquement la lambda de l’authorizer et pas celle “métier” alors qu’elles sont toutes les deux dans un VPC. Quel est ce prodige ? Il y a encore une information que je ne vous ai pas donné sur ce projet : les développeurs de chez Octo avaient bel et bien à l’origine identifié le problème de cold start, et Jules (encore lui) avait ajouté un mécanisme de préchauffage des lambda comme cela se fait souvent : un appel régulier à la méthode permet de maintenir la microVM démarrée chez AWS et ainsi réduire à néant le démarrage froid. Cela aurait dû éliminer à la fois le cold start de l’authorizer et celui de la lambda métier, mais quelque chose d’imprévu était arrivé.

Mais depuis le départ de Jules, le site avait évolué. Désormais la page d’accueil ne fait plus une seule requête à l’API mais quatre. Elle exécute donc quatre lambdas métier différentes (préchauffées) et quatre authorizer en parallèle. Problème : dans le mécanisme qui était en place une seule instance d’authorizer était chauffée. Les autres requêtes subissaient par conséquent de plein fouet le cold start de l’authorizer quand bien même leur traitement ensuite côté métier était rapide.

Exemple ci-dessous avec la console de Firefox ouverte sur notre site où une requête est insupportablement lente :

Moteur… Action !

Les problématique de performance, cela se traite en premier lieu en tapant très fort sur les gros. J’ai donc décidé d’aller taper sur l’authorizer. Une solution naïve imaginée en premier lieu consistait à chauffer davantage d’authorizer afin de supporter la charge en parallèle lors des requêtes sur la page d’accueil. Mais il existait une autre solution.

Je suis avant tout un dev, donc je suis allé voir ce que faisait en réalité cet authorizer, et cela se résume en ces quelques lignes :

const MyJwtVerifier = require("my-jwt-verifier");
const jwtDecode = require("jwt-decode");

export const authorizerFunction = async (event: any) => {
    let token = event.authorizationToken;
    try {
        await verifyToken(token);
        return generatePolicy("Allow", "*");
    } catch (err) {
        console.log(err);
        return generatePolicy("Deny", event.methodArn);
    }
};

export const verifyToken = (token: any) => {
    const myJwtVerifier = new MyJwtVerifier();
    return  myJwtVerifier.verifyAccessToken(token);
};

En gros, le machin fait juste la vérification du token JWT. Il n’a pas besoin de la base de données ! Le moment de sortir le super schéma de la documentation d’AWS :

Pour ceux qui ne parlent pas Anglais, le diagramme dit en substance : petit lapin, si t’a pas besoin de VPC, ne mets pas ta lambda dans un VPC.

Du coup, pour taper très fort sur l’authorizer à moindre frais il suffit de le sortir du VPC.

L’heure de la récolte des fruit

Alors est-ce que ça marche ? Comme je dis souvent : ne fête pas la victoire tant que tu n’as pas gagné. Voici le nouveau diagramme avec le code modifié. Vous constaterez que j’en ai profité pour instrumenter le code et rajouter des segments personnalisés sur les méthodes appelées afin de tracer également l’exécution à l’intérieur de l’authorizer:

Comme vous pouvez le voir sur la capture d’écran, je suis à présent descendu à 100 millisecondes de cold start sur l’authorizer ! Un très bon score en regard des 10 secondes précédentes. Merci à AWS XRay de m’avoir permis de trouver la vraie cause du problème.

Fin de l’épisode ?

Presque…

L’analyse dans AWS XRay montre quand même 300 millisecondes pour valider un token JWT, ce qui me paraît un petit peu exagéré. Cette durée monte même à 2 secondes parfois sur certaines traces.

Une analyse de la librairie utilisée et son usage dans notre projet montre une très mauvaise exploitation du cache : à chaque exécution la lambda télécharge les fichiers de clé publique jwks pour valider la signature du token. Cela engendre ces 300 à 2000 millisecondes de latence sur chaque appel car l’authorizer intercepte toutes les requêtes.

Il est donc le moment de reprendre ma pelle et taper encore sur l’authorizer, pour des optimisations côté code cette fois. Je vous raconterai ça dans un prochain article 🙂

Pour aller plus loin, regardez ces super slides issues du re:invent 2018 sur l’optimisation des lambdas. Et lisez l’article de Jean sur les bonnes pratiques Lambda.

Merci à Roman pour sa relecture de cet article 🙂