每天2小时CPU高峰期间的RDS PostgreSQL DB缓慢和超时

Question

[超过两周以来，我观察到我的RDS实例（db.t3.small上的PostgreSQL 10.6）每天在工作时间内有2个小时的CPU高峰，并且读写延迟增加，导致响应速度慢或超时在我的应用程序中。

我确实进行了调查（请参阅下文），至此，我非常确信这些影响用户的高峰不是由我的使用引起的，并且往往认为它们是由RDS的流氓管理任务或某些PostgreSQL问题引起的。

有人忍受并解决了PostgreSQL的类似问题吗？有人可以帮助我调查RDS管理员任务方面吗？还是将我指向其他途径以深入探讨这些问题？

我观察到的内容：

• 在RDS仪表板中，清除大约2小时长的CPU高峰，其使用率约为20％，而在正常使用情况下，CPU保持在5％以下]
• 读写延迟在这些CPU峰值附近不断增加
• 我的生产应用程序数据库中的查询变得很慢，甚至超时，使我的用户无法使用它

我调查的内容：

• DB连接在峰值期间不高，最大0到10。
• 我的数据库很小，pg_size告诉我它是18MB！我目前最高的桌子有1169行，没有一列超过10列。
• 可用存储空间还可以，但仍超过19000MB
• 我知道我的用户并不忙，这是他们使用我的应用的假期。再说一次，在几天和时间范围内，我知道我的应用使用率很高，CPU的使用率从未超过5％。
• 我在此数据库上没有计划的任务或过程。
• 记录所有语句，并且花费超过200ms的时间证实了这一点，除了PgAdmin查询少于200ms的统计信息外，没有其他语句发生，这对我停止时的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

[超过2周以来，我观察到我的RDS实例（db.t3.small上的PostgreSQL 10.6）在工作时间内每天有2个小时的CPU高峰，并且读写延迟增加，这导致...

Answer 1

可能是由于PostgreSQL的后台进程而导致磁盘上的突发信用用尽。如果我没记错的话，Rds上的所有磁盘都是gp2类型。意味着您有一定的基本知识和功劳，可以花一小段时间就超过该水平。您应该能够在监视页面的io队列中看到这种效果。如果出现这种情况，您应该会看到队列中的操作数量达到峰值。最简单的解决方案是仅增加磁盘大小。