从客户端服务端两方面分析PostgreSQL的SQL执行时间

浏览数：17 / 时间：2015年06月12日

一般我们谈SQL执行时间都有意无意地把它认为是服务端执行SQL的时间。但是，有时候我们更关心从客户端看到的SQL执行总时间。比如客户在和其它数据库做性能对比的时候。

那么这个SQL执行总时间是如何构成的呢？这要分两种情况说明。

1. 无结果集返回或返回小结果集的SQL

SQL执行总时间 = 客户端驱动处理时间 + 数据库执行SQL时间 + 通信时间

对于慢SQL，数据库执行SQL的时间占了大头，其他两项可以忽略不计。这种情况的优化也就是通常的SQL调优。

对于快SQL，并且客户端和服务端不是同一台机器的情况下，通信时间往往占了大头，其他两项可以忽略不计。而且执行这样的SQL时驱动(pgjdbc,Npgsql,libpq)和数据库间只需要发生一次通信，所以这个通信时间实际上等于两台机器上的通信延迟，也即是从客户端往服务端ping得到的延迟。普通的局域网里，通信延迟在1ms左右，对于异地系统，这个延迟可能是几十毫秒甚至更多。

对于通信延迟占了大头的情况，有一种优化措施，就是把多个SQL用";"拼到一起发给服务端。但是PostgreSQL的扩展查询协议是不支持多语句的，所以在pgjdbc(使用扩展查询协议)里，会把应用传入的多语句再拆开，依次发给服务端。
如果使用的是Npgsql驱动就可以使用这招了，下面是例子

测试程序:

点击(此处)折叠或打开

DbCommand cmd = con.CreateCommand();
cmd.CommandText = "select 1;select 2";
DbDataReader reader = cmd.ExecuteReader();
if(reader.Read())
{
System.Console.WriteLine(reader.GetValue(0));
}
if (reader.NextResult() && reader.Read())
{
System.Console.WriteLine(reader.GetValue(0));
}
reader.Close();

执行结果:

抓包结果:
抓包结果表明，2个SELECT只发生了一次通信。

点击(此处)折叠或打开

