2016年9月21日，晚上九点。

我刚洗完澡，准备躺床上看会儿书，手机突然响了。是运维同事打来的："线上出问题了，大量用户反馈页面打不开，错误率飙升到30%，你赶紧看看。"

我心里一沉，赶紧打开电脑，登录服务器。这一看，就是整整一夜。

一、故障发现

晚上九点十五分，监控系统开始报警。错误率从平时的0.1%飙升到30%，主要集中在用户登录和商品详情页。用户反馈集中在两个问题：

  1. 登录时提示"系统繁忙，请稍后重试"
  2. 商品详情页加载缓慢，有时直接500错误

我先看了一下服务器的基本状态：CPU使用率85%，内存使用率90%，磁盘I/O正常，网络带宽正常。看起来不是服务器资源的问题。

然后我看了一下PHP-FPM的状态，发现有大量进程处于"busy"状态，请求队列堆积。这说明PHP处理不过来了，但是为什么处理不过来呢？

二、初步排查

我先看了一下Nginx的错误日志，发现大量"upstream timed out"错误，PHP-FPM响应超时。这说明PHP脚本执行时间太长，导致PHP-FPM进程被占用，新的请求无法处理。

那么，是什么导致PHP脚本执行时间太长呢？

我先看了一下最近的代码部署记录。当天下午四点，部署了一个新版本，主要改动是优化了商品详情页的查询逻辑，增加了一个关联查询。

"难道是这个关联查询的问题？"我心里想。

我先看了一下数据库的状态。MySQL的CPU使用率70%，慢查询日志里有大量慢查询，主要集中在商品详情页的查询上，平均执行时间5秒，最长的达到了15秒。

"果然是数据库查询的问题。"我松了一口气，以为找到了原因。

但是，当我仔细看慢查询日志的时候，发现事情没那么简单。那个关联查询确实慢，但是只占慢查询的30%，还有70%的慢查询是其他查询，而且这些查询平时都很快，为什么突然变慢了？

三、深入排查

我开始怀疑是数据库的整体性能出了问题。我看了一下MySQL的连接数，发现连接数达到了上限（max_connections=500），大量连接处于"Sleep"状态。

"为什么有这么多Sleep连接？"我心里疑惑。

我看了一下这些Sleep连接的来源，发现大部分来自PHP-FPM。PHP-FPM的连接池配置是持久连接，每个PHP进程会保持一个数据库连接。正常情况下，PHP进程处理完请求后，连接会归还连接池，等待下一个请求使用。

但是，如果PHP进程处理请求的时间很长，连接就会被长时间占用。而如果PHP进程因为某些原因卡住了（比如死锁、无限循环），连接就会一直被占用，直到超时。

我看了一下PHP-FPM的进程状态，发现有一些进程已经运行了超过10分钟，这显然不正常。正常的PHP请求应该在1秒内完成。

"这些进程在干什么？"我用strace跟踪了一个卡住的进程，发现它在等数据库的响应。

"数据库为什么不响应？"我又看了一下MySQL的进程列表，发现有大量查询处于"Locked"状态，在等待表锁。

"表锁？"我心里一惊。我们用的是InnoDB，应该是行锁才对，怎么会有表锁？

四、找到真正的原因

我仔细看了一下那些被锁住的查询，发现它们都在等待同一个表的锁——用户行为日志表。

这个表是用来记录用户行为的，每次用户访问页面，都会插入一条记录。平时这个表的写入很频繁，但是因为是InnoDB，行锁不会影响并发。

但是，当天下午部署的新版本中，有一个定时任务，每小时执行一次，会对用户行为日志表做一次统计查询，用的是SELECT COUNT(*) FROM user_log WHERE ... GROUP BY ...。

这个查询本身没问题，但是问题在于，这个查询用了LOCK TABLES语句！

