Quand un service ralentit, où regarder ?

8h50, il reste 10 min pour remplir un formulaire en ligne avant d’enchaîner avec le boulot. Après avoir surmonté votre phobie administrative, vous vous lancez à corps perdu dans une page chargée de champs de textes tous plus incompréhensibles que les autres, et vous demandez pourquoi diable vous avez décidé de sacrifier ces précieuses minutes sur l’autel de l’ennui.

8h59, vous validez enfin ce formulaire, et là, rien ne répond. Vous remettez votre existence en question, recliquez sur le bouton de validation — on ne sait jamais —, et pestez devant cette perte de temps infinie. Enfin, après plusieurs secondes, un message s’affiche vous indiquant que votre nom de famille ne peut pas contenir d’accents. Bien que la validation des données soit légitime, quoi de plus frustrant qu’un système lent, sans pouvoir expliquer pourquoi ?

Passons maintenant du côté du développeur de la plateforme : dans le monde de l’ingénierie logicielle, les coupables peuvent être légion et provoquer des sueurs froides. Un bug, un algorithme qui marche bien avec 2 utilisateurs mais qui s’effondre au bout de 10, un appel réseau qui prend son temps ou des allocations mémoire excessives. On peut avoir une intuition, y aller au culot. Mais sans regarder ce qui se passe réellement, il est facile de consacrer une journée à optimiser une partie du code qui n’explique pas la lenteur observée.

« C’est une erreur capitale de bâtir une théorie avant de disposer de données. »
— Sherlock Holmes dans « A Scandal in Bohemia », The Adventures of Sherlock Holmes , Arthur Conan Doyle (traduction libre).

Comme Sherlock, je préfère partir des faits avant de formuler une hypothèse. Utilisateur de Go depuis une petite dizaine d’années, j’apprécie particulièrement les outils fournis avec Go : pprof – que nous verrons plus bas – permet d’examiner ce que fait un processus dans le détail et de mettre de vrais chiffres sur un ressenti.

Pour un service web en production, je trouve souvent plus pratique de commencer par le tracing : il me permet de suivre des requêtes réelles entre plusieurs couches et de repérer les étapes où elles passent du temps. En comparant plusieurs traces, je peux alors repérer une lenteur qui revient régulièrement.

Dans cet article, je vous propose un tour d’horizon de ces deux approches : les questions auxquelles elles répondent, les premiers éléments à lire et leurs limites. Apprenons ensemble où regarder avant de décider quoi changer.

De quoi parle-t-on exactement ?¶

Avant d’ouvrir un outil, attardons-nous un instant sur deux questions : « que fait mon programme pendant son exécution ? » et « qu’arrive-t-il à une requête entre son entrée et sa réponse ? »

Le profiling : que fait mon programme pendant son exécution ?¶

Un profil est une mesure prise sur une période donnée, ou un état capturé à un instant précis. Selon la question posée, il peut montrer :

• le temps CPU consommé par les fonctions ;
• les endroits où le programme alloue ou conserve de la mémoire ;
• les goroutines présentes à un instant donné.

On ne peut pas tout observer avec un seul profil, mais chaque vue aide à attribuer une consommation ou une attente à une partie précise du programme.

Le tracing : qu’arrive-t-il à une requête entre son entrée et sa réponse ?¶

Une trace suit le parcours d’une opération — par exemple une requête HTTP — entre son arrivée et sa réponse. Elle est composée de spans : chaque span correspond à une étape instrumentée, avec un début, une fin et une durée. On peut ainsi voir le temps de traitement dans un service, puis celui passé dans un appel à une base de données ou à un autre service.

Lorsque la requête traverse plusieurs services, son contexte de trace doit être transmis avec les appels pour conserver ce parcours ; des outils comme Jaeger ou Datadog APM permettent ensuite de le consulter. Le tracing indique donc où une requête passe du temps : il ne montre pas, à lui seul, quelles fonctions consomment le plus de CPU dans un service.

