Query Latency

A 14:20 page. Customers report “checkout is slow.” The application server shows CPU at 35% and memory at 60%. Memcached hit ratio is 94%. The database server shows CPU at 18%, IO at 4 MB/s. The database “looks fine.” The on-call engineer pulls out pg_stat_statements and finds one query — a single normalised query text — accounting for 88% of total database time, with a mean of 12 ms and a stddev_time of 89 ms. A p99 of 380 ms. That query was a LEFT JOIN introduced in last week’s deployment; the migration was on a smaller dataset in staging.

This is the question that pg_stat_statements was written to answer. Every relational database answers the same question in its own way: which query is slow, how often does it run, and how bad is the slow case relative to the typical one? Mean latency hides the answer. p99 latency is the answer.

What query latency is

Query latency is the wall-clock duration of a single statement from the moment the database receives the Execute message to the moment it sends the last byte of ReadyForQuery. The metrics are produced by an internal counter in the database that runs for every statement and aggregates by normalised query text — the same statement with literal values replaced by placeholders.

  Application sends:
    SELECT * FROM orders WHERE user_id = 42 AND status = 'paid'

  Database records:
    queryid   = 0xABCD1234     (hash of normalised text)
    query     = "SELECT * FROM orders WHERE user_id = $1
                 AND status = $2"
    calls     = 18394
    total_time = 47.2 s        (sum over 14 hours)
    mean_time = 2.6 ms
    stddev_time = 0.7 ms       (stddev of per-call time)
    rows      = 5              (median rows per call)

Two numbers matter on the same row. Mean time is the total time divided by the number of calls. Standard deviation time (stddev_time) is the standard deviation of per-call execution time. The relationship between the two tells you whether the query is uniformly slow (mean high, stddev low) or occasionally slow (mean moderate, stddev high — the p99 case).

PostgreSQL exposes the row through pg_stat_statements; the exporter turns it into a Prometheus metric. MySQL exposes the equivalent through performance_schema.events_statements_summary_by_digest; the digests in MySQL are computed by the server using a normalised representation. Both shapes carry the same numbers under different column names.

Why a sysadmin cares

Mean latency is, by itself, useless for production alerting. Three reasons:

1. The mean smooths over the worst cases. A mean of 50 ms covers a query that is consistently 50 ms and a query that is 1 ms half the time and 99 ms the other half. The user experience of the second is determined by the 99 ms case, not by the 50 ms mean.
2. The mean is dominated by common-case queries. A SELECT 1 health check run once a second has a mean of 0.2 ms and a calls count of 86,400 per day. The query that paid the database bill in the previous incident does not appear at the top of mean_time. It appears at the top of total_time because the sum of mean * calls is what the database actually spent.
3. Slowness is rarely uniform. A query that returns 1 row in 2 ms the first time and scans ten million rows in 600 ms the second time has a mean of 4 ms and a p99 of roughly 500 ms. The application sees both. The alerting signal is p99, not mean.

Two more numbers are routinely useful:

• Calls per second. calls / total_time against the time range is the load profile. A query that is healthy at 100 calls/sec may have a different plan at 10,000 calls/sec and fall off a cliff.
• Row spread. rows / calls is the median rows returned. Useful for catching N+1-style regressions: a single SELECT * followed by a per-row SELECT has a constant middle-tier query and a thousand-fold rise in the inner query’s row count.

How it works

Each database instruments statements differently, but the shape is the same. The instrumentation runs inside the query executor, captures a start time at the moment the executor takes ownership of the statement, and captures an end time at the moment the executor releases the statement back to the connection. The wall-clock duration is split into:

  total_time =
      parse_time +        # parse the SQL text
      plan_time +         # build the execution plan
      execute_time +      # run the plan
      commit_time         # commit the transaction (if not implicit)

Most production observability only needs total_time. The splits are useful when pg_stat_statements is paired with auto_explain or when performance_schema.events_stages_* tables are joined to the digest table.

The instrumentation hook is not free; sampling around 1% of statements is the default configuration in MySQL (performance_schema_events_statements_history_long size), and PostgreSQL with pg_stat_statements instruments every statement by default. Tune pg_stat_statements.track = top to capture the top queries by total time; track = all records utility statements (BEGIN, COMMIT, SHOW) and is rarely useful in production.

  Application          PostgreSQL                MySQL
  ---------            ----------                -----
  statement -----> parse -> normalise           parse -> digest
                          (hash of normalised)   (server-computed)
                          lower(string)
                          replace literals
                            with $N
                          strip whitespace
                          |
                          v
                pg_stat_statements        performance_schema.
                  (hash bucket)           events_statements_summary
                                            _by_digest
                          |                     |
                          v                     v
                queryid label +           schema_name + digest +
                 latency histogram        latency stats
                          |                     |
                          +----------+----------+
                                     |
                              postgres_exporter /
                              mysqld_exporter
                                     |
                              Prometheus sample

How to configure it

Step 1: PostgreSQL — load and configure the extension.

