Skip to content

🔭 Comprendre le tracing distribué (Tempo + OpenTelemetry)

Le tracing est le 3e pilier d'observabilité, après les métriques (Prometheus) et les logs (Loki). Là où une métrique dit combien et un log dit quoi sur un pod, une trace raconte le voyage d'une requête à travers le système, étape par étape, avec le temps passé à chacune.

Ce guide explique comment marche Tempo, comment l'application est instrumentée, et décortique l'incident mémoire (ballast) rencontré à la mise en service. Le pourquoi des choix est dans l'ADR 027.

1. Trace, span : le vocabulaire

  • Un span = une opération unitaire chronométrée (ex. « requête HTTP GET /posts », ou « requête SQL SELECT ... »), avec un début, une durée, et des attributs.
  • Une trace = un arbre de spans qui partagent le même trace ID. Le span racine est l'entrée (la requête HTTP), ses enfants sont les sous-opérations (appels DB...).

Visuellement, une trace est une cascade (waterfall) :

GET /healthz/ready  ━━━━━━━━━━━━━━━━━━  3.8 ms   (span HTTP, racine)
  └─ SELECT 1       ━━━━━━━            3.1 ms   (span SQL, enfant)

On voit d'un coup d'œil que l'essentiel du temps est passé dans la DB.

2. Ce que Tempo fait (et ne fait pas)

Tempo est le backend de traces : il reçoit, stocke et ressort les traces.

Sa particularité : Tempo n'indexe que le trace ID, pas le contenu des spans.

