[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. Before we start playing with the async-profiler, let’s agree on what a span is there, since the profiler borrows both the name and the idea. The most popular tracing standard nowadays is OpenTelemetry, so let’s use it as an example.

Imagine a very simple e-commerce system. A user clicks “buy” and the request travels through a few services:

gateway ---> order-service ---> payment-service
                           ---> warehouse-service ---> database

From the user’s perspective this is one operation that either succeeded or not, and either was fast or was slow. From the infrastructure perspective it is a handful of HTTP calls, a few database queries, maybe a message on a queue, executed by different threads on different machines, each of them producing its own logs. Tracing is a technique of gluing all of that back together into a single picture.

Two definitions:

Span context

Every span carries a span context. The three fields that matter for us are:

The last one is what makes a trace a tree, and not just a bag of spans. For our “buy” request it may look like this:

traceId = 4bf92f3577b34da6a3ce929d0e0e4736

spanId=00f067aa0ba902b7  POST /orders                    [=================================] 850ms
spanId=a2fb4a1d1a96d312    HTTP POST /payments           [=======]                           190ms
spanId=b9c7c989f97918e1      INSERT INTO PAYMENTS        [==]                                 55ms
spanId=eee19b7ec3c1b174    HTTP POST /reservations       [==========================]        620ms
spanId=00b976fa8a4d2f1c      SELECT ... FROM WAREHOUSE   [=========================]         600ms

Every service reports its own spans, they are shipped to some collector, and the collector groups them by traceId and rebuilds the tree using the parent spanId. This is exactly what you see in Jaeger, Zipkin, Grafana Tempo or any commercial APM.

Besides the context, a span can also carry:

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")
        .setAttribute("order.id", orderId)
        .startSpan();

try (Scope scope = span.makeCurrent()) {
    processOrder(orderId);
} catch (Exception e) {
    span.recordException(e);
    span.setStatus(StatusCode.ERROR);
    throw e;
} finally {
    span.end();
}

Three things are worth noticing here, because we will see the very same pattern in the async-profiler later on:

In practice you rarely write that code yourself. The OpenTelemetry Java agent instruments the popular frameworks and libraries for you, and in a Spring Boot 3 application you get Micrometer Tracing, 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 calls payment-service, the span context is serialized into an HTTP header - the W3C Trace Context standard calls it traceparent:

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             ^  ^                                ^                ^
             |  |                                |                flags (sampled)
             |  traceId                          parent spanId
             version

The receiving service reads that header, and every span it creates inherits the same traceId. That’s the whole magic. The same mechanism works for messaging systems, where the context is put into the message headers instead.

What tracing gives you, and what it doesn’t

Let’s go back to our waterfall. It tells us a lot:

That is a great starting point for an investigation, and very often it is enough. But now let’s change the example a little bit:

traceId = 4bf92f3577b34da6a3ce929d0e0e4736

spanId=00f067aa0ba902b7  POST /orders                    [=================================] 850ms
spanId=a2fb4a1d1a96d312    HTTP POST /payments           [=======]                           190ms
spanId=eee19b7ec3c1b174    HTTP POST /reservations       [====]                              110ms

Where did the remaining 550ms go? Somewhere in the order-service code, between the calls. Tracing tells us that it happened, but it will never tell us why, because spans exist only where somebody - you, or the instrumentation library - decided to put them. Adding more and more spans to find out is not a great idea either: they are not free, they have to be created, stored and shipped, and you would need to know upfront where to put them, which is precisely the thing you don’t know.

Filling that gap is a job for a profiler. A profiler doesn’t care about your instrumentation, it just samples what the threads are doing. The problem is the opposite one: a profile gives you a beautiful aggregation over all the requests, while the thing you are usually asked about is that one slow request from the production incident.

This is where the async-profiler’s spans come in. As we will see in the next sections, an async-profiler span is a much simpler structure than the OpenTelemetry one. There is no spanId, no parent, no attributes, no events. It is just a [start, end] interval on one thread, plus a single string called a tag:

long span = Span.start();
actualWork();
Span.end(span, tag);

And that’s on purpose. The profiler doesn’t need to draw a waterfall, it needs just enough information to answer one question: which samples were gathered by this thread while that span was open?

The tag is an arbitrary label, and it is entirely up to you what you put there. It can be an endpoint name like POST /orders, a message type, a tenant, a query ID. But it can also be the traceId we’ve just been talking about - and then the profiler and your tracing system start speaking the same language. Filtering the profile by a single traceId gives us a flame graph of one distributed request, with all its threads and all its services, which is exactly the “why” that the waterfall above was missing.

Feeding the profiler from your tracing

The idea of joining the two worlds is trivial:

Whenever a telemetry span becomes active, start a profiler span. Whenever it stops being active, end it, tagged with the tracing IDs.

No new instrumentation, no new decisions about “where to put the spans” - somebody has already made all of them for you, and did it in the places that matter. You are just piggybacking on that work.

The whole trick is in the words becomes active, so let’s look at them before writing any code.

The trap: a span’s lifetime is not a thread’s work

The naive implementation hooks the span lifecycle - start the profiler span when the telemetry span starts, end it when the telemetry span ends. It works in a simple synchronous application, and it breaks everywhere else, for one reason: a telemetry span is not bound to a thread, and a profiler span is.

Span.start() and Span.end() record the interval on whatever thread calls them. But an OpenTelemetry span:

Hook the lifecycle and you get spans that begin on one thread and end on another (garbage), or spans that cover 850ms of a thread’s time when only 50ms of it was actually spent on that request (worse - it looks plausible).

Fortunately OpenTelemetry already has a concept that means exactly “this thread is working under this span right now”, and it is the Scope:

try (Scope scope = span.makeCurrent()) {
    // this thread, and only this thread, is now working on `span`
}

The Scope is thread-bound by contract - it must be closed on the thread that opened it - which is precisely the contract Span.start()/Span.end() needs. So the rule is:

Don’t hook the span. Hook the scope.

And notice that this gives us the right behaviour for free: if one telemetry span is made current five times, on three threads, we get five profiler spans carrying the same tag. That is not a bug, that is the honest answer to “which stretches of thread time were spent on this request”.

Plain OpenTelemetry

Every makeCurrent() goes through ContextStorage, and OpenTelemetry lets us wrap it. That is a single place through which every context activation in the whole application has to pass:

import io.opentelemetry.api.trace.Span;
import io.opentelemetry.api.trace.SpanContext;
import io.opentelemetry.context.Context;
import io.opentelemetry.context.ContextStorage;
import io.opentelemetry.context.Scope;

public final class ProfilerContextStorage implements ContextStorage {
    private final ContextStorage delegate;

    private ProfilerContextStorage(ContextStorage delegate) {
        this.delegate = delegate;
    }

    public static void install() {
        ContextStorage.addWrapper(ProfilerContextStorage::new);
    }

    @Override
    public Scope attach(Context toAttach) {
        Scope scope = delegate.attach(toAttach);

        SpanContext spanContext = Span.fromContext(toAttach).getSpanContext();
        if (!spanContext.isValid()) {
            return scope;
        }

        String tag = spanContext.getTraceId() + '/' + spanContext.getSpanId();
        long profilerSpan = one.profiler.Span.start();

        return () -> {
            one.profiler.Span.endIfProfiled(profilerSpan, tag);
            scope.close();
        };
    }

    @Override
    public Context current() {
        return delegate.current();
    }
}

A few notes:

Spring Boot and Micrometer

In a Spring Boot 3 application you usually don’t touch OpenTelemetry directly, you go through Micrometer Tracing. Its ObservationHandler has scope callbacks, so we can use the same approach:

public class ProfilerObservationHandler implements ObservationHandler<Observation.Context> {
    private static final ThreadLocal<Deque<Long>> STARTS = ThreadLocal.withInitial(ArrayDeque::new);

    @Override
    public boolean supportsContext(Observation.Context context) {
        return true;
    }

    @Override
    public void onScopeOpened(Observation.Context context) {
        STARTS.get().push(Span.start());
    }

    @Override
    public void onScopeClosed(Observation.Context context) {
        Long start = STARTS.get().poll();
        if (start != null) {
            Span.endIfProfiled(start, tag(context));
        }
    }

    private static String tag(Observation.Context context) {
        TracingContext tracingContext = context.get(TracingContext.class);
        if (tracingContext == null || tracingContext.getSpan() == null) {
            return context.getContextualName();
        }
        TraceContext traceContext = tracingContext.getSpan().context();
        return traceContext.traceId() + '/' + traceContext.spanId() + '/' + context.getContextualName();
    }
}

Scopes on a single thread nest strictly, last opened is first closed, which is why a Deque is enough here - no need to match the start timestamp with any particular observation.

Registering it is the same as any other handler:

@Bean
ObservedAspect observedAspect(ObservationRegistry observationRegistry) {
    observationRegistry.observationConfig().observationHandler(new ProfilerObservationHandler());
    return new ObservedAspect(observationRegistry);
}

What to put in the tag

Now the interesting part. traceId + "/" + spanId is a good default, and here is why it works so well:

The one thing I would add on top is the operation name, as a suffix - traceId/spanId/name. Opaque hex is fine when you arrive from Jaeger with an ID in your clipboard, but it is unreadable when you are just browsing the Span stats of a JFR file and trying to work out which of these took 4 seconds. Putting the name last keeps both prefix filters (by trace, and by trace + span) working exactly as before.

Whether you can do it depends on which side you hooked:

One trade-off worth knowing: if what you mostly do is aggregate profiling - “show me the flame graph of everything that ran under POST /orders this week” - then the name is the useful prefix and the IDs are the noise, and you may prefer name/traceId/spanId instead. You can’t have both prefixes at once; pick the one that matches how you actually search. My experience is that people reach for spans when investigating a single bad request, so I keep the IDs in front.

Your application is not my application

Everything I’ve written above is a default, not a rule. The tag is a free-form string, the profiler doesn’t parse it, and nothing in async-profiler knows or cares that OpenTelemetry exists. I picked traceId/spanId because this chapter is about joining the profiler with tracing, but that is my use case, and yours may be a completely different one.

The question you should be asking is not “what does the standard say”, it is:

When somebody wakes me up at 3 a.m. with a production problem, what will I want to filter the profile by?

The answer to that is domain knowledge, and you have it - I don’t.

The best example is a multitenant system. Sooner or later you get a ticket saying “customer ACME reports the system is slow”, while every dashboard you own looks perfectly fine, because ACME is 2% of your traffic and the averages have swallowed them whole. If the customer ID is part of your tag, that investigation is one filter away - you get a flame graph of everything your application did for that one customer, and very often the answer is immediately visible: they are the only client with 40 thousand records in a collection that somebody loops over, or the only one with a feature flag that turns on an expensive code path.

Adding it is trivial. If you propagate the tenant in OpenTelemetry baggage, it is already sitting in the context you are wrapping:

String tenant = Baggage.fromContext(toAttach).getEntryValue("tenant.id");
String tag = tenant + '/' + spanContext.getTraceId() + '/' + spanContext.getSpanId();

and if you keep it in your own ThreadLocal, in an MDC, or in a security context, use that instead - it makes no difference to the profiler.

Other things I have seen work well, depending on what the application actually does:

And of course you can combine them - tenant/traceId/spanId is a perfectly reasonable tag. Just remember the ordering rule from the previous section: whatever you put first is what you can prefix-filter by, so put the dimension you group by in front, and the unique identifier behind it.

Two warnings before you go wild with this:

Nesting, and why endIfProfiled matters

Telemetry spans nest, so profiler spans will nest too. A sample taken deep inside payment-service ends up covered by the HTTP server span, the service span and the JDBC span all at once.

That is a feature. Filtering by the outer tag gives you that whole subtree, filtering by an inner tag narrows you down to just that part of the work - the same drill-down you have in the tracing UI, only now every level has a flame graph attached to it.

It does have a cost though. Every span is a JFR event, and every tag is a distinct string in the JFR constant pool - and with traceId/spanId every single tag is unique, so nothing deduplicates. An application with fine-grained instrumentation inside a loop can produce a lot of them.

This is exactly what endIfProfiled is for:

Span.endIfProfiled(profilerSpan, tag);

It records the span only if at least one profiling sample was actually taken on this thread while the span was open, and it decides that without entering native code at all. A span that encloses no sample contributes nothing to the profile - there is nothing to filter with it - so dropping it costs you no information whatsoever. With wall-clock sampling at the default interval, that quietly removes the overwhelming majority of the short nested spans, and leaves you the ones that actually have a flame graph behind them.

Use plain end() only when you genuinely want a complete list of spans, for example when you are also using the JFR file for latency statistics rather than just for filtering samples.

A note on tracing sampling

Your tracing backend almost certainly does not store 100% of the traces - head-based sampling at 1% or 5% is the norm. Mind that an unsampled trace still gets a perfectly valid traceId, still propagates it downstream, and will still end up in your profiler spans - it just never reaches Jaeger, so the tag will point at a trace you cannot look up.

You can gate on it if that bothers you:

if (!spanContext.isSampled()) {
    return scope;
}

I would rather not. Profiler spans are far cheaper than exported traces, and the profile stands on its own - a tag is still a perfectly good grouping key even if nobody can resolve it to a waterfall. Being able to profile 100% of the requests while tracing 1% of them is a feature, not a problem.

The demo application

Every snippet above is taken from a working application, which you can find here:

https://github.com/krzysztofslusarski/async-profiler-spans-demo

It is a Maven project with two independent examples - one on the plain OpenTelemetry SDK with the ContextStorage wrapper, one on Spring Boot with the ObservationHandler - plus a fake workload that does exactly what the waterfalls in this article show.

You don’t need any infrastructure to run it. There is no Jaeger, no Tempo, no collector:

./run-plain-otel.sh
./run-spring.sh

The only thing you have to provide is the async-profiler native library itself - the scripts will look for it in a few usual places, or you can point them at it with ASPROF_LIB=/path/to/libasyncProfiler.so.

The output is worth a look even if you don’t intend to write any of this yourself, because it makes the claims from this chapter checkable rather than merely plausible. The un-instrumented calculateDiscounts really is a hole in the waterfall and really is the top method once you filter the samples by tag. The root span’s tag really does show up three times, once per thread it was active on. And a 290ms span really does cover 29 samples at a 10ms wall-clock interval.