Ces deux vues étant posées, commençons par la plus locale : ce qui se passe à l’intérieur d’un programme.

Profiling : regarder à l’intérieur d’un programme¶

Imaginons un bouchon sur l’autoroute. Faut-il ajouter une voie, revoir une bretelle d’accès ou supprimer un passage qui ralentit toutes les voitures ? Tout dépend de l’endroit où le trafic se bloque réellement : accélérer les voitures sur une portion déjà fluide ne fera pas disparaître le bouchon.

La même prudence s’applique à un service Go qui ralentit sous la charge : avant de modifier une fonction qui semble coûteuse, je recueille un profil dans une situation qui ressemble au problème observé. pprof peut le faire sur un processus en cours d’exécution ou pendant des tests ; mais ici, partons d’un service HTTP.

1. Exposer pprof¶

Le package net/http/pprof expose des routes de diagnostic en standard. Lancez-les sur un port local, séparé du serveur métier :

import (
    "log"
    "net/http"
    _ "net/http/pprof"
)

func startPprof() {
    go func() {
        log.Printf("pprof : %v", http.ListenAndServe("127.0.0.1:6060", nil))
    }()
}

En appelant startPprof() au démarrage, un serveur HTTP dédié donne accès aux routes de diagnostic. L’import "net/http/pprof" les enregistre sur le routeur HTTP par défaut ; il ne reste qu’à démarrer un serveur HTTP standard avec http.ListenAndServe. Ici, le serveur écoute uniquement en local pour ne pas exposer ces routes au trafic public.

2. Capturer pendant une charge représentative¶

Pendant que le scénario lent se reproduit, capturez par exemple trente secondes de CPU :

go tool pprof 'http://localhost:6060/debug/pprof/profile?seconds=30'

3. Lire le résultat¶

Vous pouvez analyser un profil dans la CLI ou dans l’interface web de pprof.

Dans l’invite de commandes de la CLI, top affiche les fonctions les plus présentes dans les échantillons. flat correspond au temps attribué directement à une fonction ; cum inclut aussi le temps de ses appels.

Pour explorer visuellement les appels, démarrez l’interface web puis ouvrez l’adresse affichée :

go tool pprof -http=:8081 'http://localhost:6060/debug/pprof/profile?seconds=30'

Le graphe donne des temps de CPU cumulatifs et permet de voir les fonctions qui prennent la part la plus importante. Une fonction en tête du classement CPU n’est pas forcément un élément à corriger, mais une piste à examiner. La sérialisation de structures complexes en JSON ou XML peut par exemple représenter un coût important, tout en étant nécessaire au fonctionnement de la requête. Il faut alors déterminer si ce coût peut être réduit, évité ou accepté.

4. Choisir le profil adapté¶

• heap aide à repérer les allocations ou les objets encore présents ;
• goroutine montre les piles d’appels si elles s’accumulent ou semblent bloquées ;
• un profil CPU ne montre pas le temps passé à attendre un appel réseau.

Le profiling ajoute lui-même un certain coût à l’exécution, variable selon le type de profil et sa durée. Avant de l’utiliser largement en production, il faut donc en mesurer l’impact et tenir compte de cette perturbation dans l’analyse.

Tracing : suivre le parcours d’une opération¶

Le tracing ne se limite pas aux microservices. Il suit une opération — par exemple une requête HTTP — à travers les parties instrumentées d’un monolithe, ses appels à une base de données et, si besoin, d’autres services. Il répond à une question simple : où le temps a-t-il été passé ?

1. Exporter les traces¶

Pour cet exemple, je vais utiliser Jaeger comme backend pour stocker les traces. L’application envoie ses traces au format OTLP, un standard open source qui permet d’exporter les traces vers des backends compatibles.

Au démarrage de l’application, on crée un TracerProvider, on lui associe un exporteur et échantillonne (ici 10 %) des traces :

