Postgres RDS 数据库数据库连接在星期六无限增加，导致 Spring Boot Java API 应用程序中出现“JDBCConnectionException”

Posted 2023-02-24

【中文标题】Postgres RDS 数据库数据库连接在星期六无限增加，导致 Spring Boot Java API 应用程序中出现“JDBCConnectionException”

【英文标题】：Postgres RDS database DB connections increasing infinitely on Saturdays causing "JDBCConnectionException" in Spring Boot Java API app

【发布时间】：2021-12-20 15:28:32

【问题描述】：

更新添加了读/写吞吐量、IOPS 和队列深度图指标，并在我所说的错误开始的时间位置标记了图

注意：您好，只是从有经验的 DBA 或数据库开发人员（或任何有这方面知识的人）那里寻找可能导致此问题的建议。我拥有的一些日志/数据很敏感，因此我无法在此处重新发布，但我已尽力提供屏幕截图和调试数据，以便人们帮助我。谢谢。

您好，我有一个托管在 Amazon (AWS) 上的 Postgres RDS 数据库（版本 12.7 引擎）。该数据库每小时被 API 客户端（Spring Boot/Web/Hibernate/JPA Java API）“命中”或调用数千次。它仅在跨 5 个表的 Postgres 视图上的后端执行一个 1 hibernate sql 查询。 queryDB 实例 (class= db.m5.2xlarge) 规格为：

8 vCPU
32 GB RAM
Provisioned IOPS SSD Storage Type
800 GiB Storage
15000 Provisioned IOPS

我看到的问题是在星期六我醒来看到许多 JDBCConnectionExceptions 日志，我注意到我的 API Docker 容器（在 ECS 上定义为服务任务）托管在 AWS Elastic Container Service 上(ECS) 将开始失败并返回HTTP 503 错误，例如

org.springframework.dao.DataAccessResourceFailureException: Unable to acquire JDBC Connection; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection

在检查 AWS RDS DB 状态时，我还可以看到会话/连接急剧增加，如下图所示，~600 个连接。它会不断增加，似乎不会停止。

在检查 postgres 数据库 pg_locks 和 pg_stat_activity 表时，当我开始获取所有这些 JDBCConnectionExceptions 并且 DB 连接数跃升至约 400（在这个特定时间）时，我确实看到我的许多 API 查询记录在有趣的状态。我将数据导出为 CSV，并在下面包含了一段摘录：

wait_event_type   wait_event         state.                                         query
---------------   ------------       ---------------------------------------------  ----- 
IO                DataFileRead       active (480 times logged in pg_stat_activity)  SELECT * ... FROM ... query from API on postgres View
IO                DataFileRead       idle (13 times logged in pg_stat_activity)     SELECT * ... FROM ... query from API on postgres View
IO                DataFilePreFetch   active (57 times logged in pg_stat_activity)   SELECT * ... FROM ... query from API on postgres View
IO                DataFilePreFetch   idle (2 times logged in pg_stat_activity)      SELECT * ... FROM ... query from API on postgres View
Client            ClientRead         idle (196 times logged in pg_stat_activity)    SELECT * ... FROM ... query from API on postgres View
Client            ClientRead         active (10 times logged in pg_stat_activity)   SELECT * ... FROM ... query from API on postgres View
LWLock            BufferIO           idle (1 times logged in pg_stat_activity)      SELECT * ... FROM ... query from API on postgres View
LWLock            BufferIO           active (7 times logged in pg_stat_activity)    SELECT * ... FROM ... query from API on postgres View

如果我在我的 API 和 DB 运行且稳定时查看我的pg_stats_activity 表，API 查询中的大多数行只是Client ClientRead idle 状态，所以我觉得这里有问题。

您可以在发生这种情况时（即大约 19:55 UTC 或下午 2:55 CST）在 DB 上看到以下“性能指标”，DataFileRead 和 DataFilePrefetch 高得惊人，并且不断增加，这支持了 @我在上面发布的 987654345@ 数据。另外，正如我上面所说，在正常的 DB 使用过程中，当它稳定时，API 查询只会在 pg_stat_activity 表中处于Client ClientRead Idle 状态，众多的 DataFileRead/Prefetches/IO 和 ExclusiveLocks 让我感到困惑。

我不希望任何人为我调试此问题，但如果 DBA 或有类似经验的人可以为我缩小问题范围，我将不胜感激。老实说，我不确定这是否是一个 API 查询耗时太长（没有意义，因为 API 多年来一直运行稳定），星期六在我不知情的情况下在 Postgres DB 上运行的东西（我真的认为是这样的正在继续），或者一个错误的 postgresql 查询进入数据库，它锁定了资源并导致死锁（当我阅读 Postgres 自行解决死锁时，这对我来说并不完全有意义）。此外，正如我之前所说，在后端进行 SQL 查询的所有 API 调用都只是在 Postgres VIEW 上执行SELECT ... FROM ...，据我了解，您可以使用 ExclusiveLocks 执行并发 SELECTS 所以.....

将在此处接受任何建议或针对此问题的可能原因提出建议

Read-Throughput（第一个 JdbcConnectionException 发生在中部标准时间下午 2:58 或 14:58 左右，因此我在图表中标记了 READ 吞吐量开始下降的位置，因为 DB 查询超时且 API 容器失败)

写入吞吐量（API 只读取，所以我假设这里的峰值是为了写入副本 RDS 以保持同步）

