java - 对数据库进行 9 次查询后，执行相同查询的时间乘以 7

Question

我在 Windows 7 32 上使用 PostgreSQL (9.4.8)。我在 JDK 8u72 上通过 Eclipselink 2.6.3 和 JDBC 驱动程序 9.4.1208 访问数据库。

我正在执行一个简单的计数查询(使用 Criteria API 构建)。第一个查询需要一些时间，没问题，之后，接下来的 8 个查询花费的时间稍微少一些，这很好。然后对于第 9 个查询，响应是前一个查询的 7 倍，并且永远不会下降。

这里是我的日志的摘录:

[EL Fine]: sql: 2016-07-04 17:19:42.658--ServerSession(13112008)--Connection(27980113)--SELECT now()
INFO  - SELECT now() = 2016-07-04 17:19:41.8
[EL Fine]: sql: 2016-07-04 17:19:42.691--ServerSession(13112008)--Connection(27980113)--SELECT version()
INFO  - SELECT version() = PostgreSQL 9.4.8, compiled by Visual C++ build 1800, 32-bit
INFO  - JDBC Version = PostgreSQL 9.4.1208

[EL Fine]: sql: 2016-07-04 17:19:42.738--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:19:42.726, 2016-07-04 17:19:42.726]
1 - count : 788166 - 3974
[EL Fine]: sql: 2016-07-04 17:19:46.244--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:19:46.241, 2016-07-04 17:19:46.241]
2 - count : 788166 - 1500
[EL Fine]: sql: 2016-07-04 17:19:49.745--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:19:49.742, 2016-07-04 17:19:49.742]
3 - count : 788166 - 1495
[EL Fine]: sql: 2016-07-04 17:19:53.242--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:19:53.239, 2016-07-04 17:19:53.239]
4 - count : 788166 - 1481
[EL Fine]: sql: 2016-07-04 17:19:56.723--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:19:56.72, 2016-07-04 17:19:56.72]
5 - count : 788166 - 1497
[EL Fine]: sql: 2016-07-04 17:20:00.219--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:00.217, 2016-07-04 17:20:00.217]
6 - count : 788166 - 1484
[EL Fine]: sql: 2016-07-04 17:20:03.705--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:03.703, 2016-07-04 17:20:03.703]
7 - count : 788166 - 1498
[EL Fine]: sql: 2016-07-04 17:20:07.203--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:07.201, 2016-07-04 17:20:07.201]
8 - count : 788166 - 1498
[EL Fine]: sql: 2016-07-04 17:20:10.701--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:10.7, 2016-07-04 17:20:10.7]
9 - count : 788166 - 1491
[EL Fine]: sql: 2016-07-04 17:20:14.193--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:14.192, 2016-07-04 17:20:14.192]
10 - count : 788166 - 7550
[EL Fine]: sql: 2016-07-04 17:20:23.742--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:23.741, 2016-07-04 17:20:23.741]
11 - count : 788166 - 7553
[EL Fine]: sql: 2016-07-04 17:20:33.296--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:33.295, 2016-07-04 17:20:33.295]
12 - count : 788166 - 7567
[EL Fine]: sql: 2016-07-04 17:20:42.864--ServerSession(13112008)--Connection(27980113)--SELECT COUNT(DISTINCT(ID)) FROM recorder.records WHERE ((channel_number IN (?, ......, ?, ?)) AND (rec_start BETWEEN ? AND ?))
    bind => [10, 11, 12, ......, 299, 2016-03-04 17:20:42.863, 2016-07-04 17:20:42.863]
13 - count : 788166 - 7545

如您所见，第一个查询需要 3974 毫秒，接下来的查询大约需要 1500 毫秒，然后才超过 7500 毫秒!

会出什么问题？出现问题时，数据库不会占用更多的 CPU 资源，我的程序也不会。

Answer 1

这看起来像是 PostgreSQL 使用的通用计划比之前使用的计划表现更差。

如果您使用 java.sql.PreparedStatement，JDBC 驱动程序将替换前 4 次执行的参数，并在第 5 次执行时创建一个服务器端准备语句，它将被使用从此以后(假设您使用连接参数 prepareThreshold 的默认值 5)。

对于接下来的 5 次执行，PostgreSQL 服务器将为该语句创建单独的计划，替换实际传递的参数。

然后它将创建一个通用计划(使用占位符而不是查询参数)，如果查询优化器估计这个通用计划的性能不会比之前使用的特定计划差，那么这个通用计划将永远使用之后。

因此在这种情况下，前 9 次执行将使用与后续执行不同的计划，如果查询优化器做出了错误的选择，之后您会看到性能下降。

我看到两个选项:

• 在 PostgreSQL 命令行上使用 PREPARE 为您的查询创建准备好的语句，然后使用 EXPLAIN (ANALYZE) EXECUTE，比较所使用的执行计划对于前 5 次执行以及之后使用的通用查询的执行计划(您可以通过占位符 $1、$2 等来区分通用查询)。
  希望您随后可以弄清楚为什么通用计划更差并改进您的查询。

• 简单的方法:阅读the documentation如何通过将 prepareThreshold 设置为 0 来禁用此查询的服务器端准备语句。