Where OpenTelemetry Stops: the missing 44ms in a Spring Boot trace

java dev.to

A POST /orders in this demo takes 178 milliseconds. The OpenTelemetry Java agent, attached with a single JVM flag and no code changes, will tell you that 127 of those went to a downstream service and 6 to the database. It will not tell you anything about the remaining 44.

That gap is where auto-instrumentation ends and your own code begins. This article locates that boundary precisely, then crosses it: with distributed tracing across two Spring Boot services with zero code changes, then with the minimum instrumentation needed to make the missing 44 milliseconds visible.

Everything is in a companion repository: spring-boot-otel-demo. If you have Docker installed you can clone it and have a live trace in front of you in about two minutes.

Versions used: OpenTelemetry Java agent 2.30.0, opentelemetry-instrumentation-annotations 2.30.0, Spring Boot 3.5.16, Java 21, otel/opentelemetry-collector-contrib:0.157.0, jaegertracing/all-in-one:1.76.0, postgres:18-alpine. This ecosystem moves fast. Check the current OpenTelemetry Java documentation before copying any version number.

The repository has two branches on purpose. master is the agent-only state described in Step 1: no OpenTelemetry dependency in either service. manual-spans is the annotated version from Step 2. Clone, run master first, then switch branches to see the difference.

The problem

Here is a request that touches two services and a database.

POST /orders arrives at order-service. The service validates the request, calculates pricing, calls inventory-service over HTTP to check stock, persists the order to PostgreSQL, and returns a response.

It takes around 180 milliseconds. Sometimes it takes 900. Where does the time go?

The usual answer is to open the logs of both services, filter by timestamp, and reconstruct the sequence by hand. That works with two services. It does not work with eight, and it does not work at all when two requests overlap in the same window.

Traces, spans, and the one header that matters

A trace is one request through your whole system. A span is one unit of work inside it: an HTTP handler, a database query, a method call. Spans nest: each has a parent, and the trace is a tree.

Every span in a trace carries the same trace id. That is what lets a UI stitch together work that happened in different processes, on different machines.

The mechanism for carrying that id across a service boundary is a single HTTP header, traceparent, defined by the W3C Trace Context specification. order-service sends it, inventory-service reads it, and the second service knows it belongs to a trace that started somewhere else.

Here is the setup we are building:

Note the shape. The two services never talk to Jaeger. They talk to an OpenTelemetry Collector, and the Collector decides where the data goes. We will come back to why that matters.

Step 1: tracing with zero code changes

The OpenTelemetry Java agent attaches to the JVM and rewrites bytecode at class-loading time. It recognises Spring MVC, JDBC, Hibernate and HTTP clients, and creates spans for them without the application knowing.

Download the agent jar in your Dockerfile, then start the service with:

ENTRYPOINT ["java", "-javaagent:/app/opentelemetry-javaagent.jar", "-jar", "/app/app.jar"]
Enter fullscreen mode Exit fullscreen mode

Configure it with environment variables in docker-compose.yml:

environment:
  OTEL_SERVICE_NAME: order-service
  OTEL_EXPORTER_OTLP_ENDPOINT: http://otel-collector:4317
  OTEL_EXPORTER_OTLP_PROTOCOL: grpc
  OTEL_TRACES_EXPORTER: otlp
Enter fullscreen mode Exit fullscreen mode

The protocol line is load-bearing, not decoration. Port 4317 is the gRPC port and the Collector in this repo opens a gRPC receiver only. Defaults for this variable have varied across SDKs and versions, so set it explicitly: if the agent picks http/protobuf and sends it to 4317, every export fails and no traces reach Jaeger.

The failure is at least loud. The agent logs it to the service's own stdout on every export cycle, naming both the exporter and the endpoint:

[otel.javaagent] ... ERROR io.opentelemetry.exporter.otlp.internal.HttpExporter
- Failed to export spans. The request could not be executed.
java.net.SocketException: Connection reset
Enter fullscreen mode Exit fullscreen mode

If Jaeger is empty, docker compose logs order-service is the first place to look. The word HttpExporter against a port you configured for gRPC is the whole diagnosis.

That is the entire integration. No dependency in pom.xml, no configuration class, no SDK.

Bring the stack up and send a request:

curl -X POST http://localhost:8080/orders \
  -H "Content-Type: application/json" \
  -d '{"customerId":"CUST-001","sku":"SKU-1000","quantity":5}'
Enter fullscreen mode Exit fullscreen mode

Then open Jaeger at http://localhost:16686, select order-service, and click Find Traces:

One thing before you read anything into the numbers: let the JVM warm up. The first request through a fresh service can be three times slower than the steady state, and the shape of that first trace is misleading. Send the request ten times and look at the last one.

What you got for free

