Ma lambda prend-elle trop de temps à s'exécuter ?

Les architectures serverless se base principalement sur Lambda, un service qui est facturé au temps passé. Dès lors, il est crucial de s’assurer que le temps d’exécution des lambdas reste raisonnable. Heureusement, en configurant correctement les logs, il est possible d’utiliser CloudWatch Logs Insights pour identifier les invocations les plus longues.

CloudWatch Logs Insights c’est quoi ?

Lorsqu’une fonction Lambda est invoquée, les logs d’exécution sont stockées sur CloudWatch Logs. Il est alors possible de consulter un par un ces fichiers. Cela se fait aisément en phase de prototypage, mais dans un cas d’utilisation en production on bute vite sur les limites de cette approche.

C’est là qu’intervient CloudWatch Logs Insights en offrant la possibilité de rechercher et d’analyser de manière interactive les fichiers stockés dans CloudWatch. Un syntaxe “SQL like” permet de filtrer, d’agréger et de calculer des statistiques à partir des données contenues dans ces logs. Pour tirer pleinement parti de ce service, il est préférable de configurer les logs au format json.

La requête qui identifie les invocations les plus lentes

Pour accéder au service Logs Insights il faut se rendre dans la page principale CloudWatch, puis dans le menu de gauche cliquer sur “Insights” dans la section “Logs”. Il est alors possible d’utiliser des requêtes prédéfinies en cliquant sur “Queries” dans le menu de droite. Une liste d’exemples est alors affichée, dont certaines destinées aux logs des fonctions Lambda. Pour les utiliser il suffit d’en afficher une et de cliquer sur “Apply”.

Il faut alors sélectionner le log group que l’on souhaite analyser, dans notre cas celui de la lambda. Attention, si les access logs de API Gateway sont activés, deux log groups sont affichés avec des noms similaires. C’est bien celui de la fonction lambda qu’il faut choisir.

Une fois que l’on a cliqué sur le bouton “Run Query” et que la requête a achevé son exécution on obtient un tableau de résultat de la sorte :

On obtient deux choses : le temps d’exécution de la lambda (et donc de facturation) ainsi que le request ID.

Enquêter sur les causes de la lenteur

Le request ID va permettre de creuser un peu et d’aller étudier les logs d’une invocation en particulier. Par exemple, prenons l’ID fd313e66-372f-4260-aed0-f76faef7a2eb.

Si l’on retourne dans CloudWatch Logs il va être possible de rechercher toutes les lignes correspondant à cette invocation. Pour peu que le request ID soit logué systématiquement , on va obtenir plus d’informations :

Dans notre cas on se rend compte que c’est la consultation de la base de données qui pose des problèmes de performance. On peut alors aller plus loin et consulter les access logs de notre API Gateway, en utilisant l’attribut integrationRequestId.

fields @timestamp, @message
| filter integrationRequestId =  "fd313e66-372f-4260-aed0-f76faef7a2eb"
| sort @timestamp desc
| limit 20

La ligne trouvée nous permet d’identifier le path de la requête, utile par exemple lorsqu’une API expose plusieurs routes. De même on identifie le user-agent, ce qui dans certains cas permet d’identifier la cause du problème.

Avertissement sur les lambdas en timeout

J’ai été confronté à une situation où le lien entre les logs de la lambda et les access logs n’était pas possible. Si votre fonction lambda met plus de temps à répondre que le timeout configuré pour votre API, aucune valeur ne sera associée à l’attribut integrationRequestId. Par exemple dans le cas ci dessous, le timeout configuré à 30 secondes est atteint.

Si l’on consulte l’access log correspondant on voit bien que les attributs liés à la Lambda sont vides : integrationRequestId, integrationResponseStatus et integrationServiceStatus.

Si tu es arrivé jusqu’ici, merci beaucoup d’avoir lu cet article !
Pense à t’abonner à la mailing list pour ne rater aucun article, le formulaire se trouve en bas de page.
Photo de couverture par Milad Fakurian.