某些查询中 AWS RDS 中的 MySQL 100% CPU

Question

我在 AWS 上有一个托管的 MySQL (5.7.19) 实例。一般来说，事情运作得很好。我的 CPU 使用率始终保持在 4% 左右，远低于可突增实例 (t2.micro) 的 IOPS 限制。但是，如果我在可能已超出 RAM 且位于磁盘上的表上执行不使用索引的查询，则 MySQL 将“锁定”一分钟左右。读取 IOPS 确实会增加，但通常不足以进入我的信用池。CPU 将卡在 100% 直到查询完成。来自正常运行服务的其他连接将排队（我将开始看到 60 多个连接），并且许多连接最终会超时。

这是一个锁定数据库近一分钟的示例查询：

SELECT  *
    FROM  mydb.PurchaseDatabase
    WHERE  Time between '2018-11-20 00:00:00' AND '2018-11-23 00:00:00'
      and  ItemStatus=0
      and  ItemID="exampleitem";

这是我进行此查询时的 RDS 仪表板指标：

如果我第二次进行查询，它几乎立即完成（现在可能在 RAM 中来自最近针对同一个表的查询）。类似的查询也很快（例如 0.173 秒）。我启用了慢查询日志记录以及错误日志记录，并在一天后以相同的 30 秒延迟（表已被分页或 RAM 中的任何内容）进行查询。但是，没有任何内容写入慢查询表。我检查了错误日志，当我进行慢查询时，我可以看到这样的消息：

2018-11-28T06:21:05.498947Z 0 [注意] InnoDB: page_cleaner: 1000ms 预期循环用了 37072ms。设置可能不是最佳的。（在此期间，flushed=4 和 evicted=0。）

我认为这可能只是潜在问题的另一个症状，即我的实例在从磁盘读取/写入时遇到问题。我正在使用 SSD 支持的存储，我在 EBS 卷上的突发平衡不受这些慢查询的影响。在查询之前和之后，我有很多学分。

然后，我愚蠢地决定尝试通过清除旧记录来帮助数据库。我执行了这样的删除：

DELETE FROM mydb.PurchaseDatabase
    WHERE Time between '2018-01-01 00:00:00'
      and '2018-07-31 00:00:00'
      and ItemStatus=0;

这影响了 190k 表行中的大约 50k。此查询在 0.505 秒内“返回”到 MySQL Workbench，但实际上将数据库关闭了近 8 分钟！在此期间，RDS 实例甚至无法写入日志或 Cloudwatch。

释放大约 6MB 的数据库行需要 8 分钟（在此期间 CPU 固定为 100%）。我总体上远远低于 CPU 使用率，以及我的实例大小的 IOPS。t2.micro 真的无法处理这些类型的工作负载吗？我能做些什么来更好地处理正在发生的事情吗？我也尝试写出性能日志，但在这 8 分钟的停机时间内他们实际上没有写出来，所以我从来没有真正能够看到问题。

停机后，错误日志包含以下警告：

2018-11-28T18:35:59.497627Z 0 [警告] InnoDB：信号量等待时间很长：--Thread 47281889883904 已在 srv0srv.cc 1982 行等待了 250.00 秒，信号量在 Xlockatch2080RW 中创建的 X-atlf208RW:文件 dict0dict.cc 第 1184 行一个写者（线程 id 47281896187648）已将它保留在模式独占读者数 0，等待者标志 1，lock_word：0 上次读取锁定在文件 row0purge.cc 行 862 上次写入锁定在文件 /local /mysql-5.7.19.R1/storage/innobase/dict/dict0stats.cc 第 2375 行

注意：这会关闭整个数据库，而不仅仅是 PurchaseDatabase 表。连接队列被未服务的查询填满，直到最终队列已满，并且不再接受进一步的连接。旧连接最终会超时。

我猜这是某种 EBS/RDS 交互，但我看不出你应该如何能够突发到 3000 IOPS，但我什至无法管理 30 IOP 读取突发。任何建议将不胜感激，因为我担心这些问题可能会在正常工作量期间开始出现，因为我不了解根本原因。

