Latency from Logs

The on-call engineer opens the latency panel for the checkout service. The native histogram shows p99 = 480 ms; the panel shows a flat 320 ms; the alert that should have fired at p99 over 500 ms did not. Investigation: the native histogram has not been updated in 18 hours, because the application is in a deploy loop and every new build is silently dropping the histogram emission. The only thing still being logged is the final duration_ms field on each request line.

A log-derived latency percentile is the right answer in this situation. A histogram_quantile over | unwrap duration_ms produces the same shape the on-call expects, attributed to the same instance, with the same alerting semantics. The cost is paid in ruler CPU; the benefit is that the panel keeps working during a deploy regression that broke the native path.

What it is

A log-derived latency is a time series whose samples are latency values lifted directly from log lines via | unwrap, aggregated with histogram_quantile or quantile_over_time, and exposed as Prometheus-compatible series. Loki 3.x supports two shapes:

• histogram_quantile over a bucket metric produced by | unwrap ... | bucket. Used for distributed percentile estimates from log lines that carry a duration field.
• quantile_over_time over a value. Used for the simple case: compute a quantile over the per-line value within the rate window.

The unwrap form:

# p99 over the last 5 minutes, per instance.
quantile_over_time(0.99,
  {job="checkout"}
  | json
  | unwrap duration_ms [5m]
) by (instance)

The query reads as: “from log lines in job=checkout that parse as JSON, lift the duration_ms field as a number, and compute the 99th percentile over the values seen in the last 5 minutes, grouped by instance.”

Why a sysadmin cares

Native histograms are the right answer when they exist. Log- derived latency earns its place in three situations:

• Native path is broken. A deploy regression that drops histogram emission; the deploy is already in production and rolling back is not immediate. Log-derived latency is the interim signal.
• Vendor-owned binaries that emit a duration in logs but no metric. Mainframe adapters, third-party bridges, anything that prints processing took 124ms and nothing else.
• Post-hoc investigation. An old incident where the only surviving record is the log archive; the team wants to reconstruct the latency distribution to write a postmortem. quantile_over_time over the archive is the answer.

Outside these cases, the cost is paid for no benefit. A native histogram is one observation per request, summarised in a fixed bucket structure; a log-derived percentile is a parse, an unwrap, and a quantile computation per evaluation per stream.

How it works

The pipeline is the same as the error-rate pipeline, with a different parser, a different aggregator, and a different output shape.

   log line                  Loki query engine                    result
   --------                  -----------------                    ------
 {"ts":...,                parser: json
  "duration_ms": 412,   -->  unwrap duration_ms   -->  quantile_over_time(...)  -->  p99
  "level":"info"}
 {"ts":...,                  (lifts the value as a number)
  "duration_ms": 88,
  "level":"info"}

Three pieces to understand:

• | unwrap duration_ms treats the parsed field as a number; the line becomes a (timestamp, value) pair in a synthetic time series. Lines without the field (parser failure or absent value) are dropped.
• [5m] is the quantile’s window. The window bounds how much data the quantile sees; the cost scales with the lines inside the window.
• quantile_over_time(0.99, ...) computes the 99th percentile across the synthetic series. The result is a single number per evaluation per series.

Two refinements for production accuracy:

• Bucket shape for histogram_quantile. When using histogram_quantile over rate( ... | unwrap ... | bucket ... ), the bucket boundaries (le=...) matter. A bucket set that ends at 1 s and uses native histogram defaults gives accurate percentiles for sub-second latencies; a bucket set that ends at 60 s gives accurate percentiles for the long tail. Match the bucket upper bound to the service’s actual p99 envelope.
• Cost vs window. A 5-minute window sees 5 minutes of traffic; a 1-hour window sees 12x more, at 12x the parse cost. The window should be the smallest that still averages over enough events for a stable percentile. For 100 req/s, 5 minutes is 30,000 events — enough. For 1 req/s, 5 minutes is 300 events — too few, the percentile floats.

How to configure it

The recording rule that produces the metric:

