跳转到主要内容

31 观察数据库运行

使用 pg_stat_statements、pg_stat_activity 和累计统计信息视图,找出什么慢、什么卡住,以及哪些情况值得告警。

在一分钟内,我们的测试服务器用 pgbench 运行了一组混合负载:按主键查找 users 中的行、向 events 插入、项目列表和一份小报表。下面列出调用次数最多和最少的查询:

 calls | total_ms | pct  |                  query
-------+----------+------+------------------------------------------
   525 |    29923 | 66.1 | select kind, count(*) from events where
 31137 |      800 |  1.8 | select id, email, name from users where

一条查询的调用次数只有另一条的 1/59,消耗的数据库时间却是它的 37 倍:占服务器全部工作量的三分之二。请求速率仪表盘看不出这一点。100 ms 的慢查询日志也看不出来,因为一次典型调用大约只花 57 ms。

你能看到的慢查询很少是真正的问题。本章的这些视图会找出你看不到的那个问题,最后给出一份值得叫醒别人的短清单。它们几乎都读取累计统计信息系统:由每个后端进程递增的计数器,一直保留到重置或崩溃。单个计数器几乎说明不了什么;要看速率和排名。

从 pg_stat_statements 开始

pg_stat_statements 是 Postgres 最有用的可观测性工具。它按归一化后的结构对语句分组,并为每种结构保留累计总量:调用次数、时间、行数、缓冲区、WAL 和临时文件。它随 Postgres 一起提供,所有主要托管服务也都支持它。

pg_stat_statements 在服务器启动时加载

它必须预加载,所以打开它需要重启:

shared_preload_libraries = 'pg_stat_statements'   # restart required
track_io_timing = on                              # adds I/O time columns

然后在每个要查询它的数据库中执行 create extension pg_stat_statements;数据是整个集簇级别的。现代 Linux 上 track_io_timing 的开销很小(可用 pg_test_timing 检查),它记录的 I/O 时间是你能收集到的最有用的数据之一。

常量会变成占位符,因此每次主键查询都归为一行,以 queryid 为键;这个值也会在 pg_stat_activity 中显示为 query_id。

深入阅读:语句如何分组,以及 PostgreSQL 18 改了什么

pg_stat_statements.max(5,000)限制不同语句的数量;默认值 track = top 只统计顶层语句。从 PostgreSQL 18 开始,计算 queryid 哈希时会按名称标识表,因此删除并重建表后仍会保留历史。反过来,不同模式中同名的表现在会共享一条记录;如果每个租户使用一个模式,那么每个租户的 select ... from orders 都会合并成一行。把 %Q 加入 log_line_prefix,日志就会带上 queryid。

过去,发送 in ($1, $2)、接着发送 in ($1, $2, $3) 的 ORM 会让视图为每种列表长度各生成一条记录。PostgreSQL 18 会把它们合并成一条,显示为 in ($1 /*, ... */)。使用数组的 = any($1) 仍是更好的习惯:在所有版本中都只有一种语句结构(经得住数据增长的查询)。

动手验证 · lab 30-observability
select lab.prove(
  'pg_stat_statements is preloaded, compute_query_id is auto, and it tracks top-level statements',
  current_setting('shared_preload_libraries') like '%pg_stat_statements%'
  and current_setting('compute_query_id') = 'auto'
  and current_setting('pg_stat_statements.track') = 'top');

完整实验脚本

动手验证 · lab 30-observability
select count(*) from projects where id = 1;
select   count(*)
  from projects   where id = 2;

select lab.prove(
  'whitespace and constants do not change the queryid',
  (select calls from lab.stmts where query = 'select count(*) from projects where id = $1') = 2);

create table scratch (id int);
select count(*) from scratch where id = 1;
drop table scratch;
create table scratch (id int);
select count(*) from scratch where id = 1;

select lab.prove(
  'PostgreSQL 18 hashes tables by name: a dropped and recreated table keeps its queryid',
  (select calls from lab.stmts where query = 'select count(*) from scratch where id = $1') = 2);

完整实验脚本

动手验证 · lab 30-observability
select count(*) from users where id in (1, 2);
select count(*) from users where id in (1, 2, 3, 4, 5);
select count(*) from users where id in (7, 8, 9, 10, 11, 12, 13, 14, 15, 16);
select count(*) from users where id in ($1, $2) \bind 1 2 \g
select count(*) from users where id in ($1, $2, $3) \bind 1 2 3 \g

select lab.prove(
  'PostgreSQL 18 collapses IN lists of any length into one entry, shown as in ($1 /*, ... */)',
  (select calls from lab.stmts
   where query = 'select count(*) from users where id in ($1 /*, ... */)') = 5);