# postgresql.conf
shared_preload_libraries = 'pg_stat_statements'
pg_stat_statements.max = 10000
pg_stat_statements.track = top
pg_stat_statements.track_utility = off
pg_stat_statements.track_planning = off       # off: cheaper
pg_stat_statements.save = on                  # persist across restarts

max = 10000 is the default. Grow it to 20000 on hosts with very high query cardinality (a query that generates thousands of distinct normalised texts in a day will evict other rows). track = top is the right setting for production telemetry; track = all includes every BEGIN, COMMIT, and PREPARE.

Step 2: enable the collector in the exporter.

# /etc/default/prometheus-postgres-exporter
ARGS="--collector.stat_statements"

The collector issues SELECT pg_datname, pg_stat_statements.* FROM pg_stat_statements (or the equivalent view in newer versions) and emits one Prometheus sample per row.

Step 3: alert on the tails.

A reasonable production alert uses the per-digest total_time rate against the database baseline, not a single absolute threshold:

# /etc/prometheus/rules/query_latency.yaml (excerpt)
groups:
  - name: query_latency
    rules:
      - alert: SlowQueryAtP99
        # Per normalised query, the rate of total_time for queries
        # whose mean exceeds 20 ms has risen two-fold over 24 hours.
        # READ-ONLY for the alert itself.
        expr: |
          (sum by (datname, query) (rate(pg_stat_statements_total_time_seconds[15m])) > 0.02
            and
           sum by (datname, query) (rate(pg_stat_statements_total_time_seconds[15m]))
            >
           2 * sum by (datname, query) (avg_over_time(pg_stat_statements_total_time_seconds[24h] offset 1d)))
        for: 15m
        labels:
          severity: ticket
        annotations:
          summary: 'Slow query at p99 on {{ $labels.instance }}: {{ $labels.query }}'

      - alert: QueryMeanAboveBudget
        # Any single query whose 1-hour mean runs above the application
        # team's stated budget.
        expr: |
          pg_stat_statements_mean_time_seconds > 0.050
        for: 30m
        labels:
          severity: ticket

Step 4: MySQL — the equivalent shape.

# /etc/default/prometheus-mysqld-exporter
ARGS="--collect.perf_schema.events_statements \
      --collect.perf_schema.events_statements_summary_by_digest \
      --collect.perf_schema.events_stages"

The exporter emits the same total_time, mean_time, stddev_time metrics under the mysql_perf_schema_* prefix. The query_sample_text label carries a representative statement; the schema and digest labels are the per-query identifiers.

How to validate it

Every step is READ-ONLY.

# 1. Confirm pg_stat_statements is installed and visible to the exporter.
psql -h 10.0.4.10 -U db_exporter -d app \
  -c "SELECT count(*) AS rows FROM pg_stat_statements;"

 rows
------
  847

# 2. Read the top queries by total time. This is the operator-facing view.
psql -h 10.0.4.10 -U db_exporter -d app <<'SQL'
SELECT
  calls,
  round(total_exec_time::numeric / 1000, 1) AS total_sec,
  round(mean_exec_time::numeric, 1)           AS mean_ms,
  round((total_exec_time / calls)::numeric, 1) AS mean_per_call_ms,
  left(query, 60)                              AS query
FROM pg_stat_statements
WHERE calls > 0
ORDER BY total_exec_time DESC
LIMIT 5;
SQL

 calls | total_sec | mean_ms | mean_per_call_ms |             query