Analogie : Tempo est un entrepôt de colis rangés par numéro de suivi. Tu donnes le numéro, il sort le colis instantanément. Pour « tous les colis rouges », il doit parcourir les rayons (c'est ce que fait la recherche TraceQL : un scan des blocs).

C'est ce qui rend Tempo très léger en stockage : pas de gros index façon Elasticsearch (que Jaeger impose). C'est la raison du choix Tempo plutôt que Jaeger (ADR 027), d'autant qu'il s'affiche nativement dans Grafana, déjà en place.

3. La chaîne complète

flowchart LR
    APP["FastAPI<br/>SDK OpenTelemetry<br/>(ns fastapi)"] -->|"OTLP/HTTP :4318"| COL["OTel Collector<br/>gateway<br/>(ns tracing)"]
    COL -->|"OTLP/gRPC :4317"| TEMPO["Tempo<br/>single-binary<br/>(ns tracing)"]
    TEMPO -->|"écrit / lit"| DISK[("/var/tempo<br/>emptyDir<br/>WAL + blocks")]
    GRAF["Grafana"] -->|"requête :3200"| TEMPO

    style APP fill:#e1f5ff
    style COL fill:#fff3cd
    style TEMPO fill:#d4edda
    style GRAF fill:#f8d7da
  • FastAPI génère les spans et les pousse au Collector en OTLP/HTTP.
  • OTel Collector (pattern gateway) met en lot (batch), pourra échantillonner un jour, et relaie à Tempo. Il découple l'app du backend : changer Tempo ne touche pas le code.
  • Tempo ingère et écrit sur /var/tempo.
  • Grafana interroge Tempo pour afficher la cascade.

Pourquoi un Collector au milieu plutôt qu'un export direct vers Tempo ? Parce que c'est l'architecture de prod : un point unique de contrôle (batch, retry, sampling, enrichissement) sans toucher chaque application. Détail dans l'ADR 027.

4. L'intérieur du single-binary

En mode monolithic, Tempo fait tourner tous ses composants dans un seul process (en prod distribuée ils seraient sur des pods séparés, façon tempo-distributed). Sur un cluster éphémère, le monolithic suffit (analogue de Loki SingleBinary).

flowchart TD
    IN["OTLP receiver<br/>(reçoit les spans)"] --> ING["Ingester<br/>buffer EN MÉMOIRE"]
    ING -->|"écrit en continu"| WAL[("WAL<br/>/var/tempo/wal")]
    ING -->|"flush périodique"| BLK[("Blocks<br/>/var/tempo/traces")]
    BLK --> COMP["Compactor<br/>fusionne les petits blocs"]
    Q["Querier"] -->|"cherche par trace ID"| BLK
    Q --> WAL

    style IN fill:#fff3cd
    style ING fill:#d4edda
    style WAL fill:#e1f5ff
    style BLK fill:#e1f5ff
  1. L'ingester garde les spans entrants en mémoire le temps de constituer un bloc, tout en les écrivant dans le WAL (sécurité anti-crash).
  2. Périodiquement, il flush en blocs sur disque.
  3. Le compactor fusionne les petits blocs.
  4. Le querier lit dans le WAL + les blocs.

À retenir : l'ingester travaille en mémoire, donc Tempo consomme de la RAM par nature. Mais une consommation anormalement haute pour peu de trafic est le signe d'un problème (voir l'incident ballast, section 7).

5. L'instrumentation côté application

L'app est instrumentée dans app/tracing.py, branché depuis main.py :

  • Auto-instrumentation FastAPI : un span par requête HTTP, avec propagation du contexte W3C traceparent (pour relier les services entre eux).
  • Auto-instrumentation SQLAlchemy : un span par requête SQL, qui capture le temps réel passé dans la base (et les attributs : db.statement, db.system, le serveur RDS visé...). On a préféré ça à des spans custom écrits à la main : c'est moins de code et ça trace les vraies requêtes.
  • Export OTLP/HTTP vers le Collector.

Point clé : le tracing est conditionnel.

def setup_tracing(app, engine) -> bool:
    if not os.getenv("OTEL_EXPORTER_OTLP_ENDPOINT"):
        return False   # no-op : local et tests tournent sans tracing
    ...

Si la variable OTEL_EXPORTER_OTLP_ENDPOINT n'est pas présente (développement local, tests), setup_tracing ne fait rien : l'app démarre sans tracing ni erreur d'export. En prod EKS, le Deployment injecte cette variable et le tracing s'active.

6. La corrélation des 3 piliers

La vraie valeur d'une stack unifiée : naviguer métrique → trace → log dans une seule interface (Grafana).

  • Métrique → trace : un exemplar Prometheus attache un trace ID à un point de métrique (évolution prévue, voir section 8).
  • Trace → log : la datasource Tempo est configurée avec tracesToLogsV2, qui ajoute un bouton « Logs » sur un span. Un clic ouvre Loki sur le même pod et la même fenêtre temporelle.
flowchart LR
    M["Métrique RED<br/>(Prometheus)"] -->|"exemplar (trace ID)"| T["Trace<br/>(Tempo)"]
    T -->|"tracesToLogsV2"| L["Logs<br/>(Loki)"]
    style M fill:#fff3cd
    style T fill:#d4edda
    style L fill:#e1f5ff

7. Incident décortiqué : le ballast mémoire (OOM)

À la mise en service, tempo-0 redémarrait en boucle : OOMKilled, exit 137. Le réflexe (« augmenter la limite mémoire ») n'a pas marché : OOM à 256Mi, puis OOM encore à 512Mi. Le kubectl top montrait ~464Mi pour un trafic de traces quasi nul : anormal. La cause n'était pas la limite, mais un mauvais réglage de la GC Go.

7.1 Comment Go gère sa mémoire

Go a un ramasse-miettes (GC). Réglage par défaut GOGC=100 :

La GC se déclenche quand le tas (heap) a doublé depuis la dernière collecte.

Si après une GC il reste 20Mi vivants, Go laisse grimper jusqu'à 40Mi puis collecte. La cible est toujours 2 × heap_vivant.

7.2 Le ballast, un hack obsolète

Un ballast est une grosse allocation bidon gardée vivante exprès :

ballast := make([]byte, 1024*1024*1024)  // 1 Go, jamais utilisé

Avant Go 1.19, sur un service à faible heap, la GC se déclenchait trop souvent (CPU gaspillé). Le ballast gonfle artificiellement le « heap vivant » → la GC se déclenche moins souvent → moins de CPU. Le chart Tempo garde memBallastSizeMbs: 1024 par défaut, pensé pour de gros déploiements.

7.3 Pourquoi ça explose dans un conteneur limité

Le piège : Go ne connaît pas la limite cgroup de Kubernetes.

flowchart TD
    B["Ballast 1 Go<br/>(heap vivant artificiel)"] --> T["Go vise ~2 Go<br/>avant de collecter"]
    T --> G["La GC ne se déclenche jamais<br/>(on n'atteint jamais 2 Go)"]
    G --> R["La RSS réelle grimpe<br/>(ingester, WAL...)"]
    R --> C{"RSS atteint<br/>la limite cgroup ?"}
    C -->|"OUI, avant la GC"| OOM["OOMKilled (exit 137)"]
    style B fill:#fff3cd
    style OOM fill:#f8d7da
  1. Le ballast dit à Go : « tu as ~1 Go de heap, attends ~2 Go avant de collecter ».
  2. Go retarde la GC (il croit avoir de la marge).
  3. La mémoire réelle grimpe avec l'activité...
  4. ... et percute la limite cgroup AVANT que Go collecte.
  5. Le kernel tue le process → OOMKilled.

D'où l'inutilité d'augmenter la limite : la cible GC reste toujours au-dessus.

AVEC ballast (cible GC hors écran) :        SANS ballast (cible GC = 2 x ~20Mi) :
mém |            /// X  OOM (512Mi)          mém | /\    /\    /\
    |        ///                                 |/  \  /  \  /  \   GC à ~40Mi
    |    ///       monte tout droit              |    \/    \/       stable et bas
    +-----------> temps                          +-----------> temps

7.4 Le fix et la bonne pratique moderne

Le fix : memBallastSizeMbs: 0 (désactiver le ballast). La GC par défaut suffit largement → Tempo idle retombe à ~40Mi (12x moins), stable.

Depuis Go 1.19, la bonne solution n'est plus le ballast mais GOMEMLIMIT : on dit à Go « ne dépasse pas X mémoire », et il déclenche la GC de plus en plus agressivement en approchant. C'est le réglage adapté à un conteneur.

Leçon transposable : « ça OOM » ne veut pas dire « il manque de RAM ». Ici Tempo n'avait besoin que de ~40Mi. Les requests/limits Kubernetes ne pilotent pas la GC d'un runtime : pour Go (GOMEMLIMIT) comme pour la JVM (-XX:MaxRAMPercentage), il faut un knob côté runtime. Et sur un workload contraint, toujours auditer les défauts mémoire d'un chart Helm.

8. Visualiser, et aller plus loin

On consulte une trace dans Grafana → Explore → datasource Tempo → Search (par service.name, ou en TraceQL { resource.service.name = "fastapi" }), puis on ouvre la cascade.

Le service graph (#117)

Le metrics-generator de Tempo (activé en #117) dérive, depuis les traces déjà ingérées et sans toucher au code applicatif, deux familles de métriques Prometheus :

  • service_graphs : reconstruit la topologie de service (qui appelle qui, latence par arête) à partir de la structure parent/enfant des spans.
  • span_metrics : des métriques RED (taux de requêtes, erreurs, latence) par service, dérivées des traces — une source différente des métriques HTTP déjà exposées par prometheus-fastapi-instrumentator (#73), utile en recoupement.
flowchart LR
    subgraph Tempo
        T[Traces ingerees] --> MG[metrics-generator]
    end
    MG -- remote_write --> P[(Prometheus)]
    P --> G[Grafana]
    G -- "Node Graph" --> SG[Service Graph<br/>fastapi -&gt; fastapi_db]

Ce chemin exige d'activer explicitement la réception remote_write côté Prometheus (enableRemoteWriteReceiver: true sur prometheusSpec — off par défaut, le chart n'ouvre pas un endpoint d'écriture sans opt-in). Côté Grafana, la datasource Tempo pointe vers la datasource Prometheus (serviceMap.datasourceUid) pour résoudre les métriques du graphe, et nodeGraph.enabled: true active l'onglet correspondant dans l'explorateur de traces.

Sur ce projet, le graphe reste minimal (un seul service applicatif + sa DB) : la valeur est dans le mécanisme démontré (dérivation de métriques depuis des traces, sans nouvelle instrumentation), pas dans la taille du graphe.

Exemplars (enableFeatures: [exemplar-storage]) : lien direct depuis un point d'une courbe Prometheus vers la trace exacte qui l'a produit. Posé en bonus (pas un critère de done #117) — Prometheus les expose derrière un feature flag non stable.

9. Les pièges rencontrés à la mise en service

Trois pièges, capitalisés (utiles en entretien) :

  1. NetworkPolicy egress : le ns fastapi est en default-deny egress. L'app ne pouvait pas joindre le Collector (Failed to export span batch due to timeout en boucle, Cilium enforce). Fix : une règle egress vers le ns tracing port 4318. Leçon : un nouveau backend dans un autre namespace réclame une ouverture egress explicite.
  2. ballast mémoire : voir section 7.
  3. Access entry EKS : au premier aws-start, le kubectl get nodes de vérification a échoué en Forbidden (l'access entry du user CI pas encore propagée). Le terraform apply avait réussi : un simple retry du job suffit.
  4. OOM au boot malgré le ballast désactivé (#125) : tempo-0 a été observé OOMKilled 1x pendant la fenêtre de démarrage (46Mi stable ensuite, !210 tient). Le vrai coupable résiduel : sampling 100 % (Décision 4) + probes liveness/readiness toutes les 10s + scrape Prometheus, tracés comme du trafic réel dès la 1re seconde. Fix : OTEL_PYTHON_EXCLUDED_URLS=healthz,metrics sur le Deployment FastAPI — réduit le volume de spans à la source, lu nativement par le SDK OTel (aucun changement dans app/tracing.py). Leçon : sur un système qui redémarre à froid, le pic transitoire au boot peut peser plus que le régime stable mesuré après coup.

Décision et justifications : ADR 027.