努力调试 Amazon RDS MySQL 实例上的高 CPU 使用率

Question

我们正在运行 m1.xlarge MySQL RDS 服务器，但在 CPU 使用率高时遇到了一些问题。几周前，我们遇到了一些问题，大型实例的 CPU 利用率达到 100%。当我们将大小升级到 xlarge 时，情况稳定了一段时间，但 CPU 使用率逐渐再次上升。

在过去一周左右的时间里，CPU 利用率一直处于 90 年代的高位，昨天一直达到 100% 左右，这使我们的生产站点陷入停顿。重新启动数据库服务器后，CPU 使用率在数小时内回升至相同水平。

我已经在 mysql 服务器上运行了 show processlist，并且一直在通过 MySQL admin 进行监控。似乎也没有任何特别长时间运行的查询或大量查询。有几个进程长时间处于睡眠状态……这些是在我们的主应用程序之外运行的独立工作守护进程，它们与数据库进行通信。我在下面的 processlist 输出中复制了服务器名称，以说明它们是什么：

+------+----------+---------------------------------------------------+--------------+---------+-------+--------------+----------------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+------+----------+---------------------------------------------------+--------------+---------+-------+--------------+----------------------------------------------------------------------------------------+
| 13 | rdsadmin | localhost:43513 | mysql | Sleep | 14 | | NULL |
| 15 | proddbuser | app-server-1.eu-west-1.compute.internal:36460 | proddb | Sleep | 46 | | NULL |
| 451 | proddbuser | app-server-1.eu-west-1.compute.internal:55512 | proddb | Sleep | 29 | | NULL |
| 912 | proddbuser | app-server-1.eu-west-1.compute.internal:45171 | proddb | Sleep | 13 | | NULL |
| 941 | proddbuser | app-server-1.eu-west-1.compute.internal:47353 | proddb | Sleep | 53 | | NULL |
| 951 | proddbuser | app-server-1.eu-west-1.compute.internal:48014 | proddb | Sleep | 37 | | NULL |
| 1009 | proddbuser | app-server-1.eu-west-1.compute.internal:51787 | proddb | Sleep | 36 | | NULL |
| 1041 | proddbuser | app-server-1.eu-west-1.compute.internal:53777 | proddb | Sleep | 14 | | NULL |
| 1572 | proddbuser | app-server-1.eu-west-1.compute.internal:42989 | proddb | Sleep | 3 | | NULL |
| 1592 | proddbuser | app-server-1.eu-west-1.compute.internal:43279 | proddb | Sleep | 162 | | NULL |
| 2909 | proddbuser | app-server-1.eu-west-1.compute.internal:37768 | proddb | Sleep | 35 | | NULL |
| 3028 | proddbuser | app-server-1.eu-west-1.compute.internal:42568 | proddb | Sleep | 5 | | NULL |
| 3119 | proddbuser | app-server-1.eu-west-1.compute.internal:46913 | proddb | Sleep | 76 | | NULL |
| 3189 | proddbuser | app-server-1.eu-west-1.compute.internal:51466 | proddb | Sleep | 5 | | NULL |
| 3216 | proddbuser | app-server-2.eu-west-1.compute.internal:44097 | proddb | Sleep | 14552 | | NULL |
| 3218 | proddbuser | app-server-2.eu-west-1.compute.internal:44099 | proddb | Sleep | 14552 | | NULL |
| 3219 | proddbuser | app-server-2.eu-west-1.compute.internal:44107 | proddb | Sleep | 44 | | NULL |
| 3220 | proddbuser | app-server-2.eu-west-1.compute.internal:44113 | proddb | Sleep | 26 | | NULL |
| 3223 | proddbuser | app-server-2.eu-west-1.compute.internal:44184 | proddb | Sleep | 50 | | NULL |
| 3224 | proddbuser | app-server-2.eu-west-1.compute.internal:44187 | proddb | Sleep | 1 | | NULL |
| 3226 | proddbuser | app-server-2.eu-west-1.compute.internal:44208 | proddb | Sleep | 33 | | NULL |
| 3229 | proddbuser | app-server-2.eu-west-1.compute.internal:44250 | proddb | Sleep | 14 | | NULL |
| 3232 | proddbuser | app-server-2.eu-west-1.compute.internal:44279 | proddb | Sleep | 26 | | NULL |
| 3233 | proddbuser | app-server-2.eu-west-1.compute.internal:44297 | proddb | Sleep | 31 | | NULL |
| 3237 | proddbuser | app-server-2.eu-west-1.compute.internal:44334 | proddb | Sleep | 27 | | NULL |
| 3239 | proddbuser | app-server-2.eu-west-1.compute.internal:44338 | proddb | Sleep | 11 | | NULL |
| 3241 | proddbuser | app-server-2.eu-west-1.compute.internal:44356 | proddb | Sleep | 26 | | NULL |
| 3260 | proddbuser | app-server-2.eu-west-1.compute.internal:44619 | proddb | Sleep | 8 | | NULL |
| 3337 | proddbuser | utility-server-1.eu-west-1.compute.internal:45193 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 309416 LIMIT 1 |
| 3419 | proddbuser | utility-server-1.eu-west-1.compute.internal:46136 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 284530 LIMIT 1 |
| 3463 | proddbuser | app-server-1.eu-west-1.compute.internal:59619 | proddb | Sleep | 9406 | | NULL |
| 3504 | proddbuser | utility-server-1.eu-west-1.compute.internal:47063 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 260571 LIMIT 1 |
| 3577 | proddbuser | app-server-1.eu-west-1.compute.internal:34394 | proddb | Sleep | 6734 | | NULL |
| 3585 | proddbuser | utility-server-1.eu-west-1.compute.internal:47990 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 231273 LIMIT 1 |
| 3664 | proddbuser | utility-server-1.eu-west-1.compute.internal:48909 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 201525 LIMIT 1 |
| 3716 | proddbuser | app-server-2.eu-west-1.compute.internal:56301 | proddb | Sleep | 27 | | NULL |
| 3748 | proddbuser | utility-server-1.eu-west-1.compute.internal:49850 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 167839 LIMIT 1 |
| 3771 | proddbuser | my-pc:30101 | NULL | Query | 0 | NULL | show processlist |
| 3831 | proddbuser | utility-server-1.eu-west-1.compute.internal:50785 | proddb | Query | 0 | Sending data | SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 123228 LIMIT 1 |
+------+----------+---------------------------------------------------+--------------+---------+-------+--------------+----------------------------------------------------------------------------------------+