# /etc/loki/rules/prod-eu/latency.yaml
groups:
  - name: latency
    interval: 1m
    rules:
      # p99 latency per instance.
      - record: app:log_latency:p99
        expr: |
          quantile_over_time(0.99,
            {job="checkout", cluster="prod-eu"}
            | json
            | unwrap duration_ms [5m]
          ) by (instance)

      # p50 latency per instance (for comparison).
      - record: app:log_latency:p50
        expr: |
          quantile_over_time(0.5,
            {job="checkout", cluster="prod-eu"}
            | json
            | unwrap duration_ms [5m]
          ) by (instance)

      # Average latency per instance (cheaper alternative).
      - record: app:log_latency:avg
        expr: |
          sum(rate({job="checkout", cluster="prod-eu"}
                   | json
                   | unwrap duration_ms [5m])) by (instance)
            /
          sum(rate({job="checkout", cluster="prod-eu"}
                   | json
                   | unwrap duration_ms [5m])) by (instance)

Notes on the shape:

• p50 and p99 are both useful. p99 alone hides the median shift; p99 with a stable p50 catches the regression where every request got 50 ms slower (no p99 change but a real user-visible shift).
• avg is the cheaper alternative. For dashboards that want a single line, sum(rate) / count(rate) produces the average without the quantile overhead. The average does not catch p99 regressions, but it is one query where the quantile is two.
• Window of 5m matches the rule interval. A window of 30s against a rule interval of 1m produces overlapping evaluations and inflated cost.

Validate before applying:

# READ-ONLY: confirm the query returns a metric.
curl -s -u "$LOKI_USER:$LOKI_PASS" \
  --data-urlencode 'query=quantile_over_time(0.99, {job="checkout", cluster="prod-eu"} | json | unwrap duration_ms [5m]) by (instance)' \
  --data-urlencode 'start=2026-08-13T14:00:00Z' \
  --data-urlencode 'end=2026-08-13T14:05:00Z' \
  --data-urlencode 'step=60s' \
  -G http://loki.internal:3100/loki/api/v1/query_range \
  | jq '.data.resultType, (.data.result | length)'
# "matrix"
# 6

# READ-ONLY: confirm the value is sane.
curl -s -u "$LOKI_USER:$LOKI_PASS" \
  --data-urlencode 'query=quantile_over_time(0.99, {job="checkout", cluster="prod-eu"} | json | unwrap duration_ms [5m]) by (instance)' \
  -G http://loki.internal:3100/loki/api/v1/query \
  | jq '.data.result[] | {instance: .metric.instance, p99: .value[1]}'
# {"instance":"checkout-7f9c","p99":"412.5"}
# {"instance":"checkout-8k3d","p99":"388.1"}

How to validate it

Three signals confirm the metric is live and sane:

# READ-ONLY: the produced metric has the expected cardinality.
curl -s -u "$MIMIR_USER:$MIMIR_PASS" \
  --data-urlencode 'query=count(app_log_latency_p99)' \
  -G http://mimir.internal:9009/prometheus/api/v1/query \
  | jq '.data.result[0].value[1]'
# "6"

# READ-ONLY: the percentile values are bounded by the application's expected envelope.
curl -s -u "$MIMIR_USER:$MIMIR_PASS" \
  --data-urlencode 'query=app_log_latency_p99' \
  -G http://mimir.internal:9009/prometheus/api/v1/query \
  | jq '.data.result[] | {instance: .metric.instance, p99_ms: .value[1]}'
# {"instance":"checkout-7f9c","p99_ms":"412.5"}
# {"instance":"checkout-8k3d","p99_ms":"388.1"}

# READ-ONLY: cross-check with a known native metric (when available).
# Compare app_log_latency_p99 to a native histogram quantile over
# the same window. A persistent gap larger than 20% indicates the
# log-derived path is missing lines or parsing wrong.

A working latency metric produces a value within the application’s expected envelope (p99 well below the slowest known path), tracks the native metric (when present) within a small margin, and shows a stable per-instance cardinality.

How it can fail

