Trace in .NET con OpenTelemetry: le metriche dicono quanto, le trace dicono dove

Le metriche dicono che la firma di un documento ci mette più di due secondi. Ma lenta dove? La richiesta passa dallo storage, dal provider di firma remoto, dal database, poi da un’Outbox e dal sistema di notifiche. I log raccontano pezzi sparsi, uno per servizio.

Le trace seguono una richiesta in tutto il suo percorso, anche tra servizi diversi, e mostrano quanto pesa ogni tratto. Le metriche dicono quanto, le trace dicono dove.

Trace, span e contesto

Tre parole bastano per capire tutto il resto.

Ogni trace ha un trace id (16 byte) e ogni span uno span id (8 byte). Uno span nuovo eredita il trace id del padre e si annota lo span id del padre: è così che gli strumenti ricostruiscono l’albero.

Per passare da un servizio all’altro il contesto viaggia in un formato standard, il W3C Trace Context. Su HTTP è l’header traceparent:

00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01

Versione, trace id, span id del padre, flag. L’ultimo, 01, dice che la trace è campionata: ci torniamo più avanti.

In .NET uno span si chiama Activity

Activity esiste in .NET da prima di OpenTelemetry, e il nome è rimasto. La corrispondenza è diretta: uno span è un’Activity, e le Activity nascono da un’ActivitySource, come gli strumenti delle metriche nascono da un Meter.

Il modello è lo stesso delle metriche: l’API sta nel runtime, chi raccoglie i dati si iscrive alle sorgenti per nome. Se nessuno ascolta, StartActivity restituisce null e non crea niente: per questo nel codice si scrive sempre activity?..

1. La sorgente

public static class FirmaTracing
{
    public const string Name = "DocumentaleInventato.Firma";

    public static readonly ActivitySource Source = new(Name);
}

Qui un campo statico va bene, ed è quello che consiglia la documentazione: a differenza del Meter, per ActivitySource non c’è una factory nella dependency injection. Il nome è una costante perché serve anche nella configurazione.

2. Collegarle a OpenTelemetry

Ai pacchetti dell’articolo sulle metriche si aggiunge OpenTelemetry.Instrumentation.Http, per le chiamate in uscita.

builder.Services.AddOpenTelemetry()
    .WithTracing(t => t
        .AddSource(FirmaTracing.Name)
        .AddAspNetCoreInstrumentation()
        .AddHttpClientInstrumentation()
        .AddOtlpExporter());

Le richieste HTTP in entrata e in uscita diventano span da sole. Per i nostri serve AddSource, con lo stesso nome della sorgente. WithTracing e WithMetrics stanno sulla stessa catena: una sola configurazione, lo stesso exporter OTLP.

3. Uno span nostro

Il lavoro da misurare è la firma: aprire il documento dallo storage e mandarlo al provider.

using var activity = FirmaTracing.Source.StartActivity("firma.esegui");

activity?.SetTag("firma.id", r.Id);
activity?.SetTag("firma.provider", "aruba");

await using var file = await storage.ApriAsync(r.DocumentoId, ct);
await using var firmato = await provider.FirmaAsync(file, ct);

Lo span parte con StartActivity e finisce quando lo using chiama Dispose. Mentre è attivo diventa Activity.Current, e gli span creati nel frattempo, come la chiamata HTTP al provider, diventano suoi figli senza scrivere altro.

Il nome dello span descrive l’operazione, non il caso: firma.esegui, non firma 7f3a…. Gli strumenti raggruppano gli span per nome; i dettagli vanno nei tag.

4. Gli errori

Uno span sa anche se è andato bene. Quando qualcosa fallisce lo si marca in errore e si allega l’eccezione:

using var activity = FirmaTracing.Source.StartActivity("firma.esegui");

try
{
    // storage e provider, come sopra
}
catch (Exception ex) when (ex is not OperationCanceledException)
{
    activity?.SetStatus(ActivityStatusCode.Error, ex.Message);
    activity?.AddException(ex);
    throw;
}

SetStatus cambia lo stato dello span (che parte da Unset), e nella trace lo span appare rosso. AddException, da .NET 9, aggiunge un evento con tipo, messaggio e stack dell’eccezione. Il filtro when è lo stesso dell’articolo sul CancellationToken: un client che se ne va non è un errore.

I tag: qui gli id vanno bene

Nelle metriche ogni valore di un tag moltiplica le serie, e gli id sono vietati. Nelle trace no: ogni span è un record a sé, e un tag in più costa qualche byte. Anzi, l’id è proprio quello che serve per ritrovare quella firma.