完整实验脚本

用四种方式给同一视图排序,先看总时间

每次排查都从同一个视图开始,按四种方式排序。时间都花在哪里? 按 total_exec_time 排序。这是任何服务器上第一条该运行的查询:

select calls,
       round(total_exec_time) as total_ms,
       round((100 * total_exec_time
              / sum(total_exec_time) over ())::numeric, 1) as pct,
       left(regexp_replace(query, '\s+', ' ', 'g'), 40) as query
  from pg_stat_statements
 order by total_exec_time desc
 limit 4;
 calls | total_ms | pct  |                  query
-------+----------+------+------------------------------------------
   525 |    29923 | 66.1 | select kind, count(*) from events where
 10484 |     9617 | 21.2 | insert into events (account_id, project_
  5619 |     4930 | 10.9 | select p.id, p.name, (select count(*) fr
 31137 |      800 |  1.8 | select id, email, name from users where

总时间等于调用次数乘以平均时间。修复排名第一的语句,可以释放这个服务器三分之二的查询时间;修复调用最频繁的语句,最多只能释放 1.8%。

对用户来说,什么慢? 按 mean_exec_time 排序,跳过执行次数很少的语句。这份报表的平均值是 57 ms。较大的 max_exec_time 表示一条查询有时会慢得多,就像这里的插入一样:平均 0.92 ms,最大 254 ms,而当时磁盘正被其他工作占用。

什么触碰的页面最多? 按 shared_blks_hit + shared_blks_read 除以 calls 后的结果排序。耗时有噪声,页面数没有。整本书的论点可以写成这样一个查询:

 calls | blks_per_call | hit_pct |                  query
-------+---------------+---------+------------------------------------------
   525 |         35248 |    34.0 | select kind, count(*) from events where
  5619 |           257 |    99.6 | select p.id, p.name, (select count(*) fr
 10484 |            22 |    93.5 | insert into events (account_id, project_
 31137 |             3 |    67.7 | select id, email, name from users where

这份报表每次调用会触碰 35,248 个页面,也就是 275 MB:整张 events 表,而它在 project_id 上没有索引(B-树挑起大梁可以解决这一点)。主键查询只触碰 3 个页面。项目列表为 20 行触碰 257 个页面,原因是外键没有索引。每次调用的块数是应该压下去的数字,而且不同运行之间几乎不变,所以可以作为前后对比指标(只改一件事,并端到端测量)。

什么写入最多? 按 wal_bytes 排序。插入在一分钟内写入了 75 MB 的 WAL,平均每行约 7.5 KB,几乎全是整页镜像(先记日志,再写数据)。WAL 量会影响副本延迟、备份大小和磁盘吞吐量。

深入阅读:其他排序查询,以及每次插入的五条 WAL 记录
动手验证 · lab 30-observability
select lab.prove(
  'the report ran over 20 times less often than the lookup but took over 5 times more total time',
  (select calls from w where name = 'lookup') > 20 * (select calls from w where name = 'report')
  and (select total_exec_time from w where name = 'report')
      > 5 * (select total_exec_time from w where name = 'lookup'));

select lab.prove(
  'the report touches the entire events table every call (blocks per call within 5% of its pages)',
  (select (shared_blks_hit + shared_blks_read)::numeric / calls from w where name = 'report')
    between 0.95 * (select relpages from pg_class where relname = 'events')
        and 1.05 * (select relpages from pg_class where relname = 'events'));

select lab.prove(
  'the primary key lookup touches 3 pages: root and leaf of users_pkey, plus one heap page',
  (select (shared_blks_hit + shared_blks_read)::numeric / calls from w where name = 'lookup')
    between 3 and 3.5
  and (select level from bt_metap('users_pkey')) = 1);

完整实验脚本

其他排名只是替换 order by:mean_exec_time(加上 where calls > 100)、shared_blks_hit + shared_blks_read,或者 wal_bytes。rows / calls 可以找出返回行数超过应用实际使用量的查询。WAL 排名的第一行是插入:10,484 次调用、53,067 条记录、9,272 个整页镜像。这大约是每行五条记录:堆元组、主键条目,以及外键检查的三个父行各自对应的一条行锁(提交记录发生在语句之后,所以不计入)。这些锁会在每次插入时触碰三个随机的父表页;服务器当时又频繁执行检查点,整页镜像就是在这里产生的。

还有几个值也值得知道:temp_blks_written(溢写到磁盘的排序或哈希)、shared_blk_read_time(启用 track_io_timing 时;PostgreSQL 17 之前叫 blk_read_time),以及 plans 和 total_plan_time。后两者只有在打开 pg_stat_statements.track_planning = on 后才会填充;该选项默认关闭,因为有开销。

动手验证 · lab 30-observability
select lab.prove(
  'the project list touches about 257 pages for 20 rows (between 200 and 320)',
  (select (shared_blks_hit + shared_blks_read) / calls from w where name = 'projects')
    between 200 and 320);

select lab.prove(
  'each insert writes about five WAL records: heap tuple, primary key entry, and three foreign key row locks',
  (select wal_records::numeric / calls from w where name = 'insert') between 4.9 and 5.6);

-- one insert, read straight from the WAL with pg_walinspect
select lab.prove(
  'one insert transaction: heap INSERT, B-tree INSERT_LEAF, three heap LOCK records, then COMMIT',
  (select array_agg(resource_manager || '/' || record_type order by start_lsn)
   from pg_get_wal_records_info(:'wal_start', :'wal_end')
   where xid = :'insert_xid'::xid)
  = array['Heap/INSERT', 'Btree/INSERT_LEAF', 'Heap/LOCK', 'Heap/LOCK', 'Heap/LOCK',
          'Transaction/COMMIT']);

完整实验脚本

做快照并求差值;不要重置

几周之后,累计历史会占据主导地位,昨天才变慢的查询会藏在它漫长而快速的过去里。不要按计划重置。做快照并求差值:每隔几分钟复制一次视图并计算增量,这样就能问“昨天 14:00 到 14:15 之间,排名靠前的查询是什么”。大多数监控代理会替你做这件事。

在一次基准测试之前,有针对性地调用 pg_stat_statements_reset(userid, dbid, queryid) 是可以的。同时观察 dealloc(它位于 pg_stat_statements_info 中):它不断升高,意味着语句超过 pg_stat_statements.max 后正在被淘汰。

pg_stat_activity 显示此刻发生的事

pg_stat_statements 记录的是过去,pg_stat_activity 记录的是此刻:每个服务器进程一行,包括它正在运行什么、从什么时候开始运行,以及在等待什么。它的 state 可以是 active、idle(等待客户端的下一条语句,这是正常状态),或者 idle in transaction:位于一个打开的事务中,持有自己的锁,并可能持有快照,而应用正在做别的事。几毫秒属于正常情况;几分钟就是缺陷。

没有等待事件的活动会话正在占用 CPU

wait_event_type 和 wait_event 表示后端进程正在等待什么;这两列均为空的 active 行表示该会话正在 CPU 上运行。Lock 是重量级锁(可以锁表,也可以是另一个事务持有行锁时的 transactionid);LWLock 表示内部结构上的争用(解决 LWLock 等待要调整负载,而不是查询);IO 表示读取页面或刷新 WAL;Client 表示等待应用。pg_wait_events(PostgreSQL 17+)记录了每一种等待事件。每秒统计十次,你就得到了一个画像。

深入阅读:这些示例背后的会话

本节的示例来自账户 7 上的三个会话。会话 a 在事务中更新了该账户,然后运行 pg_sleep(60)。会话 b 打开一个事务,读取了一些用户,然后没有提交就进入空闲。会话 c 尝试更新同一个账户,于是被阻塞。睡眠中的会话状态是 active,而不是 idle:它正在运行一条语句,等待事件是 Timeout:PgSleep;应用步骤在数据库内运行时,慢就会呈现为这种样子。会话 a 还有一个 backend_xid,因为它执行过写入;会话 b 没有,因为事务要到第一次写入时才会取得 XID。

动手验证 · lab 30-observability
-- a: begin; update accounts set name = name where id = 7; select pg_sleep(60)
-- b: begin; select count(*) from users where account_id = 7;  (then idle)
-- c: update accounts set plan = plan where id = 7;            (blocks on a)
select lab.prove(
  'a session sleeping inside its transaction is active, waiting on Timeout/PgSleep, and has a backend_xid',
  (select state = 'active' and wait_event_type = 'Timeout' and wait_event = 'PgSleep'
          and backend_xid is not null
   from pg_stat_activity where pid = :pid_a));

select lab.prove(
  'a session waiting for a row waits on Lock/transactionid, and pg_blocking_pids names the holder',
  (select wait_event_type = 'Lock' and wait_event = 'transactionid'
          and pg_blocking_pids(pid) = array[:pid_a]
   from pg_stat_activity where pid = :pid_c));

完整实验脚本

backend_xmin 指出阻挡清理的事务

长事务会阻塞清理、持有锁,并让迁移超时。按年龄列出所有打开的事务:

select pid, state,
       date_trunc('second', now() - xact_start)   as xact_age,
       date_trunc('second', now() - state_change) as in_state,
       backend_xid, backend_xmin,
       left(query, 40)                            as last_query
  from pg_stat_activity
 where xact_start is not null and pid <> pg_backend_pid()
 order by xact_start;
 pid  |        state        | xact_age | in_state | backend_xid | backend_xmin | ...
------+---------------------+----------+----------+-------------+--------------+----
 9726 | active              | 00:00:05 | 00:00:05 |     1297936 |      1297901 | ...
 9733 | idle in transaction | 00:00:05 | 00:00:05 |             |              | ...
 9745 | active              | 00:00:03 | 00:00:03 |     1297939 |      1297901 | ...

idle in transaction 且 in_state 很大的会话,是被遗忘的事务;query 是它最后运行的那条语句。backend_xmin 是该会话快照所需的最老事务,也正是它阻挡清理的原因。会话 9733 处于读已提交隔离级别的空闲状态,没有这个值,因为读已提交会在语句之间丢弃快照;repeatable read 则会在整个事务中保留快照。

pg_blocking_pids(pid) 会显示谁阻塞了谁:9745 的更新被 {9726} 阻塞,后者更新了同一个账户但还没有提交。发生事故时,pg_cancel_backend(9726) 会取消它的语句并释放行锁;处于 idle in transaction 的会话没有正在运行的语句可取消,所以要用 pg_terminate_backend 结束它(大家都得排队)。

关注最老的 xmin,而不只是最老的查询

真正会悄悄伤害数据库的是旧快照,而不是慢查询。清理无法移除整个数据库中最老快照可能需要的任何行版本。检查 max(age(backend_xmin))(在 pg_stat_activity 中),以及复制槽的 xmin 和使用 hot_standby_feedback 的备库的相应值;它们都会阻碍同一个 xmin 清理界限(xmin horizon)推进(清理无法移除旧快照可能需要的内容)。

深入阅读:谁持有 xmin,实证检查

隔离级别决定空闲事务是否会阻止清理界限推进。会话 b 处于读已提交的空闲状态,既没有 XID,也没有 xmin:它在语句之间不持有快照,所以完全不会阻塞清理,尽管它仍然持有锁。第四个会话 d 执行了 begin isolation level repeatable read,运行一次 select 后进入空闲;只要事务保持打开,它的 backend_xmin 就会一直存在,因为之后的每条语句都必须看到同一个快照。因此,一个忘记提交的可重复读报表任务,比一个做同样事情的应用事务更糟。要找出阻碍清理界限推进的会话:

select pid, application_name, state, age(backend_xmin) as xmin_age
  from pg_stat_activity
 where backend_xmin is not null
 order by age(backend_xmin) desc
 limit 5;
动手验证 · lab 30-observability
select lab.prove(
  'an open read committed transaction that has not written shows idle in transaction, ClientRead, no xid, no xmin',
  (select state = 'idle in transaction' and wait_event = 'ClientRead'
          and backend_xid is null and backend_xmin is null
   from pg_stat_activity where pid = :pid_b));

select lab.prove(
  'a repeatable read transaction keeps its xmin while idle',
  (select state = 'idle in transaction' and backend_xmin is not null
   from pg_stat_activity where pid = :pid_d));

完整实验脚本

采样等待,看看时间花在哪里

看一眼 pg_stat_activity 就像拍了一张照片。每秒取十次样,持续一分钟,统计你看到的内容,你就得到了一个画像:会话的忙碌时间有多少花在 CPU、读取页面、等待锁或刷新 WAL 上。它不需要扩展,却能回答 pg_stat_statements 回答不了的问题:不是哪个查询,而是查询在等待什么。

每次采样都必须使用独立事务

创建一张表,然后从 psql 反复执行同一条插入语句:

create temp table wait_samples (
  taken_at timestamptz, pid int, application_name text, state text,
  wait_event_type text, wait_event text, query_id bigint
);

insert into wait_samples
select statement_timestamp(), pid, application_name, state,
       wait_event_type, wait_event, query_id
  from pg_stat_activity
 where backend_type = 'client backend'
   and state <> 'idle'
   and pid <> pg_backend_pid()
\watch interval=0.1 count=600

\watch 会每 100 ms 重新执行一次插入,共执行 600 次,也就是一分钟(count 是 psql 16+ 支持的参数)。每次执行都必须是独立事务:Postgres 每个事务只会为 pg_stat_activity 取一次快照,因此如果把采样循环写成一个 DO 块,它会把第一次采样记录 600 次。

深入阅读:SQL 中的采样循环必须清除快照

每次采样前调用 pg_stat_clear_snapshot(),并用 clock_timestamp() 给行加时间戳,因为 now() 和 statement_timestamp() 也会被冻结。(运行一分钟的 DO 块同样是一个运行一分钟的事务,这本身就是另一个小问题。)

动手验证 · lab 30-observability
begin;
select count(*) from pg_stat_activity where application_name = 'ws_late' \g /dev/null
select dblink_connect('ws_late', format('dbname=%s application_name=ws_late', current_database())) \g /dev/null
select pg_sleep(0.3) \g /dev/null

select lab.prove(
  'inside one transaction pg_stat_activity repeats its first snapshot: a session that connected since is invisible',
  (select count(*) from pg_stat_activity where application_name = 'ws_late') = 0);

select pg_stat_clear_snapshot() \g /dev/null

select lab.prove(
  'after pg_stat_clear_snapshot() the next read sees it',
  (select count(*) from pg_stat_activity where application_name = 'ws_late') = 1);
commit;

完整实验脚本

CPU 行高于核心数,说明正在排队

按等待事件统计采样。没有等待事件的活动会话正在占用 CPU,所以把它标成 CPU:

select coalesce(wait_event_type, 'CPU')  as type,
       coalesce(wait_event, 'running')   as event,
       count(*)                          as samples,
       round(100.0 * count(*) / sum(count(*)) over (), 1) as pct,
       round(count(*) / 600.0, 2)        as avg_sessions   -- / rounds taken
  from wait_samples
 where state = 'active'
 group by 1, 2
 order by samples desc;

在一个由四个会话组成的玩具负载上(一个在循环中空转,一个在睡眠,一个持有行锁并进入空闲,一个等待该行锁),采样 20 轮:

  type   |     event     | samples | pct  | avg_sessions
---------+---------------+---------+------+--------------
 CPU     | running       |      20 | 33.3 |         1.00
 Lock    | transactionid |      20 | 33.3 |         1.00
 Timeout | PgSleep       |      20 | 33.3 |         1.00

采样 20 轮时,查询应该除以 20,而不是 600。每一行的平均会话数都恰好是 1;处于事务中空闲的那个会话没有出现在这里,因为画像只统计 active 行。avg_sessions 是托管服务仪表盘绘图使用的单位。把 CPU 行与核心数比较:超过核心数,就说明会话正在排队等待处理器。

然后把 query_id 连接到 pg_stat_statements,看看哪些语句拥有这些等待。采样大多是 CPU 或 DataFileRead 的语句,慢是因为自己的工作量,修复点在执行计划;采样大多是 Lock 或 LWLock 的语句,慢是因为其他人的活动,修复点在它等待的对象上。

深入阅读:实证检查玩具画像,并把等待连接到语句
动手验证 · lab 30-observability
-- ws_cpu spins in a PL/pgSQL loop, ws_sleep runs pg_sleep, ws_hold updates
-- account 9 and idles in its transaction, ws_wait updates the same row;
-- 20 samples, 100 ms apart, with \watch
select lab.prove(
  'a session running a CPU loop samples as active with no wait event (at least 16 of 20)',
  (select count(*) from wait_samples
   where application_name = 'ws_cpu' and state = 'active' and wait_event is null) >= 16);

select lab.prove(
  'a session waiting for a row samples as Lock:transactionid every time',
  (select count(*) filter (where (wait_event_type, wait_event) = ('Lock', 'transactionid')) = count(*)
          and count(*) >= 18
   from wait_samples where application_name = 'ws_wait'));

完整实验脚本

select coalesce(s.wait_event_type || ':' || s.wait_event, 'CPU') as wait,
       count(*)                                                  as samples,
       left(regexp_replace(p.query, '\s+', ' ', 'g'), 40)        as query
  from wait_samples s
  left join pg_stat_statements p on p.queryid = s.query_id
 where s.state = 'active'
 group by 1, 3
 order by samples desc
 limit 10;

这个连接在多个用户或数据库运行同一语句时,可能返回两条记录;在共享服务器上,要过滤 pg_stat_statements,使用 dbid 和 userid。

动手验证 · lab 30-observability
select lab.prove(
  'a session idle inside its transaction samples as idle in transaction, Client:ClientRead',
  (select bool_and(state = 'idle in transaction' and (wait_event_type, wait_event) = ('Client', 'ClientRead'))
          and count(*) >= 18
   from wait_samples where application_name = 'ws_hold'));

完整实验脚本

大多数画像中,只有少数几种事件占主导

每一种都指向不同的修复方法:

  • CPU:查询正在做自己的工作。按总时间和每次调用的块数排序。
  • IO:DataFileRead:正在读取不在共享缓冲区中的页面。按 shared_blks_read 排序,先修查询,再考虑买更多内存。
  • LWLock:WALWrite 和 IO:WalSync:提交正在等待 WAL 到达磁盘。使用更少但更大的事务,或者更快的 WAL 存储(多个提交共享一次刷盘)。
  • Lock:transactionid:会话正在等待另一个事务持有的行。找到阻塞链的根(找到根阻塞者)。Lock:relation 通常表示锁队列中的 DDL。

采样不是计时器,但持续一分钟后,每种事件都会按其总时间的比例出现,这正是你需要用来排序的依据。要和上周比较,就持续采样:pg_wait_sampling 扩展在服务器内部完成这件事;托管服务商的“数据库负载”图表也是同一种画像(服务商仪表盘是等待事件采样器)。学会读取自己的 SQL 版本,就能读取它们中的任何一个。

表统计计数器能找出缺失和未使用的索引

在 pg_stat_user_tables 中,应该关注的是 seq_tup_read。 对一张 10 行的查找表来说,顺序扫描没问题;真正有代价的是顺序扫描读出的行。一分钟负载之后,events 显示为 1,054,772,482:一分钟读了十亿行,又是那份报表。大表如果每次扫描读到的行数很多且还在上升,就说明缺少索引。(events 统计出 1,573 次扫描,而报表运行了 525 次,因为每个并行工作进程的份额都会计入。要看速率。)

pg_stat_user_indexes 能找出没人使用的索引:连续几周 idx_scan = 0。但 events_pkey 在 10,484 次插入之后仍显示 0,因为唯一性检查不算扫描。不要因为某个索引看起来没用就删除约束背后的索引;还要检查副本,因为副本会统计自己的使用情况(idx_scan 为零只是疑点,不能据此定案)。

这些计数器归零的次数比你想象得多

累计统计信息会因 pg_stat_reset() 重置,会在崩溃时消失,也不会在从模板创建数据库时复制过去:在我们刚克隆的数据库中,100,000 个用户的 n_live_tup 读数是 0。判断索引未使用之前,先检查 stats_reset(位于 pg_stat_database 中)。

深入阅读:更多表计数器,以及实证检查

pg_stat_user_tables 中还有 n_dead_tup 和 last_autovacuum(清理不可省)、HOT 占比 n_tup_hot_upd / n_tup_upd(让更新保持 HOT)、last_seq_scan(PostgreSQL 16+),以及 total_autovacuum_time(PostgreSQL 18+)。

动手验证 · lab 30-observability
select lab.prove(
  'every report read the whole events table: about 2 million rows read per report',
  (select seq_tup_read::numeric from pg_stat_user_tables where relname = 'events')
  / (select calls from w where name = 'report') between 1900000 and 2200000);

select lab.prove(
  'events counts more sequential scans than report runs, because each parallel worker''s share counts',
  (select seq_scan from pg_stat_user_tables where relname = 'events')
    >= 1.5 * (select calls from w where name = 'report'));

select lab.prove(
  'events_pkey shows idx_scan = 0 after hundreds of inserts: uniqueness checks do not count as scans',
  (select idx_scan from pg_stat_user_indexes where indexrelname = 'events_pkey') = 0
  and (select n_tup_ins from pg_stat_user_tables where relname = 'events') > 100);

select lab.prove(
  'a database cloned from a template starts with empty statistics: n_live_tup is 0 for 100,000 users',
  (select n_live_tup from pg_stat_user_tables where relname = 'users') = 0
  and (select reltuples from pg_class where relname = 'users') = 100000);

完整实验脚本

缓存命中率是趋势,不是目标

缓冲区缓存命中率,也就是页请求在共享缓冲区中命中的比例,是 Postgres 最常被引用的健康指标。我们的命中率是 40.64%,放在通常的“保持在 99% 以上”规则旁边看很吓人。仔细看就会发现,这个规则站不住脚:

  • “读取”不等于磁盘读取。 Postgres 把由操作系统页缓存提供的页面也计为一次读取,耗时可能只有微秒:users 查询的命中率是 67.7%,平均只花 0.03 ms。
  • 一个查询就能占据主导。 几乎所有这些读取都来自那份报表;它的扫描使用一小块缓冲区环,所以每次运行都会从操作系统读取大部分页面。
  • 平均值会藏住尾部。 整体命中率可以达到 99.9%,同时某条查询每次运行仍要从磁盘读取 50,000 个页。

所以要把这个比例画成图,观察突然下降的时刻;然后在 pg_stat_statements 中按 shared_blks_read 排名,找出发生了什么变化。

深入阅读:为什么报表很少命中缓存

对于大于 shared_buffers 四分之一的表,顺序扫描会使用 256 KB 的缓冲区环,而不是整个缓存,这样一次大扫描就不会把其他内容全部挤出去。代价由扫描本身承担:它读到的每个页面几乎刚读完就会从这个环中被挤出,因此下一次运行还会把它们全部重新读取。它实际命中的页面,是其他查询已经缓存的页面。那份报表每次运行都能在共享缓冲区中找到大约三分之一的页面;重复运行不会提高这个比例,索引(或比表更大的缓存)则能提高这个比例。

动手验证 · lab 30-observability
select lab.prove(
  'the events table is larger than a quarter of shared_buffers, so its scans use a bulkread ring',
  pg_relation_size('events') > pg_size_bytes(current_setting('shared_buffers')) / 4);

select lab.prove(
  'the report finds under 60% of its pages in shared buffers, however often it runs',
  (select 100.0 * shared_blks_hit / (shared_blks_hit + shared_blks_read)
   from w where name = 'report') < 60);

完整实验脚本

pg_stat_io 发现后端进程写脏页的情况(PostgreSQL 16+)

pg_stat_io 会按执行者、对象和上下文拆分所有 I/O(上下文包括 normal,以及 bulkread、bulkwrite 和 vacuum 缓冲区环)。它最值得问的问题是:客户端后端进程是否在自己写脏页? 理想情况下,几乎所有这类工作都应由检查点进程和后台写入器完成(你的查询不该负责写脏页)。

在我们的实验服务器上,一上午加载数据之后,客户端后端进程写了 151,031 个页面,比后台写入器的 60,192 个还多。默认的 128 MB shared_buffers 对这份写入负载来说太小了,更激进的后台写入器(bgwriter_lru_maxpages)是另一个可以调节的地方。批量加载期间出现一部分这种情况是预期的;稳定运行时不应该如此。

深入阅读:客户端后端进程对关系执行的 fsync 次数应为零

这些 151,031 次写入发生在 normal 上下文中;检查点进程写入了 119,725 次。客户端后端进程对关系执行的 fsyncs 次数应该是零(这里就是 0);非零表示检查点进程的请求队列溢出了。读取量最大的,是在 bulkread 上运行的并行工作进程,它们正在执行报表扫描。PostgreSQL 18 中,这个视图还会报告字节数,并覆盖 WAL:这里客户端后端进程完成了大部分 WAL 写入和 7,711 次 fsync,也就是提交路径上的工作。

动手验证 · lab 30-observability
select lab.prove(
  'pg_stat_io (PostgreSQL 18) reports bytes: read_bytes, write_bytes, extend_bytes',
  (select count(*) from information_schema.columns
   where table_name = 'pg_stat_io'
     and column_name in ('read_bytes', 'write_bytes', 'extend_bytes')) = 3);

select lab.prove(
  'pg_stat_io covers WAL as an object in PostgreSQL 18',
  exists (select 1 from pg_stat_io where object = 'wal'));

完整实验脚本

检查点应该由时间触发

几乎所有检查点都应该按时间触发,而不是由 WAL 量请求触发。我们的实验服务器在 pg_stat_checkpointer(PostgreSQL 17+)中显示了 1 次按时间触发和 28 次请求触发:WAL 生成太快,默认 1 GB 的 max_wal_size 不足以应付(检查点为恢复设定上限解释了这些计数和修复办法)。在 PostgreSQL 18 中,还要读取实际完成的检查点数量 num_done:即使服务器空闲,num_timed 也会统计那些被跳过的检查点,这可能让安静的服务器看起来比实际更健康。在图中把 pg_stat_wal 的每秒 WAL 字节数和这些计数放在一起。

被遗弃的槽会填满磁盘

主库上的 pg_stat_replication 会显示每个备库的复制延迟(权威数据的副本)。每台服务器都应该检查一项,无论它是否有副本:没有消费者的复制槽会永远保留 WAL,最终填满磁盘。

select slot_name, slot_type, active, wal_status,
       pg_size_pretty(
         pg_wal_lsn_diff(pg_current_wal_lsn(), restart_lsn)) as retained
  from pg_replication_slots;

一个不活跃且 retained 不断增长的槽,说明事故正在发生。两个设置可以给它设上限:max_slot_wal_keep_size 限制槽最多保留多少 WAL,idle_replication_slot_timeout(PostgreSQL 18+)会让闲置太久的槽失效。两者默认都关闭;失效的槽意味着必须重建其消费者,但这总比磁盘写满好。

低开销估算膨胀,低峰时精确测量

膨胀是死行版本或空页面占用的空间。n_dead_tup 是一种低开销估算,足够用来画图。pgstattuple_approx 会跳过全可见页面;删除四分之一的 events 后,它报告了 24% 的死元组。精确的 pgstattuple() 和 pgstatindex 会读取整个关系,所以应在业务低峰运行(清理不可省说明了接下来该做什么)。

深入阅读:运行 pgstattuple_approx 和 pgstatindex
scanned_percent      | 100
dead_tuple_count     | 510178
dead_tuple_percent   | 24.108421492938447

scanned_percent 为 100,是因为尚未执行清理,所以没有页面被标记为全可见。pgstatindex('events_pkey') 报告的 avg_leaf_density 是 90.03:以递增键建立的新 B-树大约为 90%,也就是它的 fillfactor。如果本应紧凑的索引远低于这个值,就可以考虑执行 REINDEX CONCURRENTLY。

动手验证 · lab 30-observability
delete from events where id % 4 = 0;

select lab.prove(
  'after deleting a quarter of events, pgstattuple_approx reports 20 to 30% dead tuples',
  (select dead_tuple_percent between 20 and 30 from pgstattuple_approx('events')));

select lab.prove(
  'with nothing vacuumed since, no page is all-visible, so it scans 100% of the table',
  (select scanned_percent > 99 from pgstattuple_approx('events')));

完整实验脚本

只对需要尽快人工处理的事情告警

只对需要尽快人工处理、并且会自行恶化的事情告警。其他一切都画成图。

告警:

  1. 数据库不可达,或连接失败。
  2. 事务 ID 年龄:当 age(datfrozenxid) 达到 5 亿到 10 亿时就告警,远低于 20 亿的上限。接近上限时,Postgres 会有意停止分配事务 ID;在清理追上来之前,写入都会停止(回卷会在任何内容损坏前停止写入)。
  3. 长事务:超过应用设定的阈值,或处于 idle in transaction 超过几分钟。
  4. 复制:复制延迟超过应用能够容忍的范围、备库消失,或不活跃的复制槽正在保留 WAL。
  5. 磁盘空间:数据和 WAL 都要监控,并留出提前量(空间使用率达到 80% 且还在上升时告警)。
  6. WAL 归档失败(failed_count,位于 pg_stat_archiver 中):你的时间点恢复出现了缺口。

**画图:**按排名靠前的语句显示每秒查询时间;按状态和 application_name 显示连接;按等待事件显示会话;显示读取和命中的块;按类型显示检查点,并显示每秒 WAL 字节数;显示最大表的死元组、临时文件字节数、复制延迟,以及主机的 CPU、内存、IOPS 和磁盘延迟。

保留历史,并把它放在数据库之外

本章每个视图显示的都是“此刻”或“上次重置以来”,这两者都回答不了“昨天 14:05 发生了什么变化?”。每隔 15 到 60 秒把它们抓取到时间序列系统,保留数周历史。发生事故时,问题几乎总是要和上周比较。

本章要点

  • 到处安装 pg_stat_statements,并先按 total_exec_time 排名:调用最频繁的查询很少是代价最高的。
  • 按每次调用的块数排名,找出触碰页面过多的查询;这是最好的前后对比指标。做快照并求差值,不要重置。
  • 在 pg_stat_activity 中寻找 idle in transaction 会话和旧的 backend_xmin 值。
  • 想知道会话在等待什么,就用 pg_stat_activity 配合 \watch 每秒采样十次,持续一分钟,再按等待事件计数。没有等待事件的活动会话正在占用 CPU;把它和核心数比较。
  • 大表上数值很大且不断增加的 seq_tup_read 指向缺失的索引;idx_scan = 0 指向未使用的索引,除非它支撑某个约束。
  • 把缓存命中率当作趋势,而不是目标。检查点应当大多按时间触发。
  • 只对一份短清单告警:不可达、事务 ID 年龄、长事务、复制、磁盘空间和归档。其他一切画图,并保留历史。

延伸阅读

  • pg_stat_statements,PostgreSQL 文档。介绍每一列、各项设置以及语句如何归一化。
  • The cumulative statistics system,PostgreSQL 文档。pg_stat_activity、表和索引视图、pg_stat_io、pg_stat_checkpointer 以及所有等待事件的参考资料。
  • pg_wait_sampling,Postgres Professional。一个在服务器内部采样等待事件,并按事件和查询保留画像的扩展。
  • Viewing locks 和 progress reporting,PostgreSQL 文档。介绍 pg_locks 以及清理、索引构建等操作的 pg_stat_progress_* 视图。
  • The USE Method,Brendan Gregg。用于检查利用率、饱和度和错误的清单,让主机指标保持可信。