网络和游标，可能在默默拖慢你的 Postgres 查询-51CTO.COM

介绍

在 PostgreSQL 中，很多时候用户会对运行日志中报告的查询/语句持续时间感到困惑。其他的 PostgreSQL 工具，如 pgBadger，会根据日志文件显示相同的数据，这进一步增加了混淆。了解与网络相关开销和游标带来的全部影响，不仅对于减少混淆很重要，而且对于获得最佳性能也很重要。

那为什么要专门讨论下网络开销和游标呢？因为，它们是查询执行之后或过程中的隐藏成本。一旦查询执行开始，并且有一些数据要提供给客户端，这些就是主要影响性能的因素。因此，我们可能需要记住的重要一点是，由于所有这些都发生在查询执行之外，所以无法通过 EXPLAIN (ANALYZE) 获得相应的信息。

网络的影响

在演示中，这里使用了基于 pgbench 表的查询。

select a.bid, b.cnt from pgbench_accounts a,
   (select bid,count(*) cnt from pgbench_accounts group by bid) b
where b.bid > a.bid;

此查询没有实际意义。选择的是一个随机查询，该查询在数据库中需要一些时间才能执行。

为了捕获 EXPLAIN ANALYZE 的输出，使用了 auto_explain。进行设置以捕获所有耗时超过 250 毫秒的语句。

ALTER SYSTEM SET auto_explain.log_min_duration = 250;

使用 EXPLAIN ANALYZE 捕获其他详细信息的其他一些设置，还包括：

ALTER SYSTEM SET auto_explain.log_analyze = on;
ALTER SYSTEM SET auto_explain.log_buffers = on;
ALTER SYSTEM SET auto_explain.log_timing = on;
ALTER SYSTEM SET auto_explain.log_verbose = on;
ALTER SYSTEM SET auto_explain.log_triggers = on;
ALTER SYSTEM SET auto_explain.log_wal = on;

为了说明差异，将从以下位置执行相同查询

数据库主机服务器
通过网络连接的应用程序主机服务器

返回大量行的查询

场景 1. 在数据库主机服务器上执行

以下是由 auto_explain 生成的 PostgreSQL 日志中的几行信息：

2024-08-02 03:27:56.347 UTC [25537] LOG:  duration: 1591.784 ms  plan:
        Query Text: select a.bid, b.cnt from pgbench_accounts a,
           (select bid,count(*) cnt from pgbench_accounts group by bid) b
        where b.bid > a.bid;
        Nested Loop  (cost=12322.13..63020.46 rows=833333 width=12) (actual time=119.739..1069.924 rows=1000000 loops=1)
          Output: a.bid, b.cnt
          Join Filter: (b.bid > a.bid)
          Rows Removed by Join Filter: 1500000
          ...

正如我们所看到的，查询的外部嵌套循环用时 1069.924 毫秒，返回了 100 万条记录，但查询的总持续时间报告为 1591.784 毫秒。这有什么区别吗？

直接的 EXPLAIN ANALYZE 表明，对于这个简单的查询，规划时间为亚毫秒级，其中的数据来自一个没有任何索引的单个表。所以规划时间不应该是原因。

场景 2. 从远程应用主机服务器执行

同样，PostgreSQL 日志中的信息看起来不太一样：

2024-08-02 04:08:58.955 UTC [25617] LOG:  duration: 6568.659 ms  plan:
        Query Text: select a.bid, b.cnt from pgbench_accounts a,
           (select bid,count(*) cnt from pgbench_accounts group by bid) b
        where b.bid > a.bid;
        Nested Loop  (cost=12322.13..63020.46 rows=833333 width=12) (actual time=140.644..1069.153 rows=1000000 loops=1)
          Output: a.bid, b.cnt
          Join Filter: (b.bid > a.bid)
          Rows Removed by Join Filter: 1500000
          ...

正如我们所看到的，语句持续时间跃升至 6568.659 毫秒！尽管查询的实际执行时间几乎相同，为 1069.153 毫秒。这是一个巨大的差异。这可能是什么原因造成的呢？

返回少量行的查询

上述查询可以稍作修改，以仅返回最大值。修改后的测试查询可能如下所示：

select max(a.bid), max(b.cnt) from pgbench_accounts a,
   (select bid,count(*) cnt from pgbench_accounts group by bid) b
where b.bid > a.bid ;

除了有一个额外的聚合节点外，查询计划或时间不会发生太大变化。即使在计划中有跟我们正在讨论的主题无关的变化，因为我们只考虑查询执行的外部节点，与 PostgreSQL 报告的持续时间之间的时间差。

