Distributed tracing/Tutorial/Start
Distributed tracing starts with a single incoming request from a user, and tracks and records all the sub-queries issued between different microservices to handle that higher-level request.
In this tutorial, we'll present several example traces alongside with explanation. Then we'll give a quick tour through the search interface provided by Jaeger, the open-source tracing system we use.
Introduction
Jaeger's user interface presents a chart with time running left to right. Each row on the chart is a "span": some unit of work deemed worthy of being traced. A span is often (but not always) a HTTP request. Other times it might be something that is essentially an RPC, like a query to a database server. Rarely, it might be an expensive function call, or some other long-running unit of work.
Spans have metadata: most importantly, they have a start and end timestamp, to represent a timespan. They also have other metadata like a service name (mw-debug) and an operation name (GET https://en.wikipedia.org/wiki/Special:Version). They can also have a freeform set of key/value pairs called attributes.[1]
Spans can also have parent/child relationships with each other. Child spans indicate pieces of work that are part of the work of handling their parent span.
Reading a first example trace
For our first "hello world" trace, let's look at an application server answering a query for the Special:Version page on English Wikipedia.
The span at the root of this trace was created by our Envoy service mesh as it received this request, and that span ends as soon as Envoy receives a complete response from MediaWiki. For most services that receive external user traffic, our Envoys are configured to randomly begin tracing a small fraction of requests. When a request is selected for random sampling, that tracing flag will follow it "all the way down the stack".
Because MediaWiki knows how to propagate tracing context, our service mesh automatically creates spans for all HTTP client calls made to other services in order to handle this request.
In this case of Special:Version, we can see there's quite a few sub-requests made by MediaWiki so it can handle this user request:
- Two calls to SessionStorage, to validate this logged-in user (MW wouldn't make these requests for an anonymous fetch)
- A call made to Shellbox, to fetch the version number of the Lilypond musical rendering software used by Extension:Score
- A call made to Search, also to query its software version.
These first calls are all made before MediaWiki begins the bulk of its work rendering content for the page, and so they appear in the first 200 milliseconds of the trace.
Unfortunately as of this writing (September 2024) it is not yet possible for PHP code inside MediaWiki to emit spans, so there's now a long "blind spot" in this trace until towards the end of the query. We hope to address this soon (see T340552). In this query, the internal MediaWiki-only time is about 1 second.
In the final 200 milliseconds of the request, we see three more HTTP calls: two to EchoStore, the datastore behind user notifications. Then we see one last call made to EventGate to record some information about the pageview in Analytics. If we zoom in and look closely at this span, we can see it begins after its parent span, the user-facing HTTP request, has already ended. This is actually what happens! The response is returned to the user, but some background processing continues on the appserver process. MediaWiki refers to this performance optimization as a "deferred update".
Next up
Footnotes
- ↑ For more on the data model, see OpenTelemetry's docs.