在此示例中，PurchaseDatabase 是使用以下语句创建的。

CREATE TABLE PurchaseDatabase (
    ID BIGINT UNSIGNED, 
    TitleID VARCHAR(127), 
    TransactionID BIGINT UNSIGNED, 
    SteamID BIGINT UNSIGNED, 
    State TINYINT UNSIGNED, 
    Time DATETIME, 
    TimeCreated DATETIME, 
    ItemID VARCHAR(127), 
    Quantity INT UNSIGNED, 
    Price INT UNSIGNED, 
    Vat INT, 
    ItemStatus TINYINT UNSIGNED, 
    PRIMARY KEY (ID, TitleID)
);

如果有帮助，这里是我的这个数据库的性能仪表板。这代表了大约 50% 的预期峰值负载（当用户在某些时区登录游戏时，我们看到一个强大的 24 小时昼夜循环）。

另请注意，此问题不仅仅由 PurchaseDatabase 表引起。对我的任何表的任何查询都可能导致同样的问题。

查看日志，我可以看到系统正在消耗 CPU。因此，mysqld 可能没有获得任何 CPU 时间来服务请求，这些请求可能已经从内存中的缓冲池提供服务。它只是没有机会：

mysqld cpuUsedPc: 0.22
OS processes cpuUsedPc: 507.87
RDS processes cpuUsedPc: 2.03

操作系统似乎陷入了对 EBS 的读/写。这是那段时间的磁盘 IO：

"diskIO": [ 
   { 
      "writeKbPS": 807.33, 
      "readIOsPS": 25.92, 
      "await": 15.95, 
      "readKbPS": 105.8, 
      "rrqmPS": 0, 
      "util": 17.75, 
      "avgQueueLen": 63.77, 
      "tps": 66.62, 
      "readKb": 6348, 
      "device": "rdsdev", 
      "writeKb": 48440, 
      "avgReqSz": 13.71, 
      "wrqmPS": 0, 
      "writeIOsPS": 40.7 
   } 
],

因此，即使我没有达到 IOPS 的突发限制，我似乎仍然受 IO 限制。这看起来对吗？

"avgQueueLen": 63.77, - 哎哟！

Answer 1

这是交换！我最终将数据库复制到相同的硬件上，并编写了一些脚本来模拟数据库上的实时流量。我还运行了一些大型查询来帮助填充缓冲池，然后确保我的副本数据库与我的生产数据库的指标大致匹配。然后我尝试对它运行大型查询并且它被锁定，即使应用了索引。我可以在不关闭生产服务的情况下重现该问题，所以现在我可以随心所欲地破坏事物。

我注意到在副本数据库生命周期的早期运行相同的大型查询并没有导致问题，并追踪锁定开始的点。它几乎在缓冲池变得足够大以推送一些数据（操作系统或其他）以在 t2.micro 实例上交换后立即发生。这是来自 Cloudwatch 的图像，显​​示在可用内存降至约 50MB 以下后交换增长：

任何大型查询（带或不带索引）在红色圆圈后开始锁定数据库。当我将数据库锁定近一分钟执行 DELETE 时，您可以看到总计 5 分钟的 CPU 使用率。

考虑到这个理论，我尝试了两种解决方案：

1) 我将 innodb_buffer_pool_size 的值更改为 375M（而不是其默认的 AWS 值，即实例 RAM 大小的 3/4）。这减少了缓冲池的最大大小，并确保数据库内存占用不会增长到足以将操作系统/等推入交换区。这有效！

2）我尝试在更大的实例（2GiB 的 RAM）上运行数据库。这也有效！

这两种解决方案都有效，而且 (1) 的好处是我不必花任何额外的钱。我正在调整 innodb_buffer_pool_size 的值，以便它在不引起交换的情况下尽可能大。我在 1.2 秒内运行了相同的 DELETE 查询，数据库继续响应。下面的屏幕截图甚至无法用于生产数据库，因为数据库会在这些长查询期间停止响应，因此仪表板永远不会更新并最终失去连接。