Example: Checkout Latency

At 14:32 UTC the synthetic checkout probe in us-east-1 reports p95 of 1.8 seconds against an SLO of 500 ms. The 5xx rate is within band. The synthetic probe is not alone: customers in the support channel are reporting that checkout takes “forever”. The on-call engineer has thirty minutes of SLO burn to work with before the page escalates. This is the worked example.

What it is

A checkout-latency investigation is the six-phase loop applied to a user-visible slowdown of the checkout path. The path includes the checkout service, the cart service, the payment service, the inventory service, and the database. The investigation walks through each phase and lands on a runbook log entry.

The latency shape matters. A latency that is uniformly distributed across all spans of a trace is a platform or saturation issue. A latency that is concentrated on a single span is a regression in the dependency that owns that span. Concentrated latency is the easier of the two.

Why a sysadmin cares

Checkout is the user-visible critical path for revenue. The SLO is typically 500 ms p95; a regression to 1.8 s is a quarter of the error budget in a single hour. The investigation must be fast and accurate: a fast mitigation that does not find the root cause leaves the bug in place to recur.

The worked example matters because checkout-latency investigations are the most common page in a Grafana / Prometheus / Loki / Tempo stack. A team that has the worked example in muscle memory will resolve the page in twelve minutes; a team that does not will resolve it in sixty.

How it works

The investigation walks the six phases with the worked example running in parallel:

  14:32 UTC  Phase 1: symptom = "checkout p95 1.8 s, SLO 500 ms"
  14:34 UTC  Phase 2: impact  = "~12% error budget burned in 30 min"
  14:36 UTC  Phase 3: hypoth. = "deploy at 14:18 raised payment-svc
                            dependency timeout from 1.0 s to 4.0 s"
  14:38 UTC  Phase 4: evidence = (metrics, logs, trace, dependency)
  14:44 UTC  Phase 5: test    = confirmed
  14:50 UTC  Phase 6: cause   = timeout config regression;
                            mit. = rollback

Phase 1: Define the symptom

The page message names the symptom in plain language. The on-call engineer writes the symptom down so the rest of the team has a single source of truth:

Checkout p95 latency is 1.8 seconds in us-east-1 since 14:18 UTC, against an SLO of 500 ms. 5xx rate is 0.4% (within band). Synthetic probe confirms. Customer reports corroborate.

The symptom is specific: region, time window, magnitude, SLO. The falsifier is built into the wording: if p95 drops below 500 ms for 10 minutes, the symptom resolves.

Phase 2: Quantify the impact

The SLO burn panel says the checkout service has burned 12% of the 30-day error budget in the 30 minutes since the regression. That is the urgency: at the current rate, the budget will be exhausted in roughly 4 hours.

# SEVERITY: READ-ONLY
curl -s 'http://prometheus:9090/api/v1/query?query=slo:checkout_latency_p95:burn_rate_5m' \
  | jq '.data.result[0].value[1]'

Expected output:

"24.5"

The 24.5 is a 5-minute burn rate multiplier against the 30-day budget. A burn rate of 24.5 means the 30-day budget will be exhausted in 30 days / 24.5 = 29 hours. The calculation is consistent with the 12% in 30 minutes figure.

Phase 3: Form a hypothesis

The change log shows a deploy at 14:18 to the payment-svc. The deploy message references a configuration change to the downstream timeout: payment-svc.dependency.timeout was raised from 1.0s to 4.0s. The hypothesis:

The deploy at 14:18 raised the payment-svc dependency timeout from 1.0 s to 4.0 s. The checkout service is configured to wait up to 2.0 s on the payment-svc response; under the new timeout, the checkout service waits longer for a response that the payment-svc will not return, surfacing as checkout p95 near 1.8 s.

The hypothesis is falsifiable. The falsifier is the trace: if a single checkout request shows wait time on payment-svc of 1.8 s (not 4.0 s), the hypothesis is wrong. If the wait time matches the new timeout, the hypothesis is confirmed.

Phase 4: Find evidence

Four telemetry surfaces, in this order:

1. Service metric. The checkout latency panel by span:

# SEVERITY: READ-ONLY
curl -s 'http://prometheus:9090/api/v1/query?query=histogram_quantile(0.95,sum%20by%20(le%2C%20span_name)%20(rate(http_request_duration_seconds_bucket{job%3D%22checkout%22%2Cregion%3D%22us-east-1%22%2Cspan_name!%3D%22%22}[5m])))' \
  | jq -r '.data.result[] | "\(.metric.span_name)\t\(.value[1])"'