场景 1. 在数据库主机服务器上执行

2024-08-03 06:58:14.364 UTC [28129] LOG:  duration: 1011.143 ms  plan:
        Query Text: select max(a.bid), max(b.cnt) from pgbench_accounts a,
           (select bid,count(*) cnt from pgbench_accounts group by bid) b
        where b.bid > a.bid ;
        Aggregate  (cost=67187.12..67187.13 rows=1 width=12) (actual time=1010.914..1011.109 rows=1 loops=1)
          Output: max(a.bid), max(b.cnt)
          Buffers: shared hit=12622 read=3786
          ->  Nested Loop  (cost=12322.13..63020.46 rows=833333 width=12) (actual time=135.635..908.315 rows=1000000 loops=1)
                Output: a.bid, b.cnt
                Join Filter: (b.bid > a.bid)
                Rows Removed by Join Filter: 1500000
                Buffers: shared hit=12622 read=3786

正如我们所看到的，查询的完成时间为 1011.109 毫秒，和报告的持续时间 1011.143 毫秒之间没有太大差异。到目前为止的观察表明，当返回大量行时，会消耗额外的时间。

场景 2. 从远程主机执行语句

2024-08-03 06:55:37.221 UTC [28111] LOG:  duration: 1193.387 ms  plan:
        Query Text: select max(a.bid), max(b.cnt) from pgbench_accounts a,
           (select bid,count(*) cnt from pgbench_accounts group by bid) b
        where b.bid > a.bid ;
        Aggregate  (cost=67187.12..67187.13 rows=1 width=12) (actual time=1193.139..1193.340 rows=1 loops=1)
          Output: max(a.bid), max(b.cnt)
          Buffers: shared hit=11598 read=4810
          ->  Nested Loop  (cost=12322.13..63020.46 rows=833333 width=12) (actual time=124.508..1067.409 rows=1000000 loops=1)
                Output: a.bid, b.cnt
                Join Filter: (b.bid > a.bid)
                Rows Removed by Join Filter: 1500000
                Buffers: shared hit=11598 read=4810

同样的，1193.340 毫秒和 1193.387 毫秒没有太大差异。总的来说，我可以从结果中安全地假设，如果数据传输量最小化，在不同主机上的应用服务器不会有太大差异；同时，如果涉及大量结果的传输，影响是巨大的。

分析等待事件

幸运的是，较新版本的 PostgreSQL 为我们提供了一种监控 “等待事件” 信息的绝佳方法，查询会话/连接的 pg_stat_activity 视图。

我们可以使用 pg_gather 代码片段中的脚本，通过收集多个样本来收集性能信息，包括等待事件。该脚本每隔 10 毫秒收集一次等待事件样本，因此 20 秒内将有 2000 个样本。除了查看性能分析报告，还可以使用后端查询分析收集到的信息。

以下是我们可以看到的有关 PID: 25617 的信息（向远程主机返回大量行的场景）。

select pid, wait_event,count(*) from pg_pid_wait where pid=25617 group by 1,2 order by 3 desc;
  pid  |  wait_event  | count 
-------+--------------+-------
 25617 | ClientWrite  |   286
 25617 |              |    75
 25617 | DataFileRead |     3
(3 rows)

根据 PostgreSQL 文档，会话在 “ClientWrite” 上花费了更多时间。

等待事件	描述
`ClientWrite`	正在等待将数据发送给客户端。

它是将数据发送到客户端所花费的时间。wait_event 为 NULL 表示 CPU 利用率。

游标的影响

通常，在查询执行后，结果数据需要由应用程序进行处理。游标用于保存查询结果，再对其进行处理。对查询性能的影响主要取决于游标所在的位置，是在 PostgreSQL 服务端还是在客户端。当从单独的应用服务器发出查询时，游标的位置预计会产生影响，因此这里只测试这种情况。

客户端游标

通常，大多数 PostgreSQL 客户端和应用程序都是这种情况。数据会完全检索到数据库客户端，然后进行逐条处理。

下面是一段简单的 python 代码（用于模拟应用程序连接），用于测试相同的操作。（仅复制了相关的行）

conn =  psycopg2.connect(connectionString)
   cur = conn.cursor()
   cur.itersize = 2000
   cur.execute("select a.bid, b.cnt from pgbench_accounts a, (select bid,count(*) cnt from pgbench_accounts group by bid) b where b.bid > a.bid")
   row = cur.fetchone()
   while row is not None:
     print(row)
     time.sleep(0.001)
     row = cur.fetchone()

   conn.close()