1. Parser failures drop the line before unwrap. A JSON parse failure removes the line from the query; the unwrap never sees the value. Symptom: p99 is suspiciously low compared to the native metric.
2. The duration field is renamed. A library upgrade renames duration_ms to latency_ms; the unwrap finds no field; the metric reads as no data. Symptom: the latency panel flatlines; a separate parser-failure metric should rise.
3. The window is too short for low-traffic services. A service at 1 req/s over a 1-minute window has 60 samples; the quantile is computed over 60 numbers, which floats. Symptom: the panel is jagged, the alert fires intermittently.
4. The window is too long for high-traffic services. A service at 10,000 req/s over a 1-hour window has 36 million samples per evaluation. Symptom: ruler CPU climbs; rule evaluations miss their interval.
5. Cardinality on the by clause. A rule with by (instance, request_id) produces millions of series. Symptom: remote-write target rejects with 4xx; loki_ruler_remote_write_dropped_samples_total rises.
6. Unit drift. The application changes from duration_ms: 412 to duration: "412ms" (string, not number). The unwrap finds no numeric field. Symptom: metric is no data; the application’s own logs read fine.

How to troubleshoot it

The diagnostic order: does the rule evaluate, does the parser match, does the unwrap find a number, does the cardinality hold.

1. Rule evaluates? GET /loki/api/v1/rules. A missing lastEvaluation means the ruler is stuck.
2. Parser matches? Run the same expr with | json only, then with the unwrap added. An empty vector at the unwrap step but a populated vector at the parser step means the field name has drifted.
3. Field is numeric? Sample one line with {job="checkout"} | json | line_format "{{.duration_ms}}" and confirm the value is a number.
4. Window is right? If the metric floats, raise the window; if the ruler cannot keep up, lower it.
5. Cardinality bounded? count by (__name__) (app_log_latency_p99) in the target. The number should match the running instance count.
6. Inspect ruler logs. Parser failures, unwrap failures, and evaluation errors all appear in /var/log/loki/ruler.log.

Security implications

• The unwrapped field can carry sensitive data. A log line whose duration_ms is interleaved with a user_id field produces no leak on the unwrap path itself, but the wider query context may replicate other fields. Audit the log format.
• The metric is a fingerprint of traffic. A log-derived p99 exposes the service’s latency distribution to anyone with access to the target. For services with contractual SLAs, treat the percentile as confidential.
• Ruler CPU is a budgeted resource. A latency-derived rule on every service at every percentile is the most expensive discipline in this module. Budget it explicitly; cap the number of derived latency rules per cluster.

Performance implications

• Parser cost dominates. A query against JSON logs parses every line in the matching streams. The unwrap is on top of the parse. A high-traffic service at a long window is the canonical ruler-CPU killer.
• Window vs traffic trade-off. The window determines how many lines the engine must parse and quantile. Doubling the window roughly doubles the cost. Match the window to the percentile stability you actually need.
• Cardinality on the by clause. A rule that buckets by every parsed label is unbounded. The right by is instance (or instance, route) and nothing more.
• The bucket form (histogram_quantile) is cheaper than the quantile form. A bucket query reduces to a sum per bucket per evaluation; the quantile form reduces to a sort. For dashboards that show p50 and p99, two bucket queries are cheaper than two quantile queries.

Production guidance

• Use histogram_quantile over a bucketed form when the panel needs p50 and p99 side-by-side. Two queries, one bucket computation, one set of buckets.
• Use quantile_over_time for a single percentile. Cheaper than the bucket form when only one number is needed.
• Size the window to the service’s traffic. 5 minutes for 100 req/s; 15 minutes for 1 req/s; 1 minute for 10,000 req/s.
• Document the unit on the panel. duration_ms unwrapped as ms displayed in ms. Anything else invites a wrong-page.
• Treat the rule as a temporary expedient. The native histogram is the right answer; the log-derived form earns its place during the deploy regression that broke the native path.

Verification

You should now be able to answer:

• What is the difference between quantile_over_time and histogram_quantile over | unwrap for a log-derived latency, and when is each the right shape?
• Why does the unwrap step require a numeric field, and what happens when the field is renamed or changes type?
• How does the rate window interact with traffic volume, and what is the right window for a 1 req/s service?
• Which Loki self-metric catches a rule whose cardinality has grown beyond the instance count?
• When does a log-derived latency metric deserve a native replacement, and what is the decommission shape?

Quiz