Expected output:

checkout.total                  1.820
checkout.cart_lookup            0.012
checkout.payment_charge         1.792
checkout.inventory_reserve      0.014

The payment_charge span is 1.792 s of the 1.820 s total. The hypothesis is consistent with this distribution.

2. Dependency metric. The payment-svc upstream latency as seen from the checkout service:

# SEVERITY: READ-ONLY
curl -s 'http://prometheus:9090/api/v1/query?query=histogram_quantile(0.95,sum%20by%20(le)%20(rate(http_request_duration_seconds_bucket{job%3D%22checkout%22%2Cdependency%3D%22payment-svc%22}[5m])))' \
  | jq -r '.data.result[0].value[1]'

Expected output:

"1.802"

The dependency latency matches the checkout latency. The hypothesis is consistent.

3. Trace. A single failed checkout trace, sampled from the last 10 minutes:

# SEVERITY: READ-ONLY
curl -s 'http://tempo:3200/api/search?tags=service.name%3Dcheckout%20http.status_code%3D200%20&limit=1&start=1747214400&end=1747214700' \
  | jq -r '.traces[0].traceID'

Expected output:

0a3f9b21c7d54e2a8f0c1b9d3e7a8f4c

Inspect the trace in Grafana. The trace tree:

checkout (root)
 +-- checkout.cart_lookup           12 ms
 +-- checkout.payment_charge      1792 ms
 |    +-- payment-svc /charge     1792 ms (waiting on response)
 |    +-- payment-svc /charge     (response arrives at 1792 ms)
 +-- checkout.inventory_reserve     14 ms

The trace confirms: the wait is on the dependency response, not on any local work in the payment-svc handler. The dependency is configured to wait 4 s; the checkout is configured to wait 2 s; the checkout sees a timeout at 1.8 s (2 s minus network overhead).

4. Logs. The payment-svc error log during the window:

# SEVERITY: READ-ONLY
logcli query '{job="payment-svc"} |= "upstream_timeout" | line_format "{{.ts}} {{.msg}}"' \
  --since=14:18 --until=14:48

Expected output:

2026-08-13T14:18:07Z upstream_timeout target=card-auth path=/charge duration_ms=4000
2026-08-13T14:21:33Z upstream_timeout target=card-auth path=/charge duration_ms=4000
2026-08-13T14:25:11Z upstream_timeout target=card-auth path=/charge duration_ms=4000
... (47 similar lines)

The logs confirm that the upstream timeout is being hit at the new 4000 ms value. The dependency is timing out; the checkout service is timing out earlier and surfacing the failure as latency.

Phase 5: Test the hypothesis

The hypothesis predicted a trace of 1.8 s on the payment-svc /charge span. The trace is 1.792 s. The dependency latency matches. The logs show the upstream timeout at 4000 ms. The hypothesis is confirmed.

A falsifier would have been: trace shows payment-svc /charge at 4.0 s (matching the new timeout). In that case the checkout timeout (2.0 s) would be the limiting factor, not the dependency. The falsifier would have redirected the investigation to the checkout timeout configuration, not the payment-svc configuration.

Phase 6: Locate root cause and document

Root cause: the deploy at 14:18 raised payment-svc.dependency. timeout from 1.0s to 4.0s without a corresponding raise in checkout.dependency.timeout. The checkout service’s 2.0 s timeout is now below the payment-svc’s effective response time, producing a checkout timeout on every request that takes more than 2 s.

Mitigation: rollback the deploy. The 14:18 deploy is reverted via the standard kubectl rollout undo (or equivalent Helm rollback). Checkout p95 returns to 180 ms within 60 seconds.

Runbook log entry, written at 14:55 UTC:

# Runbook: CheckoutLatencyAboveSLO

## Symptom (Phase 1)
Checkout p95 latency 1.8 s in us-east-1 since 14:18 UTC, SLO
500 ms. 5xx rate within band.

## Impact (Phase 2)
5-minute SLO burn rate 24.5; ~12% of 30-day error budget in
30 minutes. Synthetic probe and customer reports confirm.

## Hypothesis (Phase 3)
Deploy at 14:18 raised payment-svc.dependency.timeout from
1.0 s to 4.0 s. Checkout is configured to wait 2.0 s on
payment-svc; checkout times out before payment-svc responds,
producing latency equal to checkout timeout (2.0 s) minus
network overhead (~1.8 s).