[root@node1 ~]# tcpdump -X -s 512 port 40382
...
10:34:44.476552 IP 10.167.217.175.56944 > node1.mydm.com.40382: Flags [P.], seq 1028:1053, ack 2171, win 256, length 25
0x0000: 4500 0041 0977 4000 7e06 3bac 0aa7 d9af E..A.w@.~.;.....
0x0010: c1a0 119d de70 9dbe 2912 5b2e 0d8b fa0d .....p..).[.....
0x0020: 5018 0100 a4fc 0000 5100 0000 1873 656c P.......Q....sel
0x0030: 6563 7420 313b 0d0a 7365 6c65 6374 2032 ect.1;..select.2
0x0040: 00 .
10:34:44.476724 IP node1.mydm.com.40382 > 10.167.217.175.56944: Flags [P.], seq 2171:2297, ack 1053, win 59, length 126
0x0000: 4500 00a6 bae8 4000 4006 c7d5 c1a0 119d E.....@.@.......
0x0010: 0aa7 d9af 9dbe de70 0d8b fa0d 2912 5b47 .......p....).[G
0x0020: 5018 003b b82c 0000 5400 0000 2100 013f P..;.,..T...!..?
0x0030: 636f 6c75 6d6e 3f00 0000 0000 0000 0000 column?.........
0x0040: 0017 0004 ffff ffff 0000 4400 0000 0b00 ..........D.....
0x0050: 0100 0000 0131 4300 0000 0d53 454c 4543 .....1C....SELEC
0x0060: 5420 3100 5400 0000 2100 013f 636f 6c75 T.1.T...!..?colu
0x0070: 6d6e 3f00 0000 0000 0000 0000 0017 0004 mn?.............
0x0080: ffff ffff 0000 4400 0000 0b00 0100 0000 ......D.........
0x0090: 0132 4300 0000 0d53 454c 4543 5420 3100 .2C....SELECT.1.
0x00a0: 5a00 0000 0549 Z....I
...

但是如果应用程序使用了Npgsql的Prepare()，这一招会无效，因为Prepare()后Npgsql会使用扩展查询协议。
很少有场景需要在意这么点通信延迟，而且支持多语句的简单查询协议会有其他方面的问题，所以以上只是探讨一下优化的可能性，通常不值得这么折腾。

2. 返回大量结果集的SQL

SQL执行总时间 = 客户端驱动SQL发送处理时间 + 数据库初始执行SQL时间 + 通信延迟 + Max(服务端数据Fetch时间，数据传输时间，客户端数据接受时间)

排除可以忽略的“客户端驱动SQL发送处理时间 ”和“通信延迟”，可以简化为

SQL执行总时间 = 数据库初始执行SQL时间 + Max(服务端数据Fetch时间，数据传输时间，客户端数据接受时间)

数据库初始执行SQL时间是数据库从收到SQL请求到开始发送第一条记录之间的时间。对于简单的SQL，这个时间可以忽略不计。

上面的公式中有一个Max()函数。因为数据Fetch，数据传输，数据接受这3件事情是并行做的，最终客户端看到的实行时间是它们中的最大值，而不是3个之和。对返回大量结果集的SQL,Max()中的时间经常是大头。

那么Max()中，如何确定哪个是最大值呢？
一个简单的方法，是看资源利用率（结果集要足够大，使处理时间变长，这样才能容易在资源监视器中看到资源利用率数据）。
如果服务端数据Fetch时间最大，也就是处理瓶颈，那么服务端对应的那个postgres进程的CPU利用率应该用满或接近用满。用满在CPU利用率指标是指100%除以CPU核心数，对于4核CPU，25%即达到CPU瓶颈。
如果客户端数据接受是处理瓶颈，那么客户端应用程序进程的CPU利用率应该用满。
如果上面2个都不是瓶颈，那么数据传输就是瓶颈。
下面用一个例子说明一下。

测试环境:
客户端(VM)
Win 64Bit
Npgsql 2.2.3
4核2.6G CPU
服务端(VM)
Win 64Bit
PostgreSQL 9.2.8
4核2.6G CPU
网络
延迟小于1ms
带宽1Gbps(大文件拷贝速度可达到110MB/s)

测试程序：

点击(此处)折叠或打开

DateTime start = DateTime.Now;
DbCommand cmd = con.CreateCommand();
cmd.CommandText = "select select c2,c2,c2,c2,c2,c2,c2,c2,c2,c2,c2,c2,c2,c2,c2,c2,c2,c2,c2,c2 from tball,n100";
cmd.Prepare();//Prepare()后走扩展查询协议，可以优化对某些数据类型的处理速度，比如int，double。
DbDataReader reader = cmd.ExecuteReader();
while (reader.Read())
{
for(int i=0;i<reader.FieldCount;i++)
{
var obj = reader.GetValue(i);
}
}
reader.Close();
DateTime end = DateTime.Now;
System.Console.WriteLine("escape:" + (end - start).Milliseconds);

上面的tball中有4000条记录，n100中有100条记录,c2是int型，c12为varchar(10)。通信的数据量（通过Wireshark抓包获得）：70MB。
另外，测试程序调用了Prepare(),也可以使用AlwaysPrepare=true参数，目的是为了让Npgsql以binary格式接受数据。Npgsql默认采用text格式，采用text格式不仅通信量变大，也加重了Npgsql解析数据包的负担，会影响速度。
Npgsql社区也在考虑今后总是使用binary格式(https://github.com/npgsql/npgsql/issues/447)以提升效率。

实测结果：
执行时间：4.5s
每秒处理数据量：16MB
Npgsql CPU利用率：25%
PostgreSQL CPU利用率：5%

显然瓶颈在Npgsql上，并且发现Npgsql的处理时间主要耗在"reader.GetValue(i)"上，把这一行注释掉再测后的结果如下。
执行时间：2.5s
每秒处理数据量：28MB
Npgsql CPU利用率：11%
PostgreSQL CPU利用率：10%

既然Npgsql和PostgreSQL都不是瓶颈，那么瓶颈就在数据的网络传输上。但是26MB/s的传输速度离1Gbps的带宽上限相去甚远，这是为什么呢？
仔细一番研究，发现PostgreSQL服务端的送信BUFFER设得不够大。
src/backend/libpq/pqcomm.c中有个PQ_SEND_BUFFER_SIZE宏用来控制送信BUFFER的大小。这个送信BUFFER指的是一次send()调用发送的数据量，并不是socket的SO_SNDBUF选项，Windows上PostgreSQL把SO_SNDBUF设置成了PQ_SEND_BUFFER_SIZE的4倍，其他平台没有设置SO_SNDBUF。

PQ_SEND_BUFFER_SIZE的大小为8K，现在通过修改源码，把PQ_SEND_BUFFER_SIZE和SO_SNDBUF设大，发现可以提高通信数据。

PQ_SEND_BUFFER_SIZE设成32K，SO_SNDBUF也设成32K时
执行时间：1.7s
每秒处理数据量：41MB
Npgsql CPU利用率：18%
PostgreSQL CPU利用率：14%

PQ_SEND_BUFFER_SIZE设成64K，SO_SNDBUF设成256K时
执行时间：1.3s
每秒处理数据量：54MB
Npgsql CPU利用率：25%
PostgreSQL CPU利用率：20%

当PQ_SEND_BUFFER_SIZE设成64K时，瓶颈又变成Npgsql(具体而言就是Read()方法)了。这时候再从通信上抠时间已经不可能了。

3.和SQL Server的对比

SQL Server+SQLClient的组合进行相同的测试（但是不调用cmd.Prepare(),因为调了SQLClient的Prepare()性能会更差），发现SQLClient的效率比较高。
通信数据量:42MB

不删除GetValue()的测试结果
执行时间：1.5s
每秒处理数据量：28MB

性能瓶颈也在GetValue()上，把GetValue()删掉再测
执行时间：0.5s
每秒处理数据量：84MB

4.总结

1，Npgsql接受数据的效率不够高。对某些数据类型这个问题更严重，比如Datetime，对这个问题Npgsql社区也在改进中。对本例中int和varchar，在已经Prepare()的情况下很难再提高性能了，这属于整体设计上的问题。
2，PostgreSQL在通信协议上没有尽量减小通信数据量。主要有两个问题，一是text格式传输的数据量一般会被放大，当然驱动可以通过使用binary格式来回避这个问题。第二，传输数据时，每个数据列值的前面都有一个4字节的数据长度，而其他SQL Server只在可变长数据前面加长度。这导致本例中全int类型时，PostgreSQL的通信量将近是SQL Server的两倍。
3，PostgreSQL对送信BUFFER的设置略嫌保守，如果能提供一个可以让用户设置送信BUFFER的参数就好了。不过这个问题好像只在Windows上有，在Linux上测试发现默认的送信BUFFER设置已经很合适了。
4，以上几点都不必太在意。因为很少会有场景需要对16MB/s的数据查询速度抱怨。如果真不满意可以换一个性能好的机器做客户端以及在Linux上搭PostgreSQL服务器。

郑重声明：本站内容如果来自互联网及其他传播媒体，其版权均属原媒体及文章作者所有。转载目的在于传递更多信息及用于网络分享，并不代表本站赞同其观点和对其真实性负责，也不构成任何其他建议。

从客户端服务端两方面分析PostgreSQL的SQL执行时间