在 pgbench 执行时调试查询
Debug queries as they are executed by pgbench
我从 pgbench 看到了一个奇怪的输出，我不知道还有哪些其他工具可以尝试理解延迟过大的原因。
以下是 explain 运行 对填充的 pgbench 数据库的结果：
pgbench=# explain analyze UPDATE pgbench_tellers SET tbalance = tbalance + 12345 WHERE tid = 100;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Update on pgbench_tellers (cost=0.00..2.25 rows=1 width=358) (actual time=0.077..0.077 rows=0 loops=1)
-> Seq Scan on pgbench_tellers (cost=0.00..2.25 rows=1 width=358) (actual time=0.023..0.025 rows=1 loops=1)
Filter: (tid = 100)
Rows Removed by Filter: 99
Total runtime: 0.092 ms
(5 rows)
pgbench=# explain analyze UPDATE pgbench_branches SET bbalance = bbalance + 12345 WHERE bid = 10;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------
Update on pgbench_branches (cost=0.00..1.13 rows=1 width=370) (actual time=0.045..0.045 rows=0 loops=1)
-> Seq Scan on pgbench_branches (cost=0.00..1.13 rows=1 width=370) (actual time=0.027..0.028 rows=1 loops=1)
Filter: (bid = 10)
Rows Removed by Filter: 9
Total runtime: 0.060 ms
(5 rows)
因此，根据规划器，两个查询应该在同一个范围内，第二个查询可能会稍微快一些，因为它必须扫描的行数较少。
现实是这样的：
tps = 695.349735 (including connections establishing)
tps = 695.355481 (excluding connections establishing)
statement latencies in milliseconds:
0.002471 \set nbranches 1 * :scale
0.000743 \set ntellers 10 * :scale
0.000684 \set naccounts 100000 * :scale
0.000786 \setrandom aid 1 :naccounts
0.000585 \setrandom bid 1 :nbranches
0.000609 \setrandom tid 1 :ntellers
0.000583 \setrandom delta -5000 5000
0.124286 BEGIN;
0.225984 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
0.167551 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
0.570490 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
3.230071 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
0.134970 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CU
RRENT_TIMESTAMP);
7.037875 END;
换句话说，被认为可以快 30% 完成的查询实际上慢了 5000%。
到目前为止，我的猜测是 PostgreSQL 规划器具有适用于低延迟存储的默认值，但是，这些测试是针对 iSCSI 设备执行的，可能具有更高的延迟（但也有高队列深度和高带宽）。
所以，我想知道是否有办法生成更详细的报告，说明 PostgreSQL 在测试期间执行的 I/O 操作（从它的角度来看，我可以看到 iSCSI 门户端）。并且，如果可能的话，一种配置规划器以调整其对“典型云”情况的估计的方法，在这种情况下，延迟很高，但队列深度和带宽也很高。
启用 auto_explain 以及其他一些日志配置更改后，以下是相关输出：
LOG: duration: 2667.835 ms plan:
Query Text: UPDATE pgbench_branches SET bbalance = bbalance + 3781 WHERE bid = 9;
Update on pgbench_branches (cost=4.26..8.27 rows=1 width=370) (actual time=2667.834..2667.834 rows=0 loops=1)
Buffers: shared hit=11
-> Bitmap Heap Scan on pgbench_branches (cost=4.26..8.27 rows=1 width=370) (actual time=0.010..0.010 rows=1 loops=1)
Recheck Cond: (bid = 9)
Buffers: shared hit=3
-> Bitmap Index Scan on pgbench_branches_pkey (cost=0.00..4.26 rows=1 width=0) (actual time=0.003..0.003 rows=1 loops=1)
Index Cond: (bid = 9)
Buffers: shared hit=2
LOG: duration: 9.604 ms plan:
Query Text: UPDATE pgbench_tellers SET tbalance = tbalance + 3845 WHERE tid = 33;
Update on pgbench_tellers (cost=0.00..8.28 rows=1 width=358) (actual time=9.604..9.604 rows=0 loops=1)
Buffers: shared hit=7
-> Index Scan using pgbench_tellers_pkey on pgbench_tellers (cost=0.00..8.28 rows=1 width=358) (actual time=0.009..0.010 rows=1 loops=1)
Index Cond: (tid = 33)
Buffers: shared hit=3
因此，区别似乎在于 Bitmap Heap Scan + Bitmap Index Scan 与 Index Scan。我仍然不确定为什么它不同以及它在 I/O.
方面意味着什么
更新 2
从更多关于扫描种类和使用它们的基本原理的阅读来看，PostgreSQL 似乎选择使用 Index Scan 以获得更大的 table，因为它相信大多数结果将与查询，而它使用 Bitmap Heap Scan 是因为它认为结果集足够小，可以更轻松地扫描“所有内容”，然后过滤掉不必要的结果（不会太多）。然而，由于巨大的延迟影响，堆扫描被证明是错误的策略。
更新 3
我之前的解读是错误的。或者，至少，不是完整的答案。添加 I/O 时间报告和锁定时间报告后，PostgreSQL 等待获取锁的时间似乎是造成延迟的原因。现在，更大的问题是为什么更大的 table 上的争用如此之多，或者是否有其他机制在起作用，使这些锁非常慢（有时 > 3 秒）。
除非你是 运行 除了数据库上的 pgbench 之外的其他东西，否则什么都不会锁定你两秒钟。
另外，位图堆扫描也没有错（速度很快），是更新本身。
最可能的原因是 I/O 过载 – 检查 CPU 花费的 I/O 等待时间。
另一种（不太可能）的可能性，可能与前一种可能性相结合，是一个很小的shared_buffers，以至于后端无法找到干净的缓冲区。
我从 pgbench 看到了一个奇怪的输出，我不知道还有哪些其他工具可以尝试理解延迟过大的原因。
以下是 explain 运行 对填充的 pgbench 数据库的结果：
pgbench=# explain analyze UPDATE pgbench_tellers SET tbalance = tbalance + 12345 WHERE tid = 100;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------
Update on pgbench_tellers (cost=0.00..2.25 rows=1 width=358) (actual time=0.077..0.077 rows=0 loops=1)
-> Seq Scan on pgbench_tellers (cost=0.00..2.25 rows=1 width=358) (actual time=0.023..0.025 rows=1 loops=1)
Filter: (tid = 100)
Rows Removed by Filter: 99
Total runtime: 0.092 ms
(5 rows)
pgbench=# explain analyze UPDATE pgbench_branches SET bbalance = bbalance + 12345 WHERE bid = 10;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------
Update on pgbench_branches (cost=0.00..1.13 rows=1 width=370) (actual time=0.045..0.045 rows=0 loops=1)
-> Seq Scan on pgbench_branches (cost=0.00..1.13 rows=1 width=370) (actual time=0.027..0.028 rows=1 loops=1)
Filter: (bid = 10)
Rows Removed by Filter: 9
Total runtime: 0.060 ms
(5 rows)
因此，根据规划器，两个查询应该在同一个范围内，第二个查询可能会稍微快一些，因为它必须扫描的行数较少。
现实是这样的：
tps = 695.349735 (including connections establishing)
tps = 695.355481 (excluding connections establishing)
statement latencies in milliseconds:
0.002471 \set nbranches 1 * :scale
0.000743 \set ntellers 10 * :scale
0.000684 \set naccounts 100000 * :scale
0.000786 \setrandom aid 1 :naccounts
0.000585 \setrandom bid 1 :nbranches
0.000609 \setrandom tid 1 :ntellers
0.000583 \setrandom delta -5000 5000
0.124286 BEGIN;
0.225984 UPDATE pgbench_accounts SET abalance = abalance + :delta WHERE aid = :aid;
0.167551 SELECT abalance FROM pgbench_accounts WHERE aid = :aid;
0.570490 UPDATE pgbench_tellers SET tbalance = tbalance + :delta WHERE tid = :tid;
3.230071 UPDATE pgbench_branches SET bbalance = bbalance + :delta WHERE bid = :bid;
0.134970 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) VALUES (:tid, :bid, :aid, :delta, CU
RRENT_TIMESTAMP);
7.037875 END;
换句话说，被认为可以快 30% 完成的查询实际上慢了 5000%。
到目前为止，我的猜测是 PostgreSQL 规划器具有适用于低延迟存储的默认值，但是，这些测试是针对 iSCSI 设备执行的，可能具有更高的延迟（但也有高队列深度和高带宽）。
所以，我想知道是否有办法生成更详细的报告，说明 PostgreSQL 在测试期间执行的 I/O 操作（从它的角度来看，我可以看到 iSCSI 门户端）。并且，如果可能的话，一种配置规划器以调整其对“典型云”情况的估计的方法，在这种情况下，延迟很高，但队列深度和带宽也很高。
启用 auto_explain 以及其他一些日志配置更改后，以下是相关输出：
LOG: duration: 2667.835 ms plan:
Query Text: UPDATE pgbench_branches SET bbalance = bbalance + 3781 WHERE bid = 9;
Update on pgbench_branches (cost=4.26..8.27 rows=1 width=370) (actual time=2667.834..2667.834 rows=0 loops=1)
Buffers: shared hit=11
-> Bitmap Heap Scan on pgbench_branches (cost=4.26..8.27 rows=1 width=370) (actual time=0.010..0.010 rows=1 loops=1)
Recheck Cond: (bid = 9)
Buffers: shared hit=3
-> Bitmap Index Scan on pgbench_branches_pkey (cost=0.00..4.26 rows=1 width=0) (actual time=0.003..0.003 rows=1 loops=1)
Index Cond: (bid = 9)
Buffers: shared hit=2
LOG: duration: 9.604 ms plan:
Query Text: UPDATE pgbench_tellers SET tbalance = tbalance + 3845 WHERE tid = 33;
Update on pgbench_tellers (cost=0.00..8.28 rows=1 width=358) (actual time=9.604..9.604 rows=0 loops=1)
Buffers: shared hit=7
-> Index Scan using pgbench_tellers_pkey on pgbench_tellers (cost=0.00..8.28 rows=1 width=358) (actual time=0.009..0.010 rows=1 loops=1)
Index Cond: (tid = 33)
Buffers: shared hit=3
因此，区别似乎在于 Bitmap Heap Scan + Bitmap Index Scan 与 Index Scan。我仍然不确定为什么它不同以及它在 I/O.
更新 2
从更多关于扫描种类和使用它们的基本原理的阅读来看，PostgreSQL 似乎选择使用 Index Scan 以获得更大的 table，因为它相信大多数结果将与查询，而它使用 Bitmap Heap Scan 是因为它认为结果集足够小，可以更轻松地扫描“所有内容”，然后过滤掉不必要的结果（不会太多）。然而，由于巨大的延迟影响，堆扫描被证明是错误的策略。
更新 3
我之前的解读是错误的。或者，至少，不是完整的答案。添加 I/O 时间报告和锁定时间报告后，PostgreSQL 等待获取锁的时间似乎是造成延迟的原因。现在，更大的问题是为什么更大的 table 上的争用如此之多，或者是否有其他机制在起作用，使这些锁非常慢（有时 > 3 秒）。
除非你是 运行 除了数据库上的 pgbench 之外的其他东西，否则什么都不会锁定你两秒钟。
另外，位图堆扫描也没有错（速度很快），是更新本身。
最可能的原因是 I/O 过载 – 检查 CPU 花费的 I/O 等待时间。
另一种（不太可能）的可能性，可能与前一种可能性相结合，是一个很小的shared_buffers，以至于后端无法找到干净的缓冲区。