Tracing Connection Acquisition Latency with OpenTelemetry Spans

This guide is part of OpenTelemetry Connection Pool Tracing. A slow request’s trace usually shows a request span, a few query spans, and an unexplained gap between the start of the request and the first query. Engineers read the gap as application CPU time or garbage collection, look at the query spans — all fast — and conclude the database is not involved. Often the gap is the request waiting for a pooled connection, and the queries are fast precisely because the database is not the bottleneck:

GET /api/orders/8812            1,840 ms
├─ auth.verify                      12 ms
│                                           ← 1,610 ms with no child span
├─ SELECT orders                      9 ms
├─ SELECT order_items                14 ms
└─ render                            21 ms

The objective is to make that wait a first-class span or event in every trace, attribute it to a pool by name, and make sure the traces that show it are the ones sampling keeps.

Rapid incident diagnosis

Confirm the gap is pool wait before instrumenting. If the pool exposes metrics, correlate the time of slow traces with pool wait. With OpenTelemetry pool metrics exported to Prometheus:

histogram_quantile(0.99, sum by (le, db_client_connection_pool_name)
  (rate(db_client_connection_wait_time_seconds_bucket[1m])))

A p99 wait of more than a second during the same minutes as gap-heavy traces is strong evidence. For HikariCP without OpenTelemetry metrics, hikaricp_connections_acquire_seconds from Micrometer gives the same signal.

Check what the instrumentation already records. Some runtimes can produce acquisition spans without code:

• The OpenTelemetry Java agent creates a span for DataSource.getConnection() when otel.instrumentation.jdbc-datasource.enabled=true. It is off by default because it adds a span to every database-touching request.
• Node.js pg instrumentation creates a pg-pool.connect span for pool.connect() calls.
• Python SQLAlchemy and Go database/sql instrumentations record query spans; acquisition needs a manual span or event.

Search a slow trace for spans named getConnection, HikariDataSource.getConnection or pg-pool.connect. If none exist, the gap cannot be attributed from traces alone.

Rule out the other gap causes. A gap that also appears in requests to endpoints that never touch the database is not pool wait. A gap that coincides with garbage collection pauses in runtime metrics — jvm.gc.duration, for instance — is the collector. Pool wait correlates with pool metrics and only affects database-touching routes.

Mathematical sizing or parameter formula

Acquisition tracing adds spans, and spans cost export volume and storage. Estimate it before enabling it everywhere.

extra_spans_per_second = requests_per_second × acquisitions_per_request

A service handling 2,000 requests per second, each acquiring a connection twice, adds 4,000 spans per second before sampling. With head-based sampling at 10 %, that is 400 spans per second exported — manageable, but 90 % of slow acquisitions are dropped with their traces.

A span event recorded only when the wait exceeds a threshold is far cheaper, because most acquisitions are immediate:

events_per_second = requests_per_second × acquisitions_per_request × P(wait > threshold)

If 0.5 % of acquisitions wait longer than 50 ms, the same service records 4000 × 0.005 = 20 events per second, attached to spans that exist anyway.

Choose the threshold from the pool’s normal wait distribution. Set it above the p95 of wait during healthy traffic, so events mark genuine contention, and well below the acquisition timeout, so they appear before failures do:

p95_wait_healthy < event_threshold << acquisition_timeout

With a healthy p95 of 2 ms and a 3,000 ms timeout, a 50 ms threshold fits comfortably.

For sampling, keep traces by latency rather than at random. Tail-based sampling in the Collector buffers each trace briefly and keeps it if any span exceeds a duration, so the slow requests — the ones with long acquisitions — are always retained while fast ones are sampled down.

Exact remediation & configuration

Java: enable data-source spans, or wrap the pool. With the agent, one property enables acquisition spans for every DataSource:

OTEL_INSTRUMENTATION_JDBC_DATASOURCE_ENABLED=true

Without the agent, or to record events only above a threshold, wrap the DataSource:

public final class TracedDataSource extends DelegatingDataSource {
    private static final long THRESHOLD_NANOS = TimeUnit.MILLISECONDS.toNanos(50);
    private final String poolName;

    public TracedDataSource(DataSource target, String poolName) {
        super(target);
        this.poolName = poolName;
    }

    @Override
    public Connection getConnection() throws SQLException {
        long start = System.nanoTime();
        try {
            return super.getConnection();
        } finally {
            long waited = System.nanoTime() - start;
            if (waited > THRESHOLD_NANOS) {
                Span.current().addEvent("db.pool.acquire.slow", Attributes.of(
                    AttributeKey.stringKey("db.client.connection.pool.name"), poolName,
                    AttributeKey.doubleKey("db.pool.wait_ms"), waited / 1e6));
            }
        }
    }
}

Register it around the HikariCP data source in configuration, keeping the pool name identical to HikariCP’s poolName.

Python: time the checkout around engine.connect(). SQLAlchemy’s checkout pool event fires after a connection is obtained and does not include the wait, so measure from outside:

import time
from contextlib import contextmanager
from opentelemetry import trace

tracer = trace.get_tracer("orders.db")

