网络和游标对查询性能的影响
很多时候，我们看到用户对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。通过设置，捕获所有执行时间超过250ms的语句。
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.数据库主机所在服务器2.通过网络连接的应用程序所在服务器
上面执行。
返回大量行的查询
案例 1. 在数据库主机上执行
下面是auto_explain生成的几行PostgreSQL日志
2021-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 ms内完成，并返回100万条记录，但查询的总持续时间却报告为1591.784 ms。有什么区别呢？EXPLAIN ANALYZE显示了这个简单查询的规划时间是微秒级的，其中数据是来自一个没有任何索引的表。所以规划时间不应该是原因。
案例2. 从远程应用主机执行
这次日志中的信息看起来有所不同
2021-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 ms！尽管查询的实际执行基本保持在 1069.153 ms。这是一个巨大的差异。可能是什么原因呢？
返回少量行的查询
可以对上面的查询稍加修改，以只返回最大值。修改后的测试查询可能如下所示：
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 ;
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;
查询计划或时间不会改变太多，只是有一个额外的聚合。即使有与主题无关的计划更改，我们也会讨论它，因为我们只考虑了查询执行的外部节点与PostgreSQL所报告的执行时间之间的时间差。
案例 1. 在数据库主机上执行
2021-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 ms 与报告的 1011.143 ms 的持续时间之间没有太大差别。到目前为止的观察表明，当返回太多行时，会消耗额外的时间。
案例2. 从远程应用主机执行
2021-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 ms 和 1193.387 ms之间没有太大差别。总的来说，我可以放心地从结果中假设，如果数据传输量是很小的，那么不同主机上的应用服务器不会有太大区别；同时，如果涉及到大量的结果传输，其影响是巨大的。
分析等待事件
幸运的是，较新版本的PostgreSQL为我们提供了一种很好的方法来监视会话/连接的pg_stat_activity视图中的"wait_event"信息。
来自Percona的支持，我们使用了来自pg_gather中的片段脚本，通过收集多个示例来收集性能信息，包括等待事件。脚本以每10ms的间隔收集等待事件的样本，因此在20秒内将有2000个样本。除了UI，收集的信息还可以使用后端查询进行分析。
下面是我看到的关于PID为25617的情况 (返回大量行到远程主机)。
postgres=# 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：Waiting to write data to the client.
它表明将数据写入到客户端所消耗的时间。等待事件为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毫秒的延迟。但是这些都不会影响服务端的查询性能，因为游标已经缓存在客户端。报告的查询时间和持续时间类似于从远程应用主机执行大量行的查询。正如预期的那样，网络的影响显而易见
2021-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 wraps the database server-side cursor in named cursors. A named cursor is created using the cursor()he name parameter
令人惊讶的是，即使配置了auto_explain，PostgreSQL的日志也没有提供关于查询的更多信息，甚至也没有持续时间的信息。只有如下一行信息
2021-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)
随后产生了如下一条日志
2021-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.等待事件分析对于了解服务器在哪里花费时间非常方便。
