[Java][Profiling] Async-profiler + OpenTelemetry spans | JVM/Java profiling and tuning
Skip to the content.
[Java][Profiling] Async-profiler + OpenTelemetry spans
Spans in tracing
The word span doesn’t come from the profiling world, it comes from the distributed tracing one.<br>Before we start playing with the async-profiler, let’s agree on what a span is there, since the profiler<br>borrows both the name and the idea. The most popular tracing standard nowadays is<br>OpenTelemetry, so let’s use it<br>as an example.
Imagine a very simple e-commerce system. A user clicks “buy” and the request travels through a few<br>services:
gateway ---> order-service ---> payment-service<br>---> warehouse-service ---> database
From the user’s perspective this is one operation that either succeeded or not, and either was fast<br>or was slow. From the infrastructure perspective it is a handful of HTTP calls, a few database queries,<br>maybe a message on a queue, executed by different threads on different machines, each of them producing<br>its own logs. Tracing is a technique of gluing all of that back together into a single picture.
Two definitions:
Span - a single unit of work, with a name, a start timestamp and a duration. It can be<br>POST /orders, SELECT * FROM ORDERS, or just a plain method call like calculateDiscount.
Trace - the whole tree of spans that belongs to one end-to-end operation.
Span context
Every span carries a span context . The three fields that matter for us are:
traceId - 16 bytes (32 hex characters), the same for every span in the trace
spanId - 8 bytes (16 hex characters), unique for that particular span
parent spanId - empty for the root span
The last one is what makes a trace a tree, and not just a bag of spans. For our “buy” request it may<br>look like this:
traceId = 4bf92f3577b34da6a3ce929d0e0e4736
spanId=00f067aa0ba902b7 POST /orders [=================================] 850ms<br>spanId=a2fb4a1d1a96d312 HTTP POST /payments [=======] 190ms<br>spanId=b9c7c989f97918e1 INSERT INTO PAYMENTS [==] 55ms<br>spanId=eee19b7ec3c1b174 HTTP POST /reservations [==========================] 620ms<br>spanId=00b976fa8a4d2f1c SELECT ... FROM WAREHOUSE [=========================] 600ms
Every service reports its own spans, they are shipped to some collector, and the collector<br>groups them by traceId and rebuilds the tree using the parent spanId. This is exactly what you see<br>in Jaeger, Zipkin, Grafana Tempo or any commercial APM.
Besides the context, a span can also carry:
attributes - key/value pairs, like http.response.status_code=200 or db.system=postgresql
events - timestamped messages inside the span, exceptions are usually reported that way
status - UNSET, OK or ERROR
kind - SERVER, CLIENT, INTERNAL, PRODUCER or CONSUMER
How the spans are created
In the OpenTelemetry Java API, you create a span manually like this:
Tracer tracer = openTelemetry.getTracer("com.example.orders");
Span span = tracer.spanBuilder("processOrder")<br>.setAttribute("order.id", orderId)<br>.startSpan();
try (Scope scope = span.makeCurrent()) {<br>processOrder(orderId);<br>} catch (Exception e) {<br>span.recordException(e);<br>span.setStatus(StatusCode.ERROR);<br>throw e;<br>} finally {<br>span.end();
Three things are worth noticing here, because we will see the very same pattern in the async-profiler<br>later on:
the span is started and ended explicitly, the difference between those two timestamps is the<br>duration
span.makeCurrent() puts the span into a ThreadLocal, so that any code executed below can find out<br>“in which span am I running right now?” - this is what all the instrumentation libraries use
the Scope has to be closed on the same thread that opened it
In practice you rarely write that code yourself. The OpenTelemetry Java agent instruments the popular<br>frameworks and libraries for you, and in a Spring Boot 3 application you get Micrometer Tracing ,<br>which can bridge to OpenTelemetry, out of the box.
Context propagation
The traceId alone would be useless if it stopped at the service boundary. When order-service<br>calls payment-service, the span context is serialized into an HTTP header - the<br>W3C Trace Context standard calls it<br>traceparent:
traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01<br>^ ^ ^ ^<br>| | | flags (sampled)<br>| traceId parent spanId<br>version
The receiving service reads that header, and every span it creates inherits the same traceId. That’s<br>the whole magic. The same mechanism works for messaging systems, where the context is put into the<br>message headers instead.
What tracing gives you, and what it doesn’t
Let’s go back to our waterfall. It tells us a lot:
the whole request took 850ms
620ms of that was spent in warehouse-service
and almost all of it, 600ms, was a single database query
That is a great starting point for an investigation, and very often it is enough. But now let’s change<br>the example a little bit:
traceId = 4bf92f3577b34da6a3ce929d0e0e4736
spanId=00f067aa0ba902b7 POST /orders [=================================]...