-------+-----------+---------+------------------+---------------------------------
 18294 |   284.1   |  15.5   |      15.5        | SELECT * FROM orders WHERE ...
  3940 |    97.7   |  24.8   |      24.8        | UPDATE inventory SET quantity...
 20103 |    42.0   |   2.1   |       2.1        | SELECT * FROM users WHERE ema...
  8901 |    18.3   |   2.0   |       2.0        | INSERT INTO audit_log (event_...

# 3. Inspect the worst tail. PostgreSQL 13+ exposes a per-digest
#    min_time, max_time, mean_time, stddev_time, and rows.
psql -h 10.0.4.10 -U db_exporter -d app <<'SQL'
SELECT left(query, 60) AS query,
       calls,
       round(mean_exec_time::numeric, 1) AS mean_ms,
       round(stddev_exec_time::numeric, 1) AS stddev_ms
FROM pg_stat_statements
ORDER BY mean_exec_time DESC
LIMIT 5;
SQL

# 4. Confirm the exporter emits the same shape.
curl -sf http://10.0.4.7:9187/metrics | grep -E '^pg_stat_statements_(mean|total)_time'

# 5. Confirm Prometheus is recording the alerting rule state.
promtool check rules /etc/prometheus/rules/query_latency.yaml

The first four outputs confirm the extension is loaded, the table is populated, the slowest query is identifiable by text, the worst tail is identifiable by stddev, the exporter is publishing, and the alerts parse. Confirming the alert state on a staging instance is the next step.

How it can fail

Six failure shapes cover the overwhelming majority of production query-latency incidents.

1. Plan regression after deployment. A query whose plan was a nested-loop join on 1,000 rows becomes a hash join on 1,000,000 rows after a column is added or its statistics are stale. Symptom: pg_stat_statements_mean_time and total_time rise in lockstep for the affected query; stddev_time rises modestly. The plan has not changed.
2. Cold-cache first run. A query that is normal in warm state is slow on the first execution after a database restart. Symptom: mean_time is normal for the steady-state run, but a small fraction of calls (the first ones) show max_time orders of magnitude higher. stddev_time follows the relationship mean << stddev.
3. Parameter sniffing. A query that is fast with WHERE status = 'paid' is slow with WHERE status = 'pending' because the parameter distribution pushes the planner to a different plan. Symptom: mean_time of the same digest rises; the difference shows up only when a caller hits the un-tuned parameter. Application-side or query-side parameterisation hides the issue.
4. Index bloat and statistics drift. A query whose plan is correct on fresh statistics is slow after ANALYZE has not run in days and table growth has tipped a planner threshold. Symptom: pg_stat_user_tables.n_live_tup and pg_stat_user_tables.n_mod_since_analyze show drift; the same query becomes incrementally slower until ANALYZE is forced.
5. pg_stat_statements.max exhaustion. When the normalised-text cardinality exceeds max, the extension evicts old entries. Symptom: the calls and total_time columns of evicted queries reset to near zero; p99 alerting mis-fires; the same query on a different host is fine.
6. Histogram bucket boundary at the misleading mean. A query whose mean_time is 4 ms and max_time is 4 s shows up at the bottom of the mean_time-sorted list and at the top of the max_time list. Symptom: alerting only on mean misses the bug; alerting on p99 from a histogram bucket catches it. The lesson in Slow Queries Anatomy returned to this same shape.

How to troubleshoot it

Diagnose in this order; each step is cheaper than the next.

1. Read the mean-time-per-query panel. Identify the top three queries by total_time. The names are the first evidence.
2. Read the stddev or max_time of each. If stddev_time is much larger than the mean, the distribution has a heavy tail. Inspect pg_stat_activity for the wait events of the slow sessions (this lesson’s next: lock contention).
3. Read EXPLAIN (ANALYZE, BUFFERS) for the suspect query. The output reveals whether the plan is sound and whether the buffer cache is serving the working set. The actual rows versus estimated rows divergence is the planner’s first complaint.
4. Check the application’s view. Application-side traces (Tempo) for the same request confirm the question text and the parameters. The application’s view says what the database saw.
5. Look for recent changes. A Git log on the application for queries whose plan has not changed at the database is often the cause.
6. Run the query manually with a representative parameter set. Often the most direct evidence of the planner’s choice.

Security implications

Two surfaces exist.

• Query text leakage. pg_stat_statements.query is the normalised text. With track = all it includes PREPARE and DEALLOCATE, the queries themselves and not their parameter values (those are not recorded). In MySQL, events_statements_summary_by_digest includes a sample text that may include parameter values for track = all. Treat the exporter endpoint as a confidential source; do not publish it.
• Query payload content. For PostgreSQL, the digest is derived from the text, not from the parameters. The exporter does not see credentials. For MySQL, the digest may include parameter values when track = all is set; bind the exporter to an internal network.

Performance implications

The instrumentation cost is real and is paid on the database host.

• PostgreSQL. pg_stat_statements instruments every statement whose track is enabled. At one million statements per second the cost is measurable; at the typical production QPS of a few thousand statements per second it is noise. The bigger risk is the memory consumed by max; bound it relative to the host’s available RAM.
• MySQL. performance_schema is enabled at the server level; the cost is fixed by the configuration of performance_schema_events_statements_history_long_size and is small in absolute terms.

The export itself is the cheap step. The expensive step is reading the data on every scrape. The exporter’s per-scrape query is SELECT pg_stat_statements.* and is a fixed cost.

Production guidance

• Set pg_stat_statements.max to a value related to host memory rather than to “a big number”.
• Use track = top for production telemetry; switch to track = all only when investigating a specific incident.
• Alert on p99 or stddev_time from a recording rule; do not alert on the raw mean.
• Pair pg_stat_statements with EXPLAIN (ANALYZE, BUFFERS) on the suspect query from the operator console; the planner’s view is the most reliable single signal.
• For MySQL, ensure performance_schema is enabled at the server level and that the digest collection is on.
• Treat pg_stat_statements reset (pg_stat_statements_reset()) as a force-clear, not a routine; run it after a major deployment only.

Verification

You should now be able to answer:

• What does pg_stat_statements record for every statement, and what is the difference between mean time and stddev time?
• Why is mean latency a poor alerting signal in production?
• What does the equivalent MySQL collector look like under performance_schema?
• What three alert thresholds are worth defining for query latency, and which is the right one to page on?
• What is the most common cause of plan regression after a successful deployment?

Quiz