# 观察数据库运行 > 使用 pg_stat_statements、pg_stat_activity 和累计统计信息视图，找出什么慢、什么卡住，以及哪些情况值得告警。 --- LLMS 索引： [llms.txt](/llms.txt) --- 在一分钟内，我们的测试服务器用 `pgbench` 运行了一组混合负载：按主键查找 `users` 中的行、向 `events` 插入、项目列表和一份小报表。下面列出调用次数最多和最少的查询： ```text 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 开始 {#start-with-pg_stat_statements} `pg_stat_statements` 是 Postgres 最有用的可观测性工具。它按归一化后的结构对语句分组，并为每种结构保留累计总量：调用次数、时间、行数、缓冲区、WAL 和临时文件。它随 Postgres 一起提供，所有主要托管服务也都支持它。 ### pg_stat_statements 在服务器启动时加载 {#pg_stat_statements-loads-at-server-start} 它必须预加载，所以打开它需要重启： ```ini 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`。 > [!DETAILS]- 深入阅读：语句如何分组，以及 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)` 仍是更好的习惯：在所有版本中都只有一种语句结构（[经得住数据增长的查询](/22-queries/#basics-chapter-22)）。 > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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'); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) ### 用四种方式给同一视图排序，先看总时间 {#rank-the-same-view-four-ways-total-time-first} 每次排查都从同一个视图开始，按四种方式排序。**时间都花在哪里？** 按 `total_exec_time` 排序。这是任何服务器上第一条该运行的查询： ```sql 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; ``` ```text 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` 后的结果排序。耗时有噪声，页面数没有。整本书的论点可以写成这样一个查询： ```text 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-树挑起大梁](/17-btree/#basics-chapter-17)可以解决这一点）。主键查询只触碰 3 个页面。项目列表为 20 行触碰 257 个页面，原因是外键没有索引。每次调用的块数是应该压下去的数字，而且不同运行之间几乎不变，所以可以作为前后对比指标（[只改一件事，并端到端测量](/29-benchmarking/#change-one-thing-and-measure-it-end-to-end)）。 **什么写入最多？** 按 `wal_bytes` 排序。插入在一分钟内写入了 75 MB 的 WAL，平均每行约 7.5 KB，几乎全是[整页镜像](/43-glossary/#full-page-write)（[先记日志，再写数据](/08-wal/#basics-chapter-8)）。WAL 量会影响副本延迟、备份大小和磁盘吞吐量。 > [!DETAILS]- 深入阅读：其他排序查询，以及每次插入的五条 WAL 记录 > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) > > 其他排名只是替换 `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` 后才会填充；该选项默认关闭，因为有开销。 > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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']); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) ### 做快照并求差值；不要重置 {#snapshot-and-diff-dont-reset} 几周之后，累计历史会占据主导地位，昨天才变慢的查询会藏在它漫长而快速的过去里。不要按计划重置。**做快照并求差值**：每隔几分钟复制一次视图并计算增量，这样就能问“昨天 14:00 到 14:15 之间，排名靠前的查询是什么”。大多数监控代理会替你做这件事。 在一次[基准测试](/29-benchmarking/#change-one-thing-and-measure-it-end-to-end)之前，有针对性地调用 `pg_stat_statements_reset(userid, dbid, queryid)` 是可以的。同时观察 `dealloc`（它位于 `pg_stat_statements_info` 中）：它不断升高，意味着语句超过 `pg_stat_statements.max` 后正在被淘汰。 ## pg_stat_activity 显示此刻发生的事 {#pg_stat_activity-shows-this-instant} `pg_stat_statements` 记录的是过去，`pg_stat_activity` 记录的是此刻：每个服务器进程一行，包括它正在运行什么、从什么时候开始运行，以及在等待什么。它的 `state` 可以是 `active`、`idle`（等待客户端的下一条语句，这是正常状态），或者 `idle in transaction`：位于一个打开的事务中，持有自己的锁，并可能持有[快照](/43-glossary/#snapshot)，而应用正在做别的事。几毫秒属于正常情况；几分钟就是缺陷。 ### 没有等待事件的活动会话正在占用 CPU {#an-active-session-with-no-wait-event-is-on-a-cpu} `wait_event_type` 和 `wait_event` 表示后端进程正在等待什么；这两列均为空的 `active` 行表示该会话正在 CPU 上运行。**Lock** 是重量级锁（可以锁表，也可以是另一个事务持有行锁时的 `transactionid`）；**LWLock** 表示内部结构上的争用（[解决 LWLock 等待要调整负载，而不是查询](/25-concurrency/#lwlock-waits-are-fixed-in-the-workload-not-the-query)）；**IO** 表示读取页面或刷新 WAL；**Client** 表示等待应用。`pg_wait_events`（PostgreSQL 17+）记录了每一种等待事件。每秒统计十次，你就得到了一个[画像](#sample-waits-to-see-where-the-time-goes)。 > [!DETAILS]- 深入阅读：这些示例背后的会话 > > 本节的示例来自账户 7 上的三个会话。会话 a 在事务中更新了该账户，然后运行 `pg_sleep(60)`。会话 b 打开一个事务，读取了一些用户，然后没有提交就进入空闲。会话 c 尝试更新同一个账户，于是被阻塞。睡眠中的会话状态是 `active`，而不是 idle：它正在运行一条语句，等待事件是 `Timeout:PgSleep`；应用步骤在数据库内运行时，慢就会呈现为这种样子。会话 a 还有一个 `backend_xid`，因为它执行过写入；会话 b 没有，因为事务要到第一次写入时才会取得 XID。 > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > -- 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)); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) ### backend_xmin 指出阻挡清理的事务 {#backend_xmin-names-the-transaction-holding-vacuum-back} 长事务会阻塞清理、持有锁，并让迁移超时。按年龄列出所有打开的事务： ```sql 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; ``` ```text 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` 结束它（[大家都得排队](/25-concurrency/#basics-chapter-25)）。 > [!WARNING] 关注最老的 xmin，而不只是最老的查询 > > 真正会悄悄伤害数据库的是旧快照，而不是慢查询。清理无法移除整个数据库中最老快照可能需要的任何行版本。检查 `max(age(backend_xmin))`（在 `pg_stat_activity` 中），以及复制槽的 `xmin` 和使用 `hot_standby_feedback` 的备库的相应值；它们都会阻碍同一个 xmin 清理界限（xmin horizon）推进（[清理无法移除旧快照可能需要的内容](/10-vacuum/#vacuum-cant-remove-what-an-old-snapshot-might-need)）。 > [!DETAILS]- 深入阅读：谁持有 xmin，实证检查 > > 隔离级别决定空闲事务是否会阻止清理界限推进。会话 b 处于读已提交的空闲状态，既没有 XID，也没有 xmin：它在语句之间不持有快照，所以完全不会阻塞清理，尽管它仍然持有锁。第四个会话 d 执行了 `begin isolation level repeatable read`，运行一次 `select` 后进入空闲；只要事务保持打开，它的 `backend_xmin` 就会一直存在，因为之后的每条语句都必须看到同一个快照。因此，一个忘记提交的可重复读报表任务，比一个做同样事情的应用事务更糟。要找出阻碍清理界限推进的会话： > > ```sql > 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; > ``` > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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)); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) ## 采样等待，看看时间花在哪里 {#sample-waits-to-see-where-the-time-goes} 看一眼 `pg_stat_activity` 就像拍了一张照片。每秒取十次样，持续一分钟，统计你看到的内容，你就得到了一个画像：会话的忙碌时间有多少花在 CPU、读取页面、等待锁或刷新 WAL 上。它不需要扩展，却能回答 `pg_stat_statements` 回答不了的问题：不是哪个查询，而是查询在等待什么。 ### 每次采样都必须使用独立事务 {#each-sample-must-be-its-own-transaction} 创建一张表，然后从 psql 反复执行同一条插入语句： ```sql 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 次。 > [!DETAILS]- 深入阅读：SQL 中的采样循环必须清除快照 > > 每次采样前调用 `pg_stat_clear_snapshot()`，并用 `clock_timestamp()` 给行加时间戳，因为 `now()` 和 `statement_timestamp()` 也会被冻结。（运行一分钟的 `DO` 块同样是一个运行一分钟的事务，这本身就是另一个小问题。） > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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; > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) ### CPU 行高于核心数，说明正在排队 {#a-cpu-line-above-your-core-count-means-queuing} 按等待事件统计采样。没有等待事件的活动会话正在占用 CPU，所以把它标成 CPU： ```sql 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 轮： ```text 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` 的语句，慢是因为其他人的活动，修复点在它等待的对象上。 > [!DETAILS]- 深入阅读：实证检查玩具画像，并把等待连接到语句 > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > -- 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')); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) > > ```sql > 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`。 > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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')); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) ### 大多数画像中，只有少数几种事件占主导 {#a-handful-of-events-lead-most-profiles} 每一种都指向不同的修复方法： - **CPU**：查询正在做自己的工作。按总时间和每次调用的块数排序。 - **`IO:DataFileRead`**：正在读取不在共享缓冲区中的页面。按 `shared_blks_read` 排序，先修查询，再考虑买更多内存。 - **`LWLock:WALWrite`** 和 **`IO:WalSync`**：提交正在等待 WAL 到达磁盘。使用更少但更大的事务，或者更快的 WAL 存储（[多个提交共享一次刷盘](/08-wal/#many-commits-share-one-flush)）。 - **`Lock:transactionid`**：会话正在等待另一个事务持有的行。找到阻塞链的根（[找到根阻塞者](/25-concurrency/#find-the-root-blocker)）。`Lock:relation` 通常表示锁队列中的 DDL。 采样不是计时器，但持续一分钟后，每种事件都会按其总时间的比例出现，这正是你需要用来排序的依据。要和上周比较，就持续采样：[`pg_wait_sampling`](https://github.com/postgrespro/pg_wait_sampling) 扩展在服务器内部完成这件事；托管服务商的“数据库负载”图表也是同一种画像（[服务商仪表盘是等待事件采样器](/34-managed/#provider-dashboards-are-wait-event-samplers)）。学会读取自己的 SQL 版本，就能读取它们中的任何一个。 ## 表统计计数器能找出缺失和未使用的索引 {#table-counters-find-missing-indexes-and-unused-ones} 在 `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 为零只是疑点，不能据此定案](/17-btree/#an-idx_scan-of-zero-is-a-suspect-not-a-verdict)）。 > [!NOTE] 这些计数器归零的次数比你想象得多 > > 累计统计信息会因 `pg_stat_reset()` 重置，会在崩溃时消失，也不会在从模板创建数据库时复制过去：在我们刚克隆的数据库中，100,000 个用户的 `n_live_tup` 读数是 0。判断索引未使用之前，先检查 `stats_reset`（位于 `pg_stat_database` 中）。 > [!DETAILS]- 深入阅读：更多表计数器，以及实证检查 > > `pg_stat_user_tables` 中还有 `n_dead_tup` 和 `last_autovacuum`（[清理不可省](/10-vacuum/#basics-chapter-10)）、HOT 占比 `n_tup_hot_upd / n_tup_upd`（[让更新保持 HOT](/07-hot/#basics-chapter-7)）、`last_seq_scan`（PostgreSQL 16+），以及 `total_autovacuum_time`（PostgreSQL 18+）。 > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) ## 缓存命中率是趋势，不是目标 {#the-cache-hit-ratio-is-a-trend-not-a-target} 缓冲区缓存命中率，也就是页请求在共享缓冲区中命中的比例，是 Postgres 最常被引用的健康指标。我们的命中率是 40.64%，放在通常的“保持在 99% 以上”规则旁边看很吓人。仔细看就会发现，这个规则站不住脚： - **“读取”不等于磁盘读取。** Postgres 把由[操作系统页缓存](/43-glossary/#os-page-cache)提供的页面也计为一次读取，耗时可能只有微秒：`users` 查询的命中率是 67.7%，平均只花 0.03 ms。 - **一个查询就能占据主导。** 几乎所有这些读取都来自那份报表；它的扫描使用一小块[缓冲区环](/05-buffers/#big-operations-get-a-ring)，所以每次运行都会从操作系统读取大部分页面。 - **平均值会藏住尾部。** 整体命中率可以达到 99.9%，同时某条查询每次运行仍要从磁盘读取 50,000 个页。 所以要把这个比例画成图，观察突然下降的时刻；然后在 `pg_stat_statements` 中按 `shared_blks_read` 排名，找出发生了什么变化。 > [!DETAILS]- 深入阅读：为什么报表很少命中缓存 > > 对于大于 `shared_buffers` 四分之一的表，顺序扫描会使用 256 KB 的缓冲区环，而不是整个缓存，这样一次大扫描就不会把其他内容全部挤出去。代价由扫描本身承担：它读到的每个页面几乎刚读完就会从这个环中被挤出，因此下一次运行还会把它们全部重新读取。它实际命中的页面，是其他查询已经缓存的页面。那份报表每次运行都能在共享缓冲区中找到大约三分之一的页面；重复运行不会提高这个比例，索引（或比表更大的缓存）则能提高这个比例。 > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) ## pg_stat_io 发现后端进程写脏页的情况（PostgreSQL 16+） {#pg_stat_io-catches-backends-writing-dirty-pages-postgresql-16} `pg_stat_io` 会按执行者、对象和上下文拆分所有 I/O（上下文包括 `normal`，以及 `bulkread`、`bulkwrite` 和 `vacuum` 缓冲区环）。它最值得问的问题是：**客户端后端进程是否在自己写脏页？** 理想情况下，几乎所有这类工作都应由检查点进程和后台写入器完成（[你的查询不该负责写脏页](/05-buffers/#your-query-shouldnt-be-the-one-writing-dirty-pages)）。 在我们的实验服务器上，一上午加载数据之后，客户端后端进程写了 151,031 个页面，比后台写入器的 60,192 个还多。默认的 128 MB `shared_buffers` 对这份写入负载来说太小了，更激进的后台写入器（`bgwriter_lru_maxpages`）是另一个可以调节的地方。批量加载期间出现一部分这种情况是预期的；稳定运行时不应该如此。 > [!DETAILS]- 深入阅读：客户端后端进程对关系执行的 fsync 次数应为零 > > 这些 151,031 次写入发生在 `normal` 上下文中；检查点进程写入了 119,725 次。客户端后端进程对关系执行的 `fsyncs` 次数应该是零（这里就是 0）；非零表示检查点进程的请求队列溢出了。读取量最大的，是在 `bulkread` 上运行的并行工作进程，它们正在执行报表扫描。PostgreSQL 18 中，这个视图还会报告字节数，并覆盖 WAL：这里客户端后端进程完成了大部分 WAL 写入和 7,711 次 fsync，也就是提交路径上的工作。 > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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')); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) ## 检查点应该由时间触发 {#checkpoints-should-be-timed} 几乎所有检查点都应该按时间触发，而不是由 WAL 量请求触发。我们的实验服务器在 `pg_stat_checkpointer`（PostgreSQL 17+）中显示了 1 次按时间触发和 28 次请求触发：WAL 生成太快，默认 1 GB 的 `max_wal_size` 不足以应付（[检查点为恢复设定上限](/08-wal/#checkpoints-put-a-limit-on-recovery)解释了这些计数和修复办法）。在 PostgreSQL 18 中，还要读取实际完成的检查点数量 `num_done`：即使服务器空闲，`num_timed` 也会统计那些被跳过的检查点，这可能让安静的服务器看起来比实际更健康。在图中把 `pg_stat_wal` 的每秒 WAL 字节数和这些计数放在一起。 ## 被遗弃的槽会填满磁盘 {#an-abandoned-slot-will-fill-the-disk} 主库上的 `pg_stat_replication` 会显示每个备库的复制延迟（[权威数据的副本](/38-replication/#basics-chapter-38)）。每台服务器都应该检查一项，无论它是否有副本：没有消费者的[复制槽](/43-glossary/#replication-slot)会永远保留 WAL，最终填满磁盘。 ```sql 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+）会让闲置太久的槽失效。两者默认都关闭；失效的槽意味着必须重建其消费者，但这总比磁盘写满好。 ## 低开销估算膨胀，低峰时精确测量 {#estimate-bloat-cheaply-measure-it-off-peak} 膨胀是死行版本或空页面占用的空间。`n_dead_tup` 是一种低开销估算，足够用来画图。`pgstattuple_approx` 会跳过全可见页面；删除四分之一的 `events` 后，它报告了 24% 的死元组。精确的 `pgstattuple()` 和 `pgstatindex` 会读取整个关系，所以应在业务低峰运行（[清理不可省](/10-vacuum/#basics-chapter-10)说明了接下来该做什么）。 > [!DETAILS]- 深入阅读：运行 pgstattuple_approx 和 pgstatindex > > ```text > 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`。 > > > [!EXAMPLE]- 动手验证 · lab `30-observability` > > > > ```sql > > 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'))); > > ``` > > > > [完整实验脚本](https://www.flagon.io/books/eight-kilobytes/lab/30-observability.sql) ## 只对需要尽快人工处理的事情告警 {#alert-only-on-what-needs-a-human-soon} 只对需要尽快人工处理、并且会自行恶化的事情告警。其他一切都画成图。 **告警：** 1. **数据库不可达**，或连接失败。 2. **事务 ID 年龄**：当 `age(datfrozenxid)` 达到 5 亿到 10 亿时就告警，远低于 20 亿的上限。接近上限时，Postgres 会有意停止分配事务 ID；在清理追上来之前，写入都会停止（[回卷会在任何内容损坏前停止写入](/10-vacuum/#wraparound-stops-writes-before-anything-is-corrupted)）。 3. **长事务**：超过应用设定的阈值，或处于 `idle in transaction` 超过几分钟。 4. **复制**：复制延迟超过应用能够容忍的范围、备库消失，或不活跃的复制槽正在保留 WAL。 5. **磁盘空间**：数据和 WAL 都要监控，并留出提前量（空间使用率达到 80% 且还在上升时告警）。 6. **WAL 归档失败**（`failed_count`，位于 `pg_stat_archiver` 中）：你的时间点恢复出现了缺口。 **画图：**按排名靠前的语句显示每秒查询时间；按状态和 `application_name` 显示连接；按等待事件显示会话；显示读取和命中的块；按类型显示检查点，并显示每秒 WAL 字节数；显示最大表的死元组、临时文件字节数、复制延迟，以及主机的 CPU、内存、IOPS 和磁盘延迟。 > [!TIP] 保留历史，并把它放在数据库之外 > > 本章每个视图显示的都是“此刻”或“上次重置以来”，这两者都回答不了“昨天 14:05 发生了什么变化？”。每隔 15 到 60 秒把它们抓取到时间序列系统，保留数周历史。发生事故时，问题几乎总是要和上周比较。 ## 本章要点 {#the-short-version} - 到处安装 `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 年龄、长事务、复制、磁盘空间和归档。其他一切画图，并保留历史。 ## 延伸阅读 {#further-reading} - [pg_stat_statements](https://www.postgresql.org/docs/18/pgstatstatements.html)，PostgreSQL 文档。介绍每一列、各项设置以及语句如何归一化。 - [The cumulative statistics system](https://www.postgresql.org/docs/18/monitoring-stats.html)，PostgreSQL 文档。`pg_stat_activity`、表和索引视图、`pg_stat_io`、`pg_stat_checkpointer` 以及所有等待事件的参考资料。 - [pg_wait_sampling](https://github.com/postgrespro/pg_wait_sampling)，Postgres Professional。一个在服务器内部采样等待事件，并按事件和查询保留画像的扩展。 - [Viewing locks](https://www.postgresql.org/docs/18/monitoring-locks.html) 和 [progress reporting](https://www.postgresql.org/docs/18/progress-reporting.html)，PostgreSQL 文档。介绍 `pg_locks` 以及清理、索引构建等操作的 `pg_stat_progress_*` 视图。 - [The USE Method](https://www.brendangregg.com/usemethod.html)，Brendan Gregg。用于检查利用率、饱和度和错误的清单，让主机指标保持可信。