Command Palette

Search for a command to run...

Hectal
Case 2.4·Logs at ScaleSEV3

“Some checkouts are slow and nobody can say which query. The answer was already in Postgres's own logs.”

case name: The database was telling us all along

Service
postgres
Impact
10% of checkouts slow (the Case 0.2 tail)
Detected by
p99 latency panel
Time to resolve
30 min

Skills you'll use on this case

the pattern parserunwrap to turn log fields into numbersquantile_over_timeslow-query logging

00 It starts

Reproduce this incident in your lab, then work the case alongside the timeline below. Try each query yourself before reading its result.

terminal
$ # 1. enable Postgres slow-query logging (add to the postgres service):
# command: ["postgres", "-c", "log_min_duration_statement=1000"]
docker compose up -d postgres
# 2. the Case 0.2 incident again
curl -s -X POST localhost:8080/admin/chaos -H 'content-type: application/json' -d '{"scenario":"slow-checkout"}'
── lab output ──
{"active":["slow-checkout"]}

01 The investigation

  1. 13:05

    ALERT

    p99 /checkout above 1 s — the familiar slow tail

    Traces (Case 0.4) would point at 'the database'. This time, ask the database itself which statements are slow.

  2. 13:08

    QUERY

    Postgres logs are plain text, not JSON

    LogQL· Loki
    {container=~".*postgres.*"} |= "duration:"
    result
    2026-09-26 13:08:02.418 UTC [212] LOG:  duration: 3003.271 ms  statement: select pg_sleep(3)
2026-09-26 13:07:57.102 UTC [209] LOG:  duration: 3002.884 ms  statement: select pg_sleep(3)
...
  3. 13:12

    QUERY

    Parse it with pattern: literal text plus named captures

    The pattern parser matches the line against a template: <name> captures a field, <_> skips one, and everything else must match literally. It's much easier to read than a regex for fixed-format logs like Postgres, nginx, or HAProxy.

    LogQL· Loki
    {container=~".*postgres.*"} |= "duration:"
  | pattern "<_> <_> <_> [<pid>] LOG:  duration: <duration> ms  statement: <statement>"
  | line_format "{{.duration}} ms  {{.statement}}"
    result
    3003.271 ms  select pg_sleep(3)
3002.884 ms  select pg_sleep(3)
...
  4. 13:16

    QUERY

    Turn the parsed duration into a metric — by statement

    unwrap duration makes the extracted field the sample value, so range functions like quantile_over_time and avg_over_time can compute on it. That gives latency per SQL statement straight from Postgres logs, with no metrics exporter.

    LogQL· Loki
    quantile_over_time(0.99,
  {container=~".*postgres.*"} |= "duration:"
    | pattern "<_> <_> <_> [<pid>] LOG:  duration: <duration> ms  statement: <statement>"
    | unwrap duration [10m]
) by (statement)
    result
    {statement="select pg_sleep(3)"}  3003.9
  5. 13:35

    RESOLVED

    The slow statement is identified and fixed

    In real life you'd see a genuine statement here, such as a missing index on orders(product_id) or a sequential scan, and you'd run EXPLAIN ANALYZE on it next.

Root cause

A specific SQL statement was intermittently slow. Postgres logs every statement over the threshold with its exact duration and text, but nobody collected or parsed those logs. Once parsed with pattern, they gave per-statement latency directly.

02 The concepts behind it

Parsers: json, logfmt, pattern, regexp

| json and | logfmt for structured logs. | pattern "..." for fixed-layout text logs: fast and readable. | regexp "..." with named groups when the layout varies. All extract fields at query time, which is the Loki way (Case 0.3), so parsing a new log format never requires reindexing.

Logs as metrics: unwrap

Many systems log numbers you'd love as metrics: durations, sizes, counts. | unwrap field turns a parsed numeric field into the sample value for avg_over_time, quantile_over_time, sum_over_time, max_over_time, and friends. It's perfect for exploration and for systems you can't instrument, but for high-volume, always-on use a real metric is much cheaper to query.

Third-party software already emits signals

Databases, proxies, queues, and runtimes have slow-query logs, access logs, and stats views (pg_stat_statements), and usually Prometheus exporters (postgres_exporter, redis_exporter). Collecting and parsing what they already produce is often the fastest win in observability.

03 The fix

  1. 01Switch the scenario off

    terminal
    $ curl -s -X POST localhost:8080/admin/chaos -H 'content-type: application/json' -d '{"scenario":"slow-checkout","enabled":false}'
    ── expected output ──
    {"active":[]}

04 Make sure it never surprises you again

  1. 01Keep slow-query logging on, and add postgres_exporter

    log_min_duration_statement (e.g. 500 ms) is cheap and invaluable. For continuous metrics, run postgres_exporter and enable the pg_stat_statements extension, then graph mean and total time per query with PromQL instead of parsing logs.

    obs-lab/docker-compose.ymladd to fileyaml
      postgres-exporter:
    image: quay.io/prometheuscommunity/postgres-exporter:v0.17.1
    environment:
      DATA_SOURCE_NAME: postgresql://postgres:shoplite@postgres:5432/shoplite?sslmode=disable
    # then add a scrape job for postgres-exporter:9187 in prometheus.yml

05 Your turn: write the query

Run each one against your lab before revealing the answer. Share your own version in the comments; there's usually more than one correct query.

01

Write a LogQL query counting slow statements per minute, grouped by statement text.

02

Using pino-http's JSON logs instead of metrics, compute ShopLite's average responseTime per req_url over 5 minutes.

06 Interview questions from this case

01

How would you get latency data out of a system that only writes text logs?

02

What's log_min_duration_statement in Postgres and how would you use it?

0/4 · 0%