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

After 9 queries to database, the time to perform the same query is multiplied by 7

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

我正在执行一个简单的计数查询(使用条件 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 电量,我的程序也不会。

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

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

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

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

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

我看到两个选项供您选择:

  • 在 PostgreSQL 命令行上使用 PREPARE 为您的查询创建准备好的语句,然后使用 EXPLAIN (ANALYZE) EXECUTE,将前 5 次执行所用的执行计划与之后使用的通用查询的执行计划(您可以从占位符 </code>、<code> 等判断通用查询)。
    希望您随后可以弄清楚为什么通用计划更糟糕并改进您的查询。

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