总 IOPS（IOPS 从早上 8 点开始逐渐增加，但随着 API 调用的增加，这是预期的，但这些 API 调用的总计数与其他有 0 个问题的日子相匹配，所以不真的指出了这个问题的原因）

队列深度（您可以看到我标记图表的位置以及它的峰值正好在下午 14:58 或 2:58 左右，第一个 JdbcConnectionExceptions 开始发生，API 查询开始超时，并且 Db 连接开始呈指数增长）

EBS IO Balance（这个时候burst balance也基本降到了0）

性能洞察（DataFileRead、DataFilePrefetch、buffer_io 等）

【问题讨论】：

如果出现奇怪的查询，您会注意到它们在 pg_stat_activity 中的查询文本，不是吗？是否所有连接都来自同一个 IP（应用服务器的）并且是同一个用户？

您已经向我们展示了对 IO 等待时间的监控，但是 IO 吞吐量呢？

@jjanes 是的，所有的 SELECT 查询都来自我的 API，并且没有任何奇怪的查询。唯一的“奇怪的事情”是，当它像这样失败时，所有的 wait_types 等都是 IO/DateFileRead/Fetch，通常情况下，它永远不会那样 - 从我的 API 登录到该 pg_stat_table 的所有查询都只是“Client ClientRead Idle "，此外，当 Db 连接增加到 700+ 时，pg_lock 表中存在等量的 ExclusiveLock（700+）。但是，是的，IP 都与 AWS ECS 集群上运行的 API docker 容器相匹配。我现在将发布 IO 吞吐量，谢谢

【参考方案1】：

需要调查的一些事情。

查询性能会随着时间的推移而下降。请求的数据量可能会增加，尤其是日期预测的数据量。查看 Performance Insights 你可以看到有多少块被读取（磁盘/io），命中（从缓冲区）你想要尽可能多的命中。突发平衡的损失是一个真实的指标，表明这是正在发生的事情。这在一周内不是问题，因为您的请求较少。

您必须为这些查询提供服务的共享缓冲区的实际数量，默认值为 RAM 的 25%，您可以将其调整为更高，有人说是 40%。它是一种黑暗艺术，您不太可能在外面找到答案调整和测试。

抽真空并分析您的表格。数据来自某个地方对吗？随着更新、删除和插入表变得充满垃圾等。在某个点上，自动清理进程在默认级别是不够的。您可以将这些调整为更具攻击性，在夜间手动开火等。

索引管理，同上。

Autovacuum docs

Resource Consumption

【参考方案2】：

这只是看起来您的应用服务器的要求越来越高，而数据库无法跟上。您其余的大部分观察结果只是自然的结果。为什么会发生这种情况可能最好从应用服务器而不是数据库服务器进行调查。要么是发出越来越多的请求，要么每个请求都需要更多的 IO 才能完成。 （您可以通过提高数据库效率来解决此问题，例如添加缺失的索引，但这需要您共享查询和/或其执行计划）。

看起来您的应用服务器配置为始终保持 200 个连接，即使几乎所有连接都处于空闲状态。所以，这就是它的作用。

这就是ClientRead wait_event 的意思，它只是坐在那里空闲试图读取来自客户端的下一个请求，但没有得到任何请求。可能有少数其他连接正在积极接收和处理请求，完成所有实际工作但占用 pg_stat_activity 的一小部分。所有这些额外的空闲连接都没有任何好处。但他们可能也没有造成任何真正的伤害，除了让 pg_stat_activity 看起来不整洁，让你感到困惑。

但是一旦应用服务器开始生成请求的速度超过了它们的服务速度，正在进行的请求开始堆积，并且应用服务器被配置为不断添加越来越多的连接。但是你不能仅仅通过打开更多的连接来欺负磁盘驱动器来提供更多的吞吐量（至少在你达到某个完全饱和的阈值时不会）。因此，您拥有的活动连接越多，它们之间分配相同数量的 IO 的次数就越多，每个连接的速度就越慢。让这 700 个额外的连接全部等待不会使数据更快到达。拥有更多的连接并没有任何好处，而且可能会造成一些伤害，因为它会产生争用，而处理争用本身就是一种资源消耗。

您提到的 ExclusiveLocks 可能是每个活动会话在其自己的事务 ID 上的锁。它们不会成为问题的原因，只是表明您有很多活动会话。

当两个会话同时需要完全相同的数据时，您会得到 BufferIO。一个请求数据（DataFileRead），另一个请求在第一个完成时得到通知（BufferIO）。

【讨论】：

我的 Hikari 配置是 maximumPoolSize: 30 connectionTimeout: 30000 minimum-idle: 10

你有 20 个在运行吗？

【参考方案3】：

根据您分享的内容，我猜您的连接没有正确关闭。

【讨论】：

数据库如何几乎每周/每月正常运行，除了选择星期六？这让我很困惑。此外，我计算了这些天发生这些“神秘”故障的 API 调用总数，并且 API 调用的总数与其他大多数天的问题相匹配，当时有 0 个问题。会不会是死锁问题？不是所有的 IO/DataFileRead 进程和相等数量的 ExclusiveLocks (700+) 都意味着一些查询锁定了表，因此查询超时，返回 500 服务器错误，然后 AWS 开始创建新容器，导致无限的数据库连接?

另外，我在我的 API 中使用 Spring Boot Hibernate/Data JPA，它带有 Hikari 连接池，所以我相信 Hikari 可以管理关闭 Db 连接，所以我不需要这样做跨度>