在每日 2 小时 CPU 峰值期间，RDS PostgreSQL DB 缓慢和超时

Question

2 多星期以来，我观察到我的 RDS 实例（db.t3.small 上的 PostgreSQL 10.6）在工作时间每天有 2 小时的 CPU 峰值，加上读写延迟增加，这导致响应速度不佳或我的应用程序超时。

我确实进行了调查（见下文），在这一点上，我非常确信这些影响我用户的峰值不是由我的使用引起的，并且倾向于认为它们是由来自 RDS 或某些 PostgreSQL 的流氓管理任务引起的问题。

有人忍受并解决了 PostgreSQL 的类似问题吗？ 有人可以帮我调查 RDS 管理任务方面吗？ 或者向我指出其他途径以查明这些问题的根源？

我观察到的：

• 在 RDS 仪表板中，清除大约 2 小时的 CPU 峰值，使用率约为 20%，而在正常使用情况下，CPU 保持远低于 5%
• 读写延迟在这些 CPU 峰值附近增加
• 来自我的生产应用程序数据库的查询变慢甚至超时，导致我的用户无法使用它

我调查了什么：

• 峰值期间数据库连接不高，最大 0 到 10。
• 我的数据库很小，pg_size 告诉我它是 18MB！目前我最高的桌子有 1169 行，没有超过 10 列。
• 可用存储空间还可以，19000MB以上
• 我知道我的用户不是很忙，幸好这是他们使用我的应用程序的假期。同样，在我知道我的应用使用率很高的日子和时间范围内，CPU 使用率从未超过 5%。
• 我在此数据库上没有计划任务或进程。
• 记录所有语句以及耗时超过 200 毫秒的语句证实了这一点，除了 PgAdmin 查询耗时少于 200 毫秒的统计数据之外没有多少语句发生，当我停止它们时不会影响 CPU 使用率李>
• 备份不是罪魁祸首，它们发生在夜间，大约需要 3 分钟。
• 据我所知，与错误查询或挂起交易无关。我在高峰期检查了 pg_stat_activity，检查了“空闲事务”和“活动”的持续时间。那里最多有 10-11 个活动。我在 4-5 中没有任何可疑之处。其余的是“rdsadmin”活动，我无权查看其详细信息。我看到的唯一让我有一点怀疑的活动是 PgAdmin 收集统计信息，但我用 pg_cancel_backend 杀死了它，杀死了我的 PgAdmin 服务器，它消失了，峰值持续了 30 多分钟。
• Performance Insights 似乎没有向我指出这些高峰期间的可疑活动。
• 在基本的 PostgreSQL 日志中，我看到检查点确实变得更长（长 10 到 100 倍），但进入了峰值，而不是在开始时。

以下是峰值开始前后的基本日志（在激活语句日志之前）：

2019-12-09 15:04:05 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:04:05 UTC::@:[4221]:LOG:  checkpoint complete: wrote 2 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.202 s, sync=0.001 s, total=0.213 s; sync files=2, longest=0.001 s, average=0.000 s; distance=16369 kB, estimate=16395 kB
2019-12-09 15:09:05 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:09:05 UTC::@:[4221]:LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.101 s, sync=0.001 s, total=0.112 s; sync files=1, longest=0.001 s, average=0.001 s; distance=16384 kB, estimate=16394 kB
2019-12-09 15:14:05 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:14:05 UTC::@:[4221]:LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.101 s, sync=0.002 s, total=0.113 s; sync files=1, longest=0.002 s, average=0.002 s; distance=16384 kB, estimate=16393 kB
2019-12-09 15:19:06 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:19:06 UTC::@:[4221]:LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.101 s, sync=0.001 s, total=0.113 s; sync files=1, longest=0.001 s, average=0.001 s; distance=16384 kB, estimate=16392 kB

[CPU PEAK STARTS here that day, at 16:20 UPC+1]

2019-12-09 15:24:06 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:24:06 UTC::@:[4221]:LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.101 s, sync=0.002 s, total=0.114 s; sync files=1, longest=0.002 s, average=0.002 s; distance=16384 kB, estimate=16391 kB
2019-12-09 15:29:06 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:29:06 UTC::@:[4221]:LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.101 s, sync=0.002 s, total=0.113 s; sync files=1, longest=0.001 s, average=0.001 s; distance=16384 kB, estimate=16390 kB
2019-12-09 15:34:06 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:34:06 UTC::@:[4221]:LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.103 s, sync=0.002 s, total=0.118 s; sync files=1, longest=0.002 s, average=0.002 s; distance=16384 kB, estimate=16390 kB
2019-12-09 15:39:06 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:39:06 UTC::@:[4221]:LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.104 s, sync=0.003 s, total=0.127 s; sync files=1, longest=0.002 s, average=0.002 s; distance=16384 kB, estimate=16389 kB
2019-12-09 15:44:06 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:44:06 UTC::@:[4221]:LOG:  checkpoint complete: wrote 2 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.219 s, sync=0.010 s, total=0.303 s; sync files=2, longest=0.010 s, average=0.005 s; distance=16392 kB, estimate=16392 kB
2019-12-09 15:49:07 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:49:09 UTC::@:[4221]:LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.318 s, sync=0.516 s, total=2.426 s; sync files=1, longest=0.516 s, average=0.516 s; distance=16375 kB, estimate=16390 kB
2019-12-09 15:54:07 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:54:09 UTC::@:[4221]:LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.367 s, sync=1.230 s, total=2.043 s; sync files=1, longest=1.230 s, average=1.230 s; distance=16384 kB, estimate=16389 kB
2019-12-09 15:59:07 UTC::@:[4221]:LOG:  checkpoint starting: time
2019-12-09 15:59:08 UTC::@:[4221]:LOG:  checkpoint complete: wrote 1 buffers (0.0%); 0 WAL file(s) added, 0 removed, 1 recycled; write=0.139 s, sync=0.195 s, total=1.124 s; sync files=1, longest=0.195 s, average=0.195 s; distance=16383 kB, estimate=16389 kB

CPU around 1 peak, CPU over a week, Read latency around a peak, Write latency around a peak,Performance Insights around Dec 10 peak, Performance Insights around Dec 9 peak

Answer 1

这可能是由于 PostgreSQL 的后台进程，您的磁盘上的突发信用已用完。 如果我没记错的话，Rds 上的所有磁盘都是 gp2 类型的。这意味着您有一定的基本 iops 和积分，您可以在一小段时间内花费超过此值。您应该能够在监控页面的队列深度指标中看到这种效果。如果发生这种情况，您应该会看到该数字的峰值。最简单的解决方案是增加磁盘大小。