正如我们所看到的，这里指定了 itersize，因此一次只能获取这些记录进行处理，并且在每次循环中使用 fetchone() 时，单次循环会有 1 毫秒的延迟。

但这些都不会影响服务端查询性能，因为游标已经缓存在客户端上。报告的查询时间和持续时间，类似于从远程应用服务器主机查询大量行。正如预期的那样，网络的影响是显而易见的：

2024-08-03 17:39:17.119 UTC [29180] LOG:  duration: 5447.793 ms  plan:
        Query Text: select a.bid, b.cnt from pgbench_accounts a, (select bid,count(*) cnt from pgbench_accounts group by bid) b where b.bid > a.bid
        Nested Loop  (cost=12322.13..63020.46 rows=833333 width=12) (actual time=130.919..1240.727 rows=1000000 loops=1)
          Output: a.bid, b.cnt
          Join Filter: (b.bid > a.bid)
          Rows Removed by Join Filter: 1500000
          Buffers: shared hit=1647 read=14761
          ->  Seq Scan on public.pgbench_accounts a  (cost=0.00..13197.00 rows=500000 width=4) (actual time=0.086..183.503 rows=500000 loops=1)
                Output: a.aid, a.bid, a.abalance, a.filler
                Buffers: shared hit=864 read=7333

服务端游标

如果我们有一个位于服务端的命名游标，并修改语句cur = conn.cursor()以包含一个名称，比如：cur = conn.cursor('curname')，那么创建和使用游标的方式将完全改变。

来自 psycopg2（适用于 PostgreSQL 的 Python 连接器）文档：

Psycopg 将数据库服务端游标包装在命名游标中。使用 cursor() 方法指定名称参数来创建一个命名游标

令人惊讶的是，即使配置了 auto_explain，PostgreSQL 日志也没有提供有关查询的更多信息。也没有持续时间信息。只有单独一行信息：

2024-08-03 18:02:45.184 UTC [29249] LOG:  duration: 224.501 ms  statement: FETCH FORWARD 1 FROM "curname"

PostgreSQL 游标支持具有自定义大小规范的各种 FETCH 选项。有关更多详细信息，请参阅 FETCH 的文档。编程语言驱动程序/连接器会将此功能包装到相应的函数中。

PostgreSQL 的 python 驱动 – psychopg2 – 包装了自定义批处理行数以运行 FETCH 的功能，如下所示：

cur.fetchmany(size=20000)

这将生成一条 PostgreSQL 日志记录，如下所示：

2024-08-05 05:13:30.728 UTC [32374] LOG:  duration: 262.931 ms  statement: FETCH FORWARD 20000 FROM "curname"

正如我们预期的那样，fetch 行数增加了。

但这里需要注意的重要一点是：尽管应用程序在遍历服务端游标上花费了大量时间（运行到几分钟），但 PostgreSQL 日志中有关查询或会话的信息几乎没有。

这可能会是人们所期望的最奇怪的事情。

等待事件分析

同样，我们也可以进行等待事件分析，以了解发生了什么。在 pg_gather 脚本收集的 2000 个等待事件样本中，等待事件如下所示：

pid  |  wait_event  | count
-------+--------------+-------
 30115 | ClientRead   |  1754
 30115 |   (CPU)      |   245
 30115 | DataFileRead |     1

时间花费在了 “ClientRead” 等待事件上。这意味着服务端正在等待客户端发送下一个请求。因此，应用程序服务器和数据库服务器之间的慢速网络，可能会对服务端游标产生负面影响。但 PostgreSQL 日志中不会提供有关该语句的任何信息。

结论

在本文中，我们尝试评估了将大量数据从数据库服务器传输到应用服务器的影响。

请注意：文章中讨论的行数和记录时间的数字，没有任何绝对相关性，并且可能会因许多系统和环境的因素而发生变化。

讨论更多地是关于影响方面、我们应该期待什么，以及如何作为最终用户进行分析，而不是任何绝对数字。

1. 始终尝试指定查询中的最小列数。避免使用 “SELECT *” 或者应用程序端未使用的列，以避免不必要的数据传输。

2. 避免一次向应用程序提取大量行。如果需要，请使用 LIMIT 和 OFFSET 进行正确的分页。

3. 尽可能避免使用服务端游标。PostgreSQL 仅报告第一次获取的持续时间，实际的查询性能可能不会被注意到。性能不佳的查询可能隐藏在幕后。

4. 客户端游标和数据处理时间不会影响 PostgreSQL 服务端的查询性能。

5. 等待事件分析在了解服务器花费时间的地方时非常方便。