## Evidence (Phase 4)
- checkout p95 by span: payment_charge 1.792 s of 1.820 s.
- payment-svc dependency p95 (as seen from checkout): 1.802 s.
- trace 0a3f...: wait on payment-svc /charge response is
  1.792 s, no local work in handler.
- payment-svc logs: 47 upstream_timeout events at 4000 ms
  since 14:18 UTC.

## Test (Phase 5)
Confirmed. Trace latency matches hypothesis.

## Root cause + mitigation (Phase 6)
Root cause: timeout configuration regression in 14:18 deploy.
Mitigation: rollback. p95 returned to 180 ms at 14:56 UTC.

## Follow-up
- Add pre-deploy check: payment-svc.dependency.timeout must
  be less than or equal to checkout.dependency.timeout.
- Add recording rule: payment-svc_upstream_timeout_total.
- Add alert: 10 upstream_timeout events in 5 minutes
  (severity: ticket, team: payments).
- Document the configuration invariant in the deploy runbook.

How to configure it

The investigation produces two configuration artefacts. The immediate artefact is the rollback. The follow-up artefacts are pre-deploy checks, recording rules, and a ticket-class alert.

A pre-deploy check that enforces the configuration invariant:

# deploy-checks/payment-svc-timeout.yaml
apiVersion: batch/v1
kind: Job
metadata:
  name: payment-svc-timeout-check
spec:
  template:
    spec:
      restartPolicy: Never
      containers:
      - name: check
        image: curlimages/curl:8
        command:
        - sh
        - -c
        - |
          set -eu
          # READ-ONLY: verify config consistency
          CHECKOUT_TIMEOUT=$(curl -s \
            'http://config.example.com/checkout/dependency.timeout')
          PAYMENT_TIMEOUT=$(curl -s \
            'http://config.example.com/payment-svc/dependency.timeout')
          if [ "$(echo "$PAYMENT_TIMEOUT > $CHECKOUT_TIMEOUT" | bc)" -eq 1 ]; then
            echo "FAIL: payment-svc timeout ($PAYMENT_TIMEOUT) > checkout timeout ($CHECKOUT_TIMEOUT)"
            exit 1
          fi
          echo "OK: payment-svc timeout ($PAYMENT_TIMEOUT) <= checkout timeout ($CHECKOUT_TIMEOUT)"

A recording rule that captures the upstream timeout rate:

groups:
- name: payment-svc.rules
  interval: 30s
  rules:
  - record: payment_svc:upstream_timeout:rate5m
    expr: sum by (target) (
      rate(payment_svc_upstream_timeout_total[5m])
    )

A ticket-class alert on the recording rule:

  - alert: PaymentSvcUpstreamTimeouts
    expr: payment_svc:upstream_timeout:rate5m > 0.05
    for: 10m
    labels:
      severity: ticket
      team: payments
      service: payment-svc
    annotations:
      summary: 'Payment-svc upstream timeouts above 5% for 10 minutes'
      runbook_url: 'https://runbooks.example.com/payment-svc/upstream-timeout'

How to validate it

Validate that the investigation reached phase 6 by replaying each step against the live platform:

# SEVERITY: READ-ONLY
# 1. Confirm the alert rule is back in steady state.
curl -s 'http://prometheus:9090/api/v1/query?query=histogram_quantile(0.95,sum%20by%20(region)%20(rate(http_request_duration_seconds_bucket{job%3D%22checkout%22}[5m])))' \
  | jq '.data.result[] | "\(.metric.region)=\(.value[1])"'

Expected output:

us-east-1=0.181
us-west-2=0.179
eu-west-1=0.183

# SEVERITY: READ-ONLY
# 2. Confirm the rollback completed via the change log.
kubectl rollout history deployment/checkout -n payments

Expected output:

deployment.apps/checkout with image revision
REVISION  CHANGE-CAUSE
3         deploy at 14:18 reverted (rollback)
2         deploy at 14:18 (reverted)
1         initial

# SEVERITY: READ-ONLY
# 3. Confirm the recording rule is live.
curl -s 'http://prometheus:9090/api/v1/query?query=payment_svc:upstream_timeout:rate5m' \
  | jq '.data.result'

Expected output:

{"metric":{},"value":[1747215000,"0"]}

The four checks confirm: the symptom has resolved (p95 back to SLO), the cause has been removed (deploy reverted), and the follow-up signal is live (recording rule returns 0).

How it can fail

Five specific failure shapes for a checkout-latency investigation:

1. Treating the dependency timeout as benign. The on-call sees upstream_timeout in the payment-svc logs and assumes it is a known transient. The check below: if upstream_ timeout events rose at the same time as the latency regression, they are the cause, not a side effect.

2. Stopping at the metric. The on-call sees checkout p95 elevated, sees payment-svc p95 elevated, and assumes the payment-svc is slow. The trace shows the payment-svc handler itself is fast (12 ms local work) but waiting on the response. Without the trace, the on-call resizes the payment-svc and the latency does not improve.

3. Rolling back the wrong deploy. The change log shows three deploys in the last hour. The on-call picks the most recent one and rolls it back. The latency does not improve; the correct deploy was the second most recent. Symptom: rollback completes; p95 stays elevated; the second rollback is needed.

4. Skipping the pre-deploy check. The follow-up ticket recommends a pre-deploy check; the ticket is closed without the check. The same regression ships the next quarter from a different team. The runbook log entry names the check; the runbook is not the same as the check being in CI.

5. Routing the follow-up alert to a page. The follow-up alert is configured at severity: page because the engineer remembers the page they got during the incident. The follow-up alert fires on every transient upstream timeout. The on-call mutes the channel. The next real incident is missed. Symptom: the alert fires 30 times a day; the page channel is muted by month-end.

How to troubleshoot it

When the latency investigation is taking longer than the SLO budget allows, the diagnostic order is:

1. Confirm the symptom. Open the SLO burn panel. Is the burn rate still elevated, or has the latency regressed back? If the latency has regressed, the symptom may be transient and the investigation may not need to continue.
2. Re-confirm the change window. Re-read the change log for the last two hours. The deploy at 14:18 was the first change in 72 hours; a different incident has a noisier change log. The change window narrows the hypothesis.
3. Pull a trace before opening more dashboards. A single trace localises the latency to a span. Three dashboards cannot do this.
4. Test the hypothesis with one falsifier. The falsifier is built into the hypothesis (Phase 3). If the trace does not match the falsifier, the hypothesis is wrong; pick the next one.
5. Mitigate before completion if the budget is critical. At 24.5x burn rate, the budget is critical. Roll back the suspect deploy first; investigate after. The rollback is reversible; the lost error budget is not.

Security implications

The checkout path carries user identifiers (session IDs, user IDs, payment tokens). The latency investigation must not exfiltrate those identifiers through telemetry queries. The metric labels should not include per-user labels; the trace attributes may include them but should be filtered to operators only. The logs may include card auth tokens in header values; the log-derived metrics must aggregate them out before the recording rule stores them.

Restrict the trace query to operators with a recorded purpose. A latency investigation that includes a single trace of a single user’s checkout may contain enough information to identify that user; the audit trail of who queried that trace must be retained.

Performance implications

The investigation queries walk the histogram buckets for the suspect metric family. A 5-minute rate over the suspect span (payment_charge) is bounded by the histogram bucket count; the query is cheap. The trace query is bounded by the sampling rate; if the sampling rate is 1% the on-call may need to wait up to 100 seconds for a usable trace. A high sampling rate is the right pre-investigation investment.

The pre-deploy check is a single HTTP fetch per service at deploy time; the cost is negligible.

The follow-up recording rule evaluates every 30 seconds against the payment_svc_upstream_timeout_total counter; the cost is bounded by the rate of upstream timeout events and is negligible on a healthy platform.

Production guidance

• The latency regression has a falsifier. Build the falsifier into the hypothesis (Phase 3) before opening dashboards. The falsifier is what stops the investigation from looping on the wrong cause.
• The trace is the cheapest way to localise latency to a span. Open the trace at phase 4, not at phase 5.
• Roll back before investigating when the SLO burn rate exceeds 10x. The rollback is reversible; the error budget is not.
• The follow-up is configuration, not just a ticket. The pre-deploy check, the recording rule, and the alert are the artefacts that prevent the regression from shipping again.
• Document the configuration invariant. The reason this regression shipped is that the invariant (payment-svc.timeout <= checkout.timeout) was not documented; the next deploy will check it.

Verification

You should now be able to answer:

• Which phase of the loop produces the falsifier for the hypothesis, and where does the falsifier come from?
• Why is the trace the cheapest way to localise a latency regression, and what does the metric not tell you that the trace does?
• What configuration invariant, if it had been enforced, would have prevented the regression from shipping?
• When does the right mitigation become “rollback before complete the investigation”, and what is the threshold?
• Why is the follow-up alert at severity: ticket and not at severity: page?

Quiz