Il campionamento

C’è un rovescio. Una metrica costa uguale con mille o un milione di richieste: è sempre lo stesso contatore che sale. Una trace invece costa per ogni richiesta. Con 100 firme al secondo e cinque span per firma sono più di 43 milioni di span al giorno, da spedire, conservare e indicizzare. Per questo le trace si campionano: se ne tiene una parte. Con il 10% restano comunque 864.000 trace al giorno, più che sufficienti per capire dove si perde il tempo.

La domanda è quando decidere quali tenere: all’inizio della richiesta o alla fine.

All’inizio: head sampling

.WithTracing(t => t
    .SetSampler(new ParentBasedSampler(new TraceIdRatioBasedSampler(0.1)))
    .AddSource(FirmaTracing.Name)

TraceIdRatioBasedSampler(0.1) non tira a sorte: legge i primi 8 byte del trace id, che è casuale, come un numero, e tiene la trace se cade nel primo 10% dei valori possibili. Lo stesso trace id dà sempre la stessa risposta.

ParentBasedSampler fa in modo che decida solo l’inizio della trace. Seguiamo una firma:

1. La richiesta arriva senza traceparent: è l’inizio di una trace nuova, e decide il TraceIdRatioBasedSampler. Diciamo che la tiene.
2. La chiamata al provider parte con il flag 01 in fondo al traceparent.
3. Il servizio delle notifiche riceve il messaggio, vede 01 e tiene i suoi span senza chiedersi altro.

Se al punto 1 la trace viene scartata, il flag è 00 e tutti gli altri scartano a loro volta: il contesto viaggia lo stesso, ma nessuno span viene esportato. Senza ParentBasedSampler ogni servizio applicherebbe le sue regole: basta una percentuale diversa e la stessa trace viene tenuta in un servizio e scartata in un altro, e arriva a pezzi. Il default di OpenTelemetry è ParentBased con “tieni tutto”.

Il limite: si decide all’inizio, quando non si sa ancora come andrà la richiesta. Su 1.000 firme, 10 falliscono. Con il 10% si tengono circa 100 trace, e in media una sola delle 10 in errore: proprio quelle che interessano finiscono quasi tutte nel 90% scartato.

Alla fine: tail sampling

Il rimedio è decidere quando la trace è completa. Lo fa l’OpenTelemetry Collector, il servizio che riceve la telemetria via OTLP e la inoltra agli strumenti, con il processore tail_sampling della distribuzione contrib:

processors:
  tail_sampling:
    decision_wait: 10s
    policies:
      - name: errori
        type: status_code
        status_code:
          status_codes: [ERROR]
      - name: lente
        type: latency
        latency:
          threshold_ms: 5000
      - name: il-resto
        type: probabilistic
        probabilistic:
          sampling_percentage: 10

Una trace si tiene se almeno una regola la vuole. Sulle stesse 1.000 firme: le 10 in errore ci sono tutte, più circa 100 delle altre. Lo SetStatus(ActivityStatusCode.Error) della sezione 4 serve anche a questo.

Qualche dettaglio da sapere:

• Il Collector sceglie solo tra le trace che riceve: i servizi devono mandargliele tutte. In Program.cs basta togliere SetSampler e tornare al default.
• decision_wait è quanto il Collector aspetta gli span di una trace prima di decidere, tenendoli in memoria; il default è 30 secondi. Deve coprire tutta la trace: nel nostro esempio la pubblicazione arriva un secondo dopo la firma, per via dell’Outbox. Gli span in ritardo seguono la decisione già presa: se l’errore è proprio in uno di quelli, il Collector non l’ha visto.
• La latenza è quella dell’intera trace, dal primo span che parte all’ultimo che finisce, attesa nell’Outbox compresa. Con una soglia a 2 secondi anche firme normali risulterebbero lente per quell’attesa: per questo è a 5.
• Con più istanze del Collector, tutti gli span di una trace devono arrivare alla stessa: è il compito del loadbalancing exporter, messo davanti.

Per partire basta l’head sampling, o anche tenere tutto finché il traffico lo permette. Il tail sampling serve quando le trace scartate cominciano a essere proprio quelle che cercavi.

Il contesto tra i servizi

Su HTTP il contesto viaggia da solo: HttpClient aggiunge l’header traceparent, e ASP.NET Core lo legge dall’altra parte e crea lo span del server come figlio.

Con un’Outbox no. L’Outbox è una tabella in cui il servizio scrive il messaggio da pubblicare, nella stessa transazione dei dati; un worker separato la legge e pubblica sul broker, anche secondi dopo. Activity.Current vive nel flusso della richiesta: il worker gira in un altro flusso, dove non c’è nessuna Activity. Il messaggio parte senza contesto e il filo si spezza: la pubblicazione e le notifiche finiscono in trace separate, scollegate dalla firma.

Il rimedio è salvare il contesto insieme al messaggio.

5. Nell’Outbox, una colonna in più

db.Outbox.Add(new OutboxMessage
{
    Tipo = "DocumentoFirmato",
    Payload = payload,
    TraceParent = Activity.Current?.Id
});
await db.SaveChangesAsync(ct);

Activity.Current?.Id, con il formato W3C che .NET usa di default, è proprio il valore di traceparent: trace id e span id della firma in corso.

6. Dall’altra parte, riprendere il filo

ActivityContext.TryParse(m.TraceParent, null, out var parent);

using var activity = FirmaTracing.Source.StartActivity(
    "outbox.pubblica", ActivityKind.Producer, parent);

await bus.PubblicaAsync(m.Id, m.Tipo, m.Payload, activity?.Id, ct);

Il worker ricostruisce il contesto dalla colonna e lo usa come padre: lo span di pubblicazione diventa figlio della firma, anche se parte quando la firma è finita da un pezzo. ActivityKind.Producer dice agli strumenti che lo span invia un messaggio. E activity?.Id, passato al broker, porta il filo fino a chi riceve le notifiche.

Padre o link?

Usare il contesto salvato come padre dà una trace unica, dall’inizio alla notifica. È la scelta più leggibile quando un messaggio viene pubblicato da solo.

Le convenzioni di OpenTelemetry per i messaggi, però, suggeriscono di default un’altra strada: il link. Il padre lo ammettono solo in casi limitati, quando si tratta un messaggio alla volta. Lo span di pubblicazione apre una trace sua e si collega a quella della firma, senza diventarne figlio.

using var activity = FirmaTracing.Source.StartActivity(
    "outbox.pubblica", ActivityKind.Producer, parentContext: default,
    links: [new ActivityLink(parent)]);

Il motivo: uno span ha un solo padre, ma può avere tanti link. Se il worker pubblica cinquanta messaggi in un colpo solo, con un unico span, i link sono l’unico modo per collegarlo a cinquanta firme diverse. Il padre è una scelta pratica, che dà la trace più facile da leggere, finché i messaggi si pubblicano uno alla volta; con i batch servono i link.

Come si legge una trace

Gli strumenti mostrano una trace come una cascata: una riga per span, rientrata sotto il padre, con una barra lunga quanto la durata. Con dati di esempio:

La lettura è immediata: il provider remoto pesa il 95% della firma. Ottimizzare lo storage o il database servirebbe a poco; la domanda giusta è come ridurre o rendere asincrona l’attesa del provider.

E c’è un buco: la firma finisce a 2,41 secondi, la pubblicazione parte a 3,42. È il tempo che il messaggio passa nell’Outbox prima che il worker lo prenda. Senza il contesto salvato, quel secondo non comparirebbe in nessuna trace.

Dove vederle

Gli strumenti sono quelli che accettano OTLP, come per le metriche.

• Dashboard di Aspire, in locale: la stessa dell’articolo sulle metriche, con trace, metriche e log insieme.
• Jaeger: open source, nato per le trace.
• Grafana Tempo: conserva le trace accanto alle metriche di Prometheus, nella stessa Grafana.

C’è anche un legame con i log: ILogger registra il trace id e lo span id dell’Activity corrente. Se anche i log passano da OpenTelemetry e finiscono nello stesso strumento, da una trace si arriva ai log scritti durante quella richiesta, e da un log di errore alla trace che lo ha prodotto.

builder.Logging.AddOpenTelemetry(l => l.AddOtlpExporter());

In breve

1. Un’ActivitySource per il modulo, statica, con un nome costante.
2. AddSource con lo stesso nome e un exporter OTLP.
3. Tag con gli id che servono, stato ed eccezione sugli errori.
4. Un campionamento che decide all’inizio e vale per tutta la trace.
5. Il traceparent viaggia con il messaggio, anche attraverso l’Outbox.

Codice semplificato a scopo di esempio: nomi e struttura servono a dare l'idea, non sono da copiare così.