postgresql - RDS PostgreSQL 数据库在每日 2 小时 CPU 高峰期间缓慢和超时

Question

在 2 周多的时间里，我观察到我的 RDS 实例(db.t3.small 上的 PostgreSQL 10.6)在工作时间每天有 2 小时的 CPU 峰值，同时增加了读取和写入延迟，导致我的应用程序响应不佳或超时。

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

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

我观察到的:

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

我调查过的内容:

• 数据库连接在高峰期不高，最多 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 和积分，您可以花在短时间内超过它。您应该能够在监控页面上的队列深度指标中看到这种效果。如果这令人高兴，您应该会看到该数字的峰值。最简单的解决方案是增加磁盘大小。