Distributed Tracing
Record spans with ActivitySource, carry trace context across service boundaries, and read a waterfall to find the slow call.
using Activity? activity = source.StartActivity("ChargeCard", ActivityKind.Client);One request to your service may cause calls to three other services and two databases. A log line from each of them, scattered across five machines, will not tell you which one was slow. Distributed tracing exists to answer that.
Spans and traces
A span is one timed unit of work: handling a request, running a query, calling another service. Each span records a start time, a duration, a name, tags and a status. A trace is all the spans belonging to one original request, arranged as a tree by each span naming its parent.
In .NET the span class is called Activity, which predates the word span, and you create spans from an ActivitySource. Starting a span while another is current makes the current one its parent automatically, so the tree builds itself as calls nest.
Across a service boundary
Every trace has a 16 byte trace id, and every span an 8 byte span id. To continue a trace in another process, those ids travel in an HTTP header called traceparent, defined by the W3C TraceContext standard, which has been the default format since .NET 5. HttpClient adds the header on the way out and ASP.NET Core reads it on the way in, both without any code from you.
Reading a waterfall
A trace viewer draws each span as a bar on a time axis. Look for the longest bar with no children, which is where the time actually went, and for gaps between bars, which is time spent in your own code rather than waiting on anything.
Shorthand
activity?.SetTag("k", v) is the same as if (activity != null) { activity.SetTag("k", v); }. You need one of them, because StartActivity returns null when nothing is listening.
Example
using System.Diagnostics;
// One ActivitySource per component is enough.
var source = new ActivitySource("Shop.Checkout", "1.0.0");
// A listener is normally the telemetry library. Without one, StartActivity
// returns null and nothing is recorded.
var listener = new ActivityListener
{
ShouldListenTo = candidate => candidate.Name == "Shop.Checkout",
Sample = (ref ActivityCreationOptions<ActivityContext> options) =>
ActivitySamplingResult.AllData,
ActivityStopped = activity => Console.WriteLine(
$"{activity.DisplayName} parent={activity.Parent?.DisplayName ?? "none"}")
};
ActivitySource.AddActivityListener(listener);
// The outermost span is the root of the trace.
using (Activity? checkout = source.StartActivity("Checkout", ActivityKind.Server))
{
checkout?.SetTag("order.id", 4711);
// Started while Checkout is current, so Checkout becomes the parent.
using (Activity? charge = source.StartActivity("ChargeCard", ActivityKind.Client))
{
charge?.SetStatus(ActivityStatusCode.Ok);
}
using (Activity? email = source.StartActivity("QueueEmail", ActivityKind.Producer))
{
email?.SetTag("template", "receipt");
}
}
// Output:
// ChargeCard parent=Checkout
// QueueEmail parent=Checkout
// Checkout parent=noneWhen to use it
- Find which of five services adds 300 ms to a slow checkout.
- Attach an order id to a span so one customer complaint can be located in the trace store.
- Tie a failing downstream call to the exact request that caused it.
- See whether time went into waiting on a database or into your own code between calls.
More examples
The header that joins two services
This is what HttpClient sends when an Activity is current, and what ASP.NET Core parses on arrival to set the incoming span's parent. Knowing the format matters when a trace comes out broken: if the downstream spans form a separate trace, something in between dropped or rewrote this header, which proxies and message queues often do.
GET /payments/4711 HTTP/1.1
Host: payments.internal
traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
# 00 version
# 4bf92f3577b34da6a3ce929d0e0e4736 trace id, same for every span in the trace
# 00f067aa0ba902b7 span id of the caller, the parent
# 01 flags; 01 means this trace is sampledA span around a dependency call in an endpoint
The span is disposed when the method returns, which stops it and records its duration, and that happens correctly after an await because the current activity flows with the async call. Setting Error status in the catch is what makes the failure visible as a red bar in the viewer instead of a successful span that happens to be followed by an exception log.
using System.Diagnostics;
public sealed class OrderReader
{
// Static and shared. Creating a source per call would be wasteful.
private static readonly ActivitySource Source = new("Shop.Orders");
private readonly HttpClient _client;
public OrderReader(HttpClient client) => _client = client;
public async Task<string> ReadAsync(int id, CancellationToken token)
{
using Activity? activity = Source.StartActivity("ReadOrder");
activity?.SetTag("order.id", id);
try
{
// HttpClient starts its own child span and sends traceparent.
return await _client.GetStringAsync($"/orders/{id}", token);
}
catch (HttpRequestException ex)
{
activity?.SetStatus(ActivityStatusCode.Error, ex.Message);
throw;
}
}
}Sampling, so tracing stays affordable
Recording every span of every request costs CPU in the app and money in the backend. A ratio sampler keeps a tenth of traces and drops the rest, and because the decision travels in the traceparent flags, every service in the trace makes the same choice, so you get whole traces rather than fragments. Keep sampling at 1.0 while you are building the instrumentation and lower it when the volume is real.
// Package: OpenTelemetry.Extensions.Hosting
builder.Services.AddOpenTelemetry()
.WithTracing(tracing => tracing
.AddAspNetCoreInstrumentation()
.SetSampler(new TraceIdRatioBasedSampler(0.1))
.AddOtlpExporter());
Discussion