关于 Tower 在 2017.2.10 故障的说明

关于 Tower 在 2017.2.10 故障的说明

徐峥徐峥
Tower 在 2017 年 2 月 10 日上午 9:35 点出现了大范围访问缓慢或无法访问的故障,我们立即开始修复,11:15 陆续恢复正常访问,故障持续约 1 小时 40 分钟。这次故障正好发生在早上工作的高峰时段,对所有受影响的用户,我们致以诚挚的歉意,现将故障的详细情况汇报如下。

TL;DR

程序员大意写下的缺陷引发了大面积访问故障。修复时又因为疏忽导致故障时间长达近两小时。作为补偿,我们将为所有 Tower Pro 用户延长 10 天付费期。

原因

我写了一个查询
ModelOne.where \
  model_two_id: instance_of_model_three.has_many_model_twos
                                       .and_some_scope
Rails 生成的 SQL 是
SELECT
  *
FROM model_ones
WHERE model_ones.model_two_id
IN (SELECT
  model_twos.id
FROM model_twos
WHERE model_three_id = id_of_model_three_instance
AND some_scope = some_value)
这个 SQL 没有用 model_ones 上对 model_two_id 的索引,对 model_ones 做了全表扫描。今天早上在生产环境,同时有三十多个这样的查询在执行,数据库实例 CPU 跑满,整个数据库响应缓慢。进而 unicorn 超时自杀。

其中,查询里的条件 and_some_scope 是关键。如果查询只是
ModelOne.where \
  model_two_id: instance_of_model_three.has_many_model_twos
Rails 会生成两个查询
SELECT
  *
FROM model_twos
WHERE model_three_id = id_of_model_three_instance
SELECT
  *
FROM model_ones
WHERE model_two_id IN (ids_from_query_1)
这组查询会如期使用索引,分别都不超过 3ms. 但一旦加上了 and_some_scope, Rails 就会把两个查询组合起来,导致 MySQL 判断不应该用索引。

为什么测试阶段没发现

这个查询只会在访客访问团队页面和动态页面时触发。在长达一周的灰度发布中,因为疏忽,我没有用访客身份的成员来进行测试。与此同时,在灰度环境中即便有访客触发了这个满查询,因为单个查询还不能耗尽数据库实例的 CPU 资源,也没有引起我注意。

为什么故障用了两小时才处理好

我们立刻回滚了代码,但是因为回滚之前触发的查询依然在执行,所以数据库压力并没有立刻降下来。通过
SELECT
  *
FROM INFORMATION_SCHEMA.PROCESSLIST
WHERE command != 'Sleep';
查看数据库状态的时候,这些导致问题的查询的 state 是 "Sending data", 所以一开始我们的注意力放在了别的地方。

最后注意到时间比较长的查询一直是相同的三十来个
SELECT
  *
FROM model_ones
WHERE model_ones.model_two_id
IN (SELECT
  model_twos.id
FROM model_twos
WHERE model_three_id = id_of_model_three_instance
AND some_scope = some_value)
然后意识到 "Sending data" 这个 state 并不表示「已经查询完了,正在发送数据」(What does it mean when MySQL is in the state "Sending data"? and 9.14.2 General Thread States)。这些进程中很多的 rows_read 和 rows_examined 都是 0, 它们应该在等 IO. 于是杀掉了这三十多个进程,故障才恢复了。

教训和措施

  • 要清楚 Rails 生成的每一个查询
  • 测试的时候不要漏掉分支
  • 不要忽视慢查警告

补偿

为了表达我们的歉意,我们将为每个 Tower Pro 团队延长 10 天付费期以作补偿,补偿已经生效。

---
致以深切的歉意
充满愧疚的 Snow
文章被以下专栏收录
28 条评论
推荐阅读