原来，开发这个定时任务的同事，为了保证统计数据的一致性，加了LOCK TABLES user_log READ语句。这个语句会给整个表加一个读锁，导致其他所有写入操作都被阻塞，直到锁被释放。

而这个统计查询，因为数据量已经很大了（几百万条记录），执行时间需要5-10分钟。在这5-10分钟里，用户行为日志表被加了读锁，所有写入操作都被阻塞，PHP进程都在等数据库的锁，导致PHP-FPM进程被占满，新的请求无法处理，最终导致整个网站瘫痪。

找到原因的时候，已经是凌晨三点了。

五、紧急修复

找到原因后，我先紧急处理：

  1. Kill掉那个卡住的统计查询，释放表锁
  2. 暂停那个定时任务
  3. 重启PHP-FPM，清理卡住的进程

处理完之后，网站很快恢复了正常，错误率降到了0.1%以下。

然后，我修改了那个定时任务，去掉了LOCK TABLES语句，改用SET TRANSACTION ISOLATION LEVEL REPEATABLE READ的事务隔离级别来保证数据一致性，这样就不会锁表了。

同时，我也优化了那个统计查询，增加了合适的索引，把查询时间从5-10分钟降到了10秒以内。

六、这一夜学到的教训

等一切处理完，已经是早上六点了。窗外天已经亮了，我坐在椅子上，疲惫但是清醒。

这一夜的排查，让我学到了很多：

1. 线上故障排查要循序渐进 不要一上来就猜原因，要从表象入手，一步步深入。先看服务器状态，再看应用日志，再看数据库状态，最后看代码。每一步都要有证据，不要凭感觉。

2. 日志和监控非常重要 如果没有完善的日志和监控，这个故障可能要排查更久。Nginx错误日志、PHP-FPM慢日志、MySQL慢查询日志、服务器监控，这些都是排查故障的利器。平时一定要把日志和监控做好。

3. 数据库锁是隐形杀手 很多时候，性能问题不是因为SQL写得不好，而是因为锁。表锁、行锁、间隙锁，这些锁如果用得不好，会导致严重的性能问题。特别是LOCK TABLES这种全表锁，在高并发场景下绝对不能用。

4. 代码审查不能走过场 这个Bug的根源，是那个同事在代码里加了LOCK TABLES语句。如果代码审查的时候有人注意到这个问题，就不会有这次故障了。代码审查不是走过场，要认真看每一行代码，特别是数据库相关的代码。

5. 压力测试要覆盖真实场景 这个定时任务在测试环境测试过，但是测试环境的数据量小，查询很快，锁的时间短，没有暴露问题。到了生产环境，数据量大了，查询慢了，锁的时间长了，问题就暴露了。压力测试一定要用真实的数据量，覆盖真实的场景。

6. 紧急处理要先恢复再排查 线上出故障的时候，第一要务是恢复服务，而不是排查根因。可以先回滚代码、重启服务、扩容，先让服务恢复正常，然后再慢慢排查根因。这次我一开始就陷入了排查，没有先做紧急处理，导致故障持续了比较长的时间，这是一个教训。

七、写在最后

线上出了个Bug，我排查了整整一夜。

从晚上九点到早上六点，九个小时，从最初的慌乱，到一步步深入，到最终找到原因并修复，这个过程虽然辛苦，但是收获很大。

每一次线上故障，都是一次成长的机会。它会暴露你系统的薄弱环节，暴露你知识的盲区，暴露你流程的不足。重要的不是避免故障，而是从故障中学习，让系统变得更健壮，让自己变得更专业。

现在，我们的系统增加了更多的监控和告警，代码审查也更加严格了，数据库操作也有了规范。我相信，类似的故障以后不会再发生了。

但是，我也知道，系统永远会有新的Bug，新的故障。作为程序员，我们能做的，就是不断学习，不断进步，在每一次故障中成长。

窗外，太阳已经升起来了。我站起身，伸了个懒腰，准备去睡一会儿。

新的一天，又开始了。