Read that waterfall carefully, because there is more in it than it first appears.

The trace crosses the service boundary. inventory-service GET /inventory/{sku} is nested inside the client span of order-service. Two JVMs, two containers, one trace. Nobody wrote code to make that happen. The agent injected traceparent on the way out and read it on the way in.

The persistence layer is broken down for you. OrderRepository.save at 5.93ms contains Session.persist at 1.36ms, the actual INSERT at 496µs, and Transaction.commit at 3.37ms.

That last pair is worth sitting with. The INSERT is under half a millisecond. The commit costs nearly seven times as much. Most of the time spent persisting this order is not the query. It is everything around it. You would never learn that from a log line, and it is the kind of detail that changes how you think about transaction boundaries under load.

Self time versus total time. The client span for the inventory call is 127.37ms, while the server span inside inventory-service is 123.69ms. The difference is real client-side and network overhead. When hunting a bottleneck, the number you want is not the widest bar, but the bar that is wide and does not have equally wide children. A service that takes two seconds is not guilty if 1.9 of them are spent waiting for someone else.

Where the agent stops

Now look at the start of the trace:

The root span starts at zero. The first child span starts around 44 milliseconds later. Nothing at all is recorded in between.

That gap is your business logic. In this service it is request validation followed by a pricing calculation: plain Java, no I/O. The DTO mapping that happens after persistence is invisible for the same reason, though at well under a millisecond it does not leave a hole you can see.

And that is exactly why the agent cannot see them. Auto-instrumentation works by recognising libraries: a servlet container, a JDBC driver, an HTTP client. It has no way to know that computePricing is a meaningful unit of work in your domain. From the agent's point of view, the time between two library calls is just time.

This is the honest limit of "zero code changes". The agent gives you the skeleton of the request for free. The flesh is your problem.

Step 2: naming your own work

Add one dependency to order-service:

<properties>
  <!-- Must match the agent version pinned in the Dockerfile -->
  <opentelemetry-instrumentation.version>2.30.0</opentelemetry-instrumentation.version>
</properties>

<dependency>
  <groupId>io.opentelemetry.instrumentation</groupId>
  <artifactId>opentelemetry-instrumentation-annotations</artifactId>
  <version>${opentelemetry-instrumentation.version}</version>
</dependency>
Enter fullscreen mode Exit fullscreen mode

Keep that version aligned with the agent jar you download in the Dockerfile. A mismatch between the two is the most common reason @WithSpan spans silently fail to appear. The build succeeds, the service starts, and the spans simply are not there.

Then annotate the methods that matter. @WithSpan creates a span for the method, correctly parented to whatever span is active. @SpanAttribute attaches a method parameter to that span as a searchable field:

@WithSpan("calculate-pricing")
private PricingBreakdown computePricing(@SpanAttribute("order.sku") String sku,
                                        @SpanAttribute("order.quantity") int quantity) {
    // both helpers are plain in-memory work: a price list scan and a discount tier walk
    BigDecimal basePrice = lookupBasePrice(sku);
    BigDecimal discountRate = resolveVolumeDiscountRate(quantity);

    BigDecimal subtotalAfterDiscount = BigDecimal.ZERO;
    BigDecimal taxAmount = BigDecimal.ZERO;
    int remainingUnits = quantity;

    while (remainingUnits > 0) {
        int unitsInLine = Math.min(LINE_SIZE, remainingUnits);
        BigDecimal lineSubtotal = applyPerUnitRules(basePrice, unitsInLine);

        BigDecimal lineDiscount = lineSubtotal.multiply(discountRate).setScale(2, RoundingMode.HALF_UP);
        BigDecimal lineAfterDiscount = lineSubtotal.subtract(lineDiscount);
        BigDecimal lineTax = lineAfterDiscount.multiply(TAX_RATE).setScale(2, RoundingMode.HALF_UP);

        subtotalAfterDiscount = subtotalAfterDiscount.add(lineAfterDiscount);
        taxAmount = taxAmount.add(lineTax);
        remainingUnits -= unitsInLine;
    }

    BigDecimal totalPrice = subtotalAfterDiscount.add(taxAmount).setScale(2, RoundingMode.HALF_UP);
    return new PricingBreakdown(basePrice, discountRate, taxAmount, totalPrice);
}
Enter fullscreen mode Exit fullscreen mode

No I/O, no sleeps, no database. Pure CPU work, which is exactly the point. This is the kind of method the agent cannot see.

One disclosure, since the numbers have to add up: the loop you see here is cheap at quantity = 5. The weight sits in lookupBasePrice, which builds and linearly scans a price catalog of roughly 950,000 entries, once per call rather than once per unit. That is deliberately absurd. In a real service it would be a cached lookup and the span would measure microseconds. The point of this article is the shape of the trace, not the size of the number, and a gap of forty milliseconds is easier to see in a screenshot than a gap of forty microseconds.

