7 性能剖析
使用 PostgreSQL 日志、pg_stat_statements、auto_explain 和性能剖析器找出高代价查询，并将测量结果与整体工作负载代价联系起来。
1. 什么是性能剖析
前几章讨论了查询如何工作、执行计划由哪些构件组成，以及哪些因素会影响规划器在不同计划之间的选择。这是最困难也最重要的部分。理解这些机制之后，逻辑和常识通常就足以发挥很大作用：你可以判断查询是否在高效执行，以及什么措施可能改善它。
但怎样才能找到真正值得优化的查询？
任何优化任务——不只是数据库优化——都从性能剖析（profiling）开始，即使我们不总是使用这个词。我们把有问题的任务拆分成更小的部分，并测量每个部分占总工作量的多少。知道每个部分执行了多少次也很有用。
某个组件在总代价中所占的份额越大，优化它的潜在收益就越大。在实践中，优化工作本身的代价也很重要：理论上很大的收益，可能需要付出高昂代价，或者伴随较大风险才能获得。
有时某个组件单独看运行得很快，但执行次数太多。例如，ORM 生成的查询就常有这种情况。此时，更有用的问题可能是：这个操作是否真的应该执行这么多次？改变应用架构通常并不容易，但它带来的收益可能远大于调优一次查询调用。
对数据库整体活动进行性能剖析，对于管理员也很有价值：管理员可能并不是在调查某一个投诉，而是在寻找系统资源消耗最大的部分。监控系统应当能展示这样的性能概况。
Andrey Zubkov 的 pg_profile 扩展就是完成这项工作的工具之一。它建立在 PostgreSQL 统计信息视图之上，并定期保存活动快照。比较不同快照，既可以发现性能问题，也可以发现问题出现时所处的条件。监控架构、工具和指标选择的完整讨论超出了本书范围。
Postgres Professional 还出版了 Alexey Lesovsky 的俄语书籍《Monitoring PostgreSQL》，对这一主题进行了深入讨论。不过，在调查一个具体问题时，性能剖析的范围应当限定为重现该问题所需的操作。
为了解决具体问题，性能剖析应当这样建立：测量结果只覆盖重现该问题所需的那些操作。
2. 测量什么
应该使用什么单位来表示一个组件的代价？对于终端用户来说，最有意义的度量是响应时间：从执行某个动作到得到结果，经过了多少秒。
在这个意义上，查看 I/O 的数量可能更方便，也就是读取和写入的页面数量。这个度量更加稳定：在数据和配置参数相同的情况下，它不依赖硬件特性或服务器当前负载。
研究符合现实的数据量也很重要。Postgres.ai 的 Database Lab Engine 等工具能够快速创建轻量级数据库克隆（thin clone），在不复制全部存储的情况下重现生产规模的行为时，这会很有帮助。
I/O 通常能较好地反映执行查询所需的工作量，因为大量时间都花在读取和处理数据页面上。不过，这个度量对终端用户来说意义不大。
3. 应用性能剖析
性能问题经常出在数据库中：一个糟糕的执行计划就可能让运行时间相差几个数量级。但情况并不总是如此。缓慢的客户端连接、序列化、应用服务器工作、客户端渲染、排队、远程服务调用以及网络传输，都可能占据用户响应时间的主要部分。因此，完整的性能剖析应当覆盖客户端、应用服务器、网络和数据库。
除非系统的每个组件都提供有用的遥测信息，否则很难获得这样的端到端性能剖析。至少要测量总响应时间，并将它与数据库工作所占用的时间进行比较。在认定数据库是瓶颈之前，还要检查明显的网络延迟以及 PostgreSQL 之外所花费的时间。
从现在开始，假定问题已经定位在数据库中。
4. PL/pgSQL 性能剖析
一个用户动作通常会执行多条 SQL 语句。要找到值得优化的语句，我们需要包含语句级细节的剖析结果。
服务器端应用还可能包含过程代码，而不只是 SQL。
对于 PL/pgSQL 代码，Jan Wieck 的 PL Profiler 可以剖析脚本和实时会话。它会生成 HTML 报告，还可以用火焰图表示调用关系。
Pavel Stěhule 的 plpgsql_check 是另一个有用的扩展。它可以对 PL/pgSQL 代码执行额外检查，发现一些性能问题，并提供性能剖析功能。
5. 查询性能剖析
PostgreSQL 提供两条获取已执行 SQL 剖析结果的主要内置途径：服务器日志记录，以及累积的语句统计信息，后者最常通过 pg_stat_statements 获得。
服务器日志
配置参数可以启用语句及其执行时长的日志记录。log_min_duration_statement 是常见的起点。
怎样才能在日志中准确识别属于某个用户动作的查询？在一个会话中修改 log_min_duration_statement 只会影响同一个会话；性能专家没有标准方式从另一个会话为任意后端修改该参数。可以过滤共同的日志消息流，只选择所需的消息。为此，可以在 log_line_prefix 中加入额外的标识信息，例如进程 ID、会话 ID、用户、数据库或应用名称。连接池会让情况更加复杂。在函数内部执行的嵌套 SQL 又是另一个问题。auto_explain 模块可以记录计划；如果设置了 auto_explain.log_nested_statements，还可以记录嵌套语句的计划。
繁忙服务器的日志可能变得非常庞大。pgBadger 等外部工具可以汇总和分析 PostgreSQL 日志数据。
在有助于把用户可见的工作与数据库活动关联起来时，应用代码也可以发出自己的关联标识符和诊断消息。
语句统计信息
第二种方法是使用 pg_stat_statements 扩展收集语句执行统计信息。这里的“统计信息”与第六章“统计信息”中的含义不同。规划器统计信息描述数据分布，帮助预测未来的执行。pg_stat_statements 记录的是实际发生的工作的聚合信息。收集的查询执行统计信息包括以页面数量表示的 I/O 信息。
由于不同查询的数量可能非常多，存储空间由 pg_stat_statements.max 限制。当表填满时，执行频率较低的语句条目的信息会被丢弃。
除了常量不同之外，如果查询具有相同的语法解析树，就会被视为同一个查询。需要记住，这些查询可能有不同的执行计划，执行时间也可能不同。
当 compute_query_id 设置为 auto 或 on 时，PostgreSQL 核心会计算查询标识符。这样，不同扩展获取的信息就可以使用统一标识符进行关联。
启用 pg_stat_statements 扩展，我们将使用它来建立性能剖析：
CREATE EXTENSION pg_stat_statements;
CREATE EXTENSION
ALTER SYSTEM SET shared_preload_libraries =
'pg_stat_statements';
ALTER SYSTEM
然后必须重启服务器。
postgres$ pg_ctl restart -l /home/postgres/logfile
postgres$ /usr/local/pgsql/bin/psql demo
在下面的示例中，我们还要收集嵌套语句：
SET pg_stat_statements.track = 'all';
SET
创建一个只包含待检查字段的紧凑视图：
CREATE VIEW statements_v AS
SELECT
queryid,
toplevel,
substring(regexp_replace(query,' +',' ','g') FOR 55)
AS query,
calls,
round(total_exec_time)/1000 AS time_sec,
shared_blks_hit + shared_blks_read +
shared_blks_written AS shared_blks
FROM pg_stat_statements
ORDER BY total_exec_time DESC;
CREATE VIEW
现在考虑一份报告：按飞机型号和票价舱等显示乘客数量。先定义一个函数，统计某一飞机和票价舱等对应的乘客数量：
CREATE FUNCTION qty(
airplane_code text, fare_conditions text
) RETURNS bigint
AS $$
SELECT count(*)
FROM timetable tt
JOIN boarding_passes bp ON bp.flight_id = tt.flight_id
JOIN seats s ON s.airplane_code = tt.airplane_code
AND s.seat_no = bp.seat_no
WHERE tt.airplane_code = qty.airplane_code
AND s.fare_conditions = qty.fare_conditions;
$$ STABLE LANGUAGE sql;
CREATE FUNCTION
然后以此为基础创建一个表函数：
CREATE FUNCTION report()
RETURNS TABLE(
model text,
economy bigint, comfort bigint, business bigint
)
AS $$
DECLARE
r record;
BEGIN
FOR r IN
SELECT a.airplane_code, a.model
FROM airplanes a
ORDER BY a.model
LOOP
report.model := r.model;
report.economy := qty(r.airplane_code, 'Economy');
report.comfort := qty(r.airplane_code, 'Comfort');
report.business := qty(r.airplane_code, 'Business');
RETURN NEXT;
END LOOP;
END;
$$ STABLE LANGUAGE plpgsql;
重置语句统计信息并执行报告：
SELECT pg_stat_statements_reset();
SELECT * FROM report();
model | economy | comfort | business
-------------------------+---------+---------+----------
Aerobus A320neo | 120803 | 0 | 24494
Aerobus A330-900neo | 337923 | 42242 | 43775
Aerobus A350-1000 | 736214 | 0 | 115244
Aerobus A350F | 0 | 0 | 0
Boeing 737 MAX 7 | 556344 | 0 | 61743
Boeing 767-300F | 0 | 0 | 0
Boeing 777-300ER | 2238243 | 329509 | 205873
Boeing 787-9 Dreamliner | 613540 | 68505 | 156712
Bombardier CRJ700 | 91626 | 21181 | 10604
Embraer E170 | 191837 | 0 | 16006
(10 rows)
现在检查性能剖析结果：
SELECT * FROM statements_v \gx
-[ RECORD 1 ]----------------------------------
queryid | -3009688052632882778
toplevel | t
query | SELECT * FROM report()
calls | 1
time_sec | 28.311
shared_blks | 9417875
-[ RECORD 2 ]----------------------------------
queryid | -3792749405278051211
toplevel | f
query | SELECT count(*) +
| FROM timetable tt +
| JOIN boarding_passe
calls | 30
time_sec | 28.292
shared_blks | 9416655
-[ RECORD 3 ]----------------------------------
queryid | 704897965492952962
toplevel | f
query | SELECT a.airplane_code, a.model +
| FROM airplanes a +
| ORDE
calls | 1
time_sec | 0
shared_blks | 4
-[ RECORD 4 ]----------------------------------
queryid | -3948231919979109674
toplevel | t
query | SELECT pg_stat_statements_reset()
calls | 1
time_sec | 0
shared_blks | 0
有三个条目值得关注：
顶层的 report() 调用；
qty 中的查询，执行了 30 次；
驱动 PL/pgSQL 循环的查询。
几乎所有执行时间和缓冲区工作都来自 qty 查询。这个重复工作是显而易见的目标：报告应当围绕一条面向集合的查询重新组织。
6. 单个查询的性能剖析
性能剖析确定值得优化的语句后，我们还需要查询内部的性能剖析结果。EXPLAIN ANALYZE 可以提供这样的结果。这个结果由计划节点组成。但计划是一棵树，而不是一个扁平列表；解读时间时，这一点很重要。
对于每个节点，actual time、rows 和 loops 会告诉我们执行过程中发生了什么。
EXPLAIN 的 buffers 选项显示 I/O 数量；如果启用了 track_io_timing，它还会显示 I/O 操作花费的时间。
对于计划诊断，基数估计至少和运行时间同样重要。比较估计的 rows 与 actual rows 时，要把 loops 考虑进去。计划树底部的较大误差可能向上传播，并扭曲连接方法、访问路径、聚合和内存决策。
应该从估计首次严重出错的最深节点开始，而不是责怪每个继承该误差的父节点。
良好的基数估计并不能保证计划良好——代价参数和代价模型仍然可能有误——但较大的基数错误是最先需要调查的问题之一。
有时查询运行时间太长，无法实际使用 EXPLAIN ANALYZE。这时只能满足于普通的 EXPLAIN，并在信息不完整的情况下尝试理解低效的原因。
现在把乘客报告重写成一条 SQL 查询并检查它：
EXPLAIN (analyze, costs off, timing off)
WITH rf AS MATERIALIZED (
SELECT f.flight_id, r.airplane_code
FROM flights f
JOIN routes r ON r.route_no = f.route_no
AND r.validity @> f.scheduled_departure
), t AS (
SELECT rf.airplane_code,
count(*) FILTER
(WHERE s.fare_conditions = 'Economy') AS economy,
count(*) FILTER
(WHERE s.fare_conditions = 'Comfort') AS comfort,
count(*) FILTER
(WHERE s.fare_conditions = 'Business') AS business
FROM rf
JOIN boarding_passes bp ON bp.flight_id = rf.flight_id
JOIN seats s ON s.airplane_code = rf.airplane_code
AND s.seat_no = bp.seat_no
GROUP BY rf.airplane_code
)
SELECT a.model,
coalesce(t.economy, 0) AS economy,
coalesce(t.comfort, 0) AS comfort,
coalesce(t.business, 0) AS business
FROM airplanes a
LEFT JOIN t ON a.airplane_code = t.airplane_code
ORDER BY a.model;
正如下一页清楚显示的，大型计划并不总是适合以文本形式处理。为了更清楚地查看计划，可以使用第三方工具；其中一个是 explain.tensor.ru。
注意，消除重复读取后，查询执行时间减少了多少，读取的页面数量也少了多少：
QUERY PLAN
------------------------------------------------------------
Sort (actual rows=10.00 loops=1)
Sort Key: ((ml.model ->> current_setting('bookings.la...
Sort Method: quicksort Memory: 25kB
Buffers: shared hit=13059 read=37154
CTE rf
-> Hash Join (actual rows=37671.00 loops=1)
Hash Cond: (f.route_no = r.route_no)
Join Filter: (r.validity @> f.scheduled_departure)
Rows Removed by Join Filter: 115016
Buffers: shared hit=397 read=5
-> Seq Scan on flights f (actual rows=37671.00 ...
Buffers: shared hit=368
-> Hash (actual rows=2030.00 loops=1)
Buckets: 2048 Batches: 1 Memory Usage: 145kB
Buffers: shared hit=29 read=5
-> Seq Scan on routes r (actual rows=2030.0...
Buffers: shared hit=29 read=5
...
Buffers: shared hit=13059 read=37153
-> Hash Join (actual rows=5982418.00 ...
Hash Cond: ((rf.airplane_code = s...
Buffers: shared hit=13059 read=37153
-> Hash Join (actual rows=5982418...
Hash Cond: (bp.flight_id = rf...
Buffers: shared hit=13057 rea...
-> Seq Scan on boarding_passe...
Buffers: shared hit=12660...
-> Hash (actual rows=37671.00...
Buckets: 65536 (originall...
Buffers: shared hit=397 r...
-> CTE Scan on rf (actual...
Storage: Memory Maxi...
Buffers: shared hit=3...
-> Hash (actual rows=1741.00 loop...
Buckets: 2048 Batches: 1 Me...
Buffers: shared hit=2 read=8
-> Seq Scan on seats s (actua...
Buffers: shared hit=2 read=8
Planning:
Buffers: shared hit=5 read=1
Planning Time: 0.287 ms
Execution Time: 1388.015 ms
(54 rows)
为了获得参照，统计相关主表的堆页数量：
SELECT sum(relpages)
FROM pg_class
WHERE relname IN ('flights', 'routes', 'boarding_passes',
'seats', 'airplanes');
sum
-------
50212
(1 row)
对于需要全部行的查询，这个数字可以作为粗略的上限估计：如果处理的页面明显更多，可能说明同一批数据被扫描了多次。
在这个例子中，计划已经接近最优。它仍然可以改进，但幅度远不会像之前那样大。
参考资源