exporter, err := otlptracehttp.New(ctx)
if err != nil {
    return err
}

tp := trace.NewTracerProvider(
    trace.WithBatcher(exporter),
    trace.WithSampler(trace.ParentBased(trace.TraceIDRatioBased(0.1))),
)
otel.SetTracerProvider(tp)
defer tp.Shutdown(ctx)

Il reste à configurer l’exporteur pour envoyer les traces vers le point de collecte OTLP de Jaeger. En local, l’exporteur HTTP peut utiliser http://localhost:4318 comme adresse de base ; les traces sont alors envoyées sur /v1/traces.

2. Instrumenter les entrées et les dépendances¶

Maintenant que l’application peut exporter des traces, il reste à instrumenter le code métier. Le plus simple pour un serveur HTTP est de créer un span racine pour chaque requête avec un middleware HTTP. Dans mon cas, voici ce que donne la mise en place avec le routeur chi :

r.Use(telemetry.HTTPHandler)
r.Use(telemetry.RouteAttributes)

HTTPHandler s’appuie sur otelhttp.NewHandler. Le second middleware groupe les requêtes qui utilisent un pattern (par exemple GET /v1/profiles/{id}) : on évite ainsi de créer une valeur différente pour chaque identifiant.

Les bibliothèques d’instrumentation font ensuite une grande partie du travail : otelsql pour ma base de données (ici MySQL), redisotel pour Redis, et otelhttp.NewTransport pour les appels HTTP à des services internes ou externes. Le contexte de la trace est transmis aux appels HTTP sortants, ce qui fait que les spans de ces appels sont liés à la même trace (à condition que le service distant soit instrumenté).

3. Lire une trace¶

Dans Jaeger, ouvrez une requête lente et suivez ses spans du début à la réponse. Une étape longue indique où regarder, pas forcément la cause : elle peut contenir du calcul, attendre une base de données ou appeler une dépendance distante. Comparez plusieurs traces avant de conclure.

Pour vous donner un exemple d’utilisation : chez Molotov, cette instrumentation m’a permis à plusieurs reprises d’analyser des lenteurs dans l’application. J’ai par exemple pu identifier un appel qui était fait deux fois, une fois dans l’API Gateway et une seconde dans le service spécialisé pour la gestion des enregistrements (bookmarks). La trace a indiqué où chercher ; la lecture du code a confirmé qu’un appel pouvait être supprimé, pour un gain de quelques centaines de millisecondes.

Une trace n’est pas un benchmark et ne remplace pas un profil pprof. Elle situe la lenteur sur le parcours d’une opération ; un profil aide ensuite à comprendre ce qui se passe dans le processus concerné.

Par où commencer ?¶

Partez du symptôme observé : il indique la première mesure à prendre.

Le premier outil ne clôt pas le diagnostic. Une trace peut désigner un appel ou un processus à examiner avec pprof ; un profil CPU peu chargé peut au contraire indiquer qu’il faut suivre les dépendances. Après une correction, mesurez de nouveau le même symptôme.

Ce que j’en retiens¶

Le cas des bookmarks chez Molotov l’illustre bien : la mesure a permis de trouver une étape en double, puis de supprimer quelques centaines de millisecondes sans optimisation complexe.

pprof et le tracing donnent deux vues complémentaires d’un problème de performance : le premier aide à examiner ce qui se passe à l’intérieur d’un processus Go ; le second suit une opération à travers les étapes instrumentées. Dans les deux cas, les chiffres servent à poser une meilleure question. Pour juger le résultat d’une modification, il faut ensuite comparer des mesures obtenues dans des conditions comparables.

De mon côté, je viens d’installer Tempo et de le configurer dans Grafana pour l’expérimenter dans la stack NuCorder . Ce sera sans doute l’objet d’un futur article, lorsque j’aurai pris le temps de l’apprivoiser !