调试由pgbench执行的查询

Question

我看到了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秒)。

Answer 1

除非您在数据库上运行的是pgbench之外的其他东西，否则任何东西都不会锁定您2秒。

此外，位图堆扫描没有出错(速度很快)，而是更新本身。

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

另一种(不太可能的)可能性，也许与前一种可能相结合，是一个很小的shared_buffers，因此后端找不到干净的缓冲区。