时间戳

首页 > 解决方案 > 调试由 pgbench 执行的查询

postgresql - 调试由 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更大的表，因为它认为大多数结果将与查询无关，而使用Bitmap Heap Scan它是因为它认为结果集将是足够小，以便更容易扫描“所有内容”，然后过滤掉不必要的结果（其中不会太多）。然而，由于巨大的延迟影响，堆扫描被证明是错误的策略。

更新 3

我之前的解释是错误的。或者，至少，不是完整的答案。添加 I/O 时间报告和锁定时间报告后，似乎 PostgreSQL 等待获取锁的时间是造成延迟的原因。现在，更大的问题是为什么大表上的争用要高得多，或者是否有其他机制在起作用使这些锁非常慢（有时 > 3 秒）。

标签： postgresqlbenchmarkingquery-performance

解决方案

除非你在数据库上运行除了 pgbench 之外的其他东西，否则没有什么会锁定你两秒钟。

此外，位图堆扫描没有错（它很快），它是更新本身。

最可能的原因是 I/O 过载 - 检查 CPU 花费的 I/O 等待时间。

另一种（不太可能）的可能性，可能与前一种结合起来，是 tiny shared_buffers，因此后端无法找到干净的缓冲区。

推荐阅读