Two things worth knowing before scattering these around.

It works on private methods, but only because the agent is rewriting bytecode. This is not a Spring proxy, so there is no self-invocation problem to worry about. A private method called from within the same class still gets its span. If one fails to appear, check the version alignment above first, then try widening the method's visibility.

Extract before you annotate. A span is only useful if it wraps one coherent thing. If your pricing logic sits inline in the middle of a 200-line service method, annotating that method tells you nothing you did not already know.

Switch to the manual-spans branch, rebuild, send the same request, and the gap is gone:

validate-order-request at 32µs. calculate-pricing at 38.68ms, most of the 44ms gap from before, now with a name. check-inventory and persist-order wrap the library spans they own, and map-response closes the request at 20µs.

Note that a few milliseconds are still unaccounted for. That residue is not a failure of instrumentation: some of what sits between two spans is request deserialisation, framework dispatch and other work that is not yours to name. You are never going to close the gap completely, and chasing the last microsecond is how you end up with a trace so noisy that nobody reads it.

The totals: 178.06ms without manual spans, 184.86ms with them. Do not read that difference as the cost of instrumentation. Two annotations cannot cost seven milliseconds. The runtime overhead of a span is a context push and a timestamp, measured in fractions of a microsecond. What you are looking at is JVM noise: a minor GC, a scheduling hiccup, network jitter between two containers. Run the same request twenty times and you will see a wider spread than this with no code change at all.

There is one real cost worth naming: annotating a small private method can prevent the JIT from inlining it, so a hot, tight method may genuinely run slower once instrumented. That is an argument for instrumenting meaningful units of work rather than every method you can reach. It is not an argument against instrumenting at all. In an I/O bound service like this one, where a single HTTP call accounts for 70% of the request, it is invisible.

Attributes are where this gets useful

Click on the calculate-pricing span:

The span carries order.sku = SKU-1000 and order.quantity = 5, the actual values from the request. It also carries code.function = computePricing and code.namespace = com.example.orderservice.order.OrderService, added automatically.

This is the difference between something took 38ms and OrderService.computePricing took 38ms for SKU-1000 at quantity 5. Once those attributes are on the span you can search on them: every pricing calculation above a threshold, filtered by SKU. That is a question you cannot ask a log file without writing a parser first.

Two cautions. Whatever you put in an attribute ends up in your observability backend, so keep personal data and secrets out of them. And be careful about where that attribute travels: order.sku is harmless on a span, because traces are sampled and stored as individual records. Put the same field on a metric and you have created one time series per SKU. High-cardinality labels are the classic way to take down a Prometheus instance, and the mistake is easy to make once you start instrumenting by habit rather than by intent.

Why the Collector is in the picture

You may have noticed the agent could have pointed straight at Jaeger. In development it can. There are three reasons not to do that anywhere else.

Batching and retries belong in a separate process, not in the request path of your application. The Collector can enrich, filter and drop data centrally rather than in every service. And most importantly:

exporters:
  otlp:
    endpoint: jaeger:4317
    tls:
      insecure: true
Enter fullscreen mode Exit fullscreen mode

Changing your observability backend means editing that block. It does not mean touching, rebuilding or redeploying a single service. Your applications emit OTLP, an open protocol, and where it lands is a deployment detail.

If you have ever had to argue an architecture decision on vendor lock-in grounds, this is an unusually clean example: the instrumentation is standard, the wire protocol is standard, and the vendor-specific part is one block in one file.

For completeness: OTLP travels over gRPC on port 4317 and over HTTP/protobuf on 4318. The specification says the default should be http/protobuf unless an SDK has good reason to pick gRPC (backward compatibility, typically), so what you actually get depends on your SDK and version. Pin it explicitly, as in the compose file above. gRPC is generally the right choice for agent-to-collector traffic, which is high volume and continuous. Switch to HTTP if you have proxies or load balancers in between that are unhappy with long-lived HTTP/2 connections, which is common enough in enterprise networks.

What this does not cover

Tracing every request is affordable on a laptop but not in production, so sampling strategy is the decision waiting on the other side of this setup. Traces are also only one of three signals: metrics and logs travel the same pipeline, and correlating existing Log4j2 output with trace ids is arguably the highest-value thing to do after this. Asynchronous boundaries deserve their own article: put a message on a queue and the context does not propagate on its own, so the trace breaks silently at exactly that point.

The boundary described here, though, does not move. Auto-instrumentation maps the parts of your system that are made of libraries. Everything that is genuinely yours (the logic you were actually hired to write) stays invisible until you name it.

Naming it costs one dependency and a handful of annotations.

Source: dev.to

arrow_back Back to Tutorials