@contextmanager
def traced_connection(engine, pool_name="orders-primary"):
    with tracer.start_as_current_span("pool.acquire", attributes={"db.client.connection.pool.name": pool_name}) as span:
        start = time.perf_counter()
        conn = engine.connect()
        span.set_attribute("db.pool.wait_ms", (time.perf_counter() - start) * 1000)
    try:
        yield conn
    finally:
        conn.close()

With the Session API, measure the first statement’s connection acquisition the same way by calling session.connection() inside the span.

Node.js: use the built-in span and name the pool. The pg instrumentation’s pg-pool.connect span covers pool.connect(); queries issued directly on pool.query() acquire internally within the query span. Keep acquisition explicit on hot paths so the wait has its own span:

const client = await pool.connect();          // traced as pg-pool.connect
try {
  const { rows } = await client.query("SELECT * FROM orders WHERE id = $1", [id]);
  return rows[0];
} finally {
  client.release();
}

Go: span around db.Conn(ctx). database/sql acquires connections inside QueryContext; to trace the wait separately, obtain the connection explicitly:

func withConn(ctx context.Context, db *sql.DB, fn func(*sql.Conn) error) error {
    ctx, span := tracer.Start(ctx, "pool.acquire",
        trace.WithAttributes(attribute.String("db.client.connection.pool.name", "orders-primary")))
    start := time.Now()
    conn, err := db.Conn(ctx)
    span.SetAttributes(attribute.Float64("db.pool.wait_ms", float64(time.Since(start).Microseconds())/1000))
    span.End()
    if err != nil {
        return err
    }
    defer conn.Close()
    return fn(conn)
}

Keep slow traces with tail sampling. In the Collector, keep every trace with a span longer than 500 ms or an error, and 5 % of the rest:

processors:
  tail_sampling:
    decision_wait: 10s
    num_traces: 200000
    policies:
      - name: slow
        type: latency
        latency: { threshold_ms: 500 }
      - name: errors
        type: status_code
        status_code: { status_codes: [ERROR] }
      - name: baseline
        type: probabilistic
        probabilistic: { sampling_percentage: 5 }

Tail sampling needs every span of a trace to reach the same Collector instance; with several Collectors, route by trace ID with the load-balancing exporter in front.

Validation & verification

Induce a wait and find it in a trace. In staging, reduce the pool to 2 connections and run 50 concurrent requests against a route that holds a connection for 200 ms. Then search for traces containing the acquisition span or event:

# Tempo TraceQL
{ span.db.client.connection.pool.name = "orders-primary" && name = "pool.acquire" && duration > 100ms }
{ event:name = "db.pool.acquire.slow" }

Traces must appear, with acquisition durations of hundreds of milliseconds and query spans unchanged.

Check the attribution matches metrics. Over the same test window, the p99 of acquisition span durations should agree with the p99 of db.client.connection.wait_time for the pool within a reasonable margin. A large disagreement means the manual span does not cover the whole acquisition — for example, a Go query issued on *sql.DB instead of the acquired *sql.Conn.

Confirm sampling keeps them. With tail sampling configured and the baseline at 5 %, all traces from the induced-wait test that exceeded 500 ms must be present, not about one in twenty.

Measure overhead. Compare request latency and CPU with acquisition spans enabled and disabled under the same healthy load. Span creation costs microseconds; if overhead is measurable, switch to threshold events.

Reading an acquisition trace during an incident

A trace with an acquisition span answers “did this request wait for a connection?” The more useful question during an incident is “why was the pool full?”, and the same trace backend can answer it when queried the right way.

Find the holders, not just the waiters. The requests that waited are victims. The requests that held connections during the wait are the cause. Query for traces of the same service that overlap the slow acquisition in time and contain long database spans or long gaps between their own acquisition and release:

# TraceQL: requests on the same pool with long database work, in the incident window
{ resource.service.name = "orders-api" && span.db.system = "postgresql" && duration > 500ms }
  | select(span.db.query.text, span.db.namespace)

If the holders are a single endpoint — a report, an export, a batch import triggered through the API — the remedy is to give that endpoint its own pool or move it to a worker. If the holders are spread across endpoints with slow queries, the database is the constraint.

Compare span timelines, not averages. In the waterfall of a holder, look at what happens between its first and last database span. A long stretch with no database spans while a connection is checked out — an HTTP call to another service, a large JSON serialisation — is time the pool lost for no database work. Those gaps, multiplied by request rate, are often the entire saturation.

Use span metrics for the fleet view. Most tracing backends and the Collector’s span metrics connector can derive rate and duration histograms from spans. Deriving a histogram from acquisition spans per endpoint shows which routes wait most, even when sampling keeps only a fraction of traces:

connectors:
  spanmetrics:
    histogram:
      explicit: { buckets: [5ms, 25ms, 100ms, 250ms, 1s, 3s] }
    dimensions:
      - name: http.route
      - name: db.client.connection.pool.name

Frequently Asked Questions

Related

• OpenTelemetry Connection Pool Tracing — the parent guide to OpenTelemetry pool instruments.
• Collecting db.client.connection Metrics with the OpenTelemetry Collector — the metrics side of the same pipeline.
• Measuring Connection Acquisition Latency Percentiles — benchmarking the wait distribution these spans record.
• Understanding Connection Acquisition Timeouts in Go — how database/sql waits for connections internally.
• Linking Slow Queries to Traces with SQLCommenter — reaching the trace from a slow statement in the database.