我还应该说，在此期间网站上的流量极低，相对于正常的高峰时段，大约是我们在高峰时段看到的负载的 10%。

我们还有新的遗物监控，它向我们展示了最耗时的应用程序数据库调用是什么。它向我们展示了一个占我们应用程序在数据库中花费 99% 时间的特定调用是一个简单的按 id 查询查找，如下所示：

SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`id` = 123 LIMIT 1

（与在上述进程列表中运行的查询不太一样）

在过去一周左右的时间里，此操作变慢了，请求时间之间的标准偏差在增加，并且以秒为单位测量的最长时间。我认为这只是 CPU 利用率问题的结果，而不是原因。

这个表有大约 80,000 行，所以不是很大。预计数据库中的大部分应用程序时间都花在查找此表中的记录上，应用程序的主要功能基于此。我自己从我的应用程序服务器到生产数据库运行了几次类似的查询，而 CPU 使用率保持在 100% 左右，并且在 1 或 2 毫秒内响应。

基于以上所有情况，我们不确定如何进行调试。只是想知道是否有人知道什么样的事情可能是根本原因以及如何调查这些事情？对运行我们的数据库服务器的底层服务器的访问受到限制，因为它是一个 Amazon RDS 实例。

Answer 1

设法解决了这个问题，这些是我遵循的步骤：

首先，我通过在他们的论坛上发帖联系了 Amazon RDS 团队，他们确认是 mysqld 进程占用了所有这些 CPU - 这消除了物理服务器上运行的其他东西的配置错误

其次，我追踪了正在运行的查询的来源：

SELECT `mytable`.* FROM `mytable` WHERE `mytable`.`foreign_key` = 231273 LIMIT 1 

我最初忽略了这个原因，因为当我监视 show processlist 输出时，这些查询似乎都没有花费特别长的时间。在用尽其他途径之后，我决定可能值得跟进......我很高兴我做到了。

正如您在 show processlist 输出中所见，这些查询来自一个实用程序服务器，该服务器运行一些存在于我们的主应用程序代码之外的战术实用程序作业。这就是为什么它们在我们的新遗物监控中没有出现缓慢或导致问题的原因，因为新的遗物代理仅安装在我们的主应用程序服务器上。

松散地遵循本指南：

http://www.mysqlperformanceblog.com/2007/02/08/debugging-sleeping-connections-with-mysql/

我能够将这些查询跟踪到我们实用程序服务器盒上的特定运行进程。这是一段 ruby​​ 代码，它在遍历大约 70,000 条记录、检查一些字段值并使用这些值来决定是否需要在“mytable”中创建新记录时效率非常低下。在进行了一些分析之后，我能够确定，该进程不再需要，因此可以被终止。

更糟糕的是，由于 cron 作业的配置方式以及每个实例花费了多长时间，同一进程似乎同时运行了 6 个实例！我杀死了这些进程，令人难以置信的是，我们的 CPU 使用率从 100% 左右下降到了 5% 左右！