eleven26
0%

记一次一言难尽的优化

Posted on Edited on

本来上周想写的，但是上周到现在一直在做一些优化的事情，所以一直拖到了现在。

标题也写了，这真的是一次 “一言难尽” 的优化，因为本来以为是一个非常高大上的技术问题，以为需要做很多很多优化才能解决的问题，但背后原因令人咋舌。

技术栈

开始之前，有必要说一下项目用到的技术栈：

  • MySQL
  • MongoDB
  • RabbitMQ
  • laravel-s（基于 swoole 开发的一个框架）
  • redis

背景

从项目上线几年以来，偶尔会出现一种情况，php worker 进程（也就是处理 http 请求的那些进程）全部被占用，导致用户所有后续的请求一直处于 pending 的状态，这个时候从用户的角度来看，其实就是服务器宕机了。

但是很诡异的是，虽然进程全部被占满了，但是服务器的 CPU、内存、磁盘，数据库的 CPU、内存、磁盘都处于一个相对正常的状态，甚至可以说毫无波澜。就是明显不是资源不足导致的请求无法被及时处理。

之前一直的应对方法：遇到这种情况的时候，很多次都是通过重启进程来解决。有时候重启进程之后，问题就不再出现了。有时候需要经历前前后后好几次的重启问题才不再出现。

然后每经历一次，都能找到可以优化的一个或者几个接口，所以 “宕机” 的情况多了之后，接口也逐渐优化过不少了。

上周以前的优化

从一开始到上周以前，基于出现的慢请求，团队成员对应用也做了很多的优化。比如：

  • 加了两台应用的服务器，然后 nginx 负载均衡
  • mongo 分库分表（也加了 2 台服务器）
  • 导入导出的优化
  • 使用 elasticsearch 来搜索
  • 优化了很多其他的慢请求对应的接口，当然是实实在在的优化，并不是自己感性的感觉

优化的结果： 优化到最后，已经没有非常明显的慢请求了。但是结果呢？还是偶尔来一次 “宕机”，但我们能看到的慢请求里面，去看代码好像都已经优化得没有办法再优化了。所以这个是最诡异的

新的发现： 因为常规的 MySQL、MongoDB 都没有慢查询，后面联想到了会不会是推队列导致的，因为项目里面也用到了 RabbitMQ。然后在代码里面加上了对推队列耗时的监测，最后发现偶尔的情况下，统计到推队列的时间会长达十几二十秒。

上周的优化

基于这一新的发现，对需要推队列的请求做了一些针对性优化，比如原来是通过 for 循环做了一些推队列的操作，然后针对这些情况，改成了批量去推，然后在消息消费的时候再去循环处理。

优化之后，还是偶尔会有 “宕机” 的情况。后面怀疑是另外一个系统请求频繁导致的，因为这个系统的请求都需要推队列，因此怀疑是 RabbitMQ 的那台机无法承受得住这么高的请求量。（但在产生这个怀疑的时候，MQ 所在服务器在 “宕机” 的时候资源其实也是处于正常状态。）但因为 “宕机” 的时候刚好推队列也慢了，所以有这样的怀疑。

针对推消息到队列很慢的情况，上周又做了一些优化，具体来说就是将处理另外一个系统的 php 进程跟 RabbitMQ 服务器隔离开来。

上周优化的结果

将另一个系统的请求处理的进程跟 MQ 服务器隔离开了之后，第二天，“宕机” 的情况还是出现了。

万万没想到，本以为能做的都做了，总不至于还会 “宕机” 吧，但事实就是这样。

想起了之前在 qa 环境中，会出现建立到 MQ 的连接的时候耗时过长的情况，因此在生产环境中，在建立 MySQL、MongoDB、RabbitMQ 连接的地方都加上了埋点，监测一下是否有建立连接耗时过长的情况。

结果：并没有出现过一次连接耗时过长的情况，毕竟本来都是走的内网，平时 ping 一下大概 <= 1ms。

发现问题

上面都没有提到的一点是 redis，因为 redis 这个东西个人是对它的性能一点也不怀疑的，所以之前虽然即使想到了会不会是 redis 导致的时候，又马上否定自己的想法，不可能，绝对不可能。

但是那一天看到一个请求，一段代码里面本来没有做什么特别的操作，但是耗时很长。但是里面没有 MySQL、MongoDB 慢查询，没有推队列的操作，但是有 redis 的操作，但是那个操作也不是什么需要耗时很长的操作，就是一个 set nx 的操作。讲道理应该是非常快的。

由于没有其他可以怀疑的地方了，然后给这个 set nx 的操作加上耗时监测。第二天起来的时候，先去看了看慢请求日志，真的发现有一次 set nx 耗时长达 16s，到这个时候基本可以肯定是 redis 导致的问题了。

然后联想到好像平时用的数据库都有慢查询日志，想了想 redis 是否也有慢查询日志，搜索一番，真的有。然后去服务器上执行一下 slowlog，发现服务器 “宕机” 的时间点有很多 keys xx* 的操作，所以到此为止，其实问题基本上等于解决了，接下来只需要去找到对应的代码，改掉 keys * 的操作就行了。因为 keys * 是会阻塞整个 redis 线程的，导致其他 redis 操作完全无法进行。所以也就出现了 set nx 也需要十几秒的情况。

至此，几年以来，偶尔来一次的 “宕机” 总算是找到根本原因了。而这么久才找到仅因为对 redis 太过于相信了，总是感性地认为 redis 太过于强劲，完全不需要管它的性能问题。但事实证明，还是需要对外部依赖长点心，要不然偶尔恶心你一次。

问题代码

从 slowlog 里面得到的一些命令，搜索代码之后，发现有如下几行代码，这是将近 4 年前的代码：

1
2
3
4
5
6
7
8
9
10
11
// function A
$keys = array_merge(
    // 每个 keys * 操作 600ms
    app('redis')->keys($this->getKeyName($companyId, $this->skuKey, $skuId) . '*'),
    app('redis')->keys($this->getKeyName($companyId, $this->giftKey, $skuId) . '*'),
    app('redis')->keys($this->getKeyName($companyId, $this->skuGiftKey, $skuId) . '*')
);

if (count($keys) > 0) {
    app('redis')->del($keys);
}

我们可以发现，这里做了 keys * 操作，而且还做了三次。

然后去看看调用这个函数的地方，一个 for 循环来调用这个函数：

1
2
3
4
5
// function B
foreach ($skuIds as $skuId) {
    // 一次调用 1.8s
    $this->cleanCacheBySkuId($companyId, $skuId);
}
1
2
// 接口 c
$service->b();

然后调用 B 函数的地方是一个接口（我们称作 C 吧），突然想起了之前 php 进程被占满的时候，都会显示几个或者多个 C 接口正在处理。但是之前看过这个接口，好像也没有很多复杂的操作，只是 for 循环做了一些数据库的操作，但是一般来说 for 循环的次数比较少。所以就一直不太在意。

keys * 是如何影响到全平台的？

  • 很久以前代码里面加入了一个记录活跃用户的 redis 操作，所以每次请求都会需要 redis，所以一旦 redis 阻塞了，所有的其他请求都得等待了
  • 队列使用了 horizon，而这个 horizon 里面也是有很多 redis 操作的，很多状态信息都是通过 redis 记录的。因此 redis 阻塞也会导致推队列的操作耗时过长（准确来说并不是推队列耗时过长，只是推队列的时候附带的 redis 操作耗时过长，所以上面以为的推队列耗时过长的怀疑是错误的）。

“宕机” 是怎么发生的

看过了 redis 的慢日志之后，发现一次 keys * 的操作要 600ms，也就是说一次 for 循环需要 1.8s 以上，如果参数传了 10 个，那就是 18s 起步了。（也就是这个时候开始，服务器已经开始卡顿了，又还没有完全 “宕机”）。然后这个时候肯定绝大多数用户应该等不及了，接口居然没有响应了，这谁能忍。然后大家开始刷新，不刷不要紧，这一刷就导致更多请求在等待处理了，但是这些请求基本上都需要在 18s 以后才能正常处理。（所以有时候会出现一种情况，客户用着用着反馈卡顿，但是过了一会等开发去看的时候，又不卡了）

这个时候绝大多数人的请求影响不会很大，但是还有一个人，那就是等待 C 接口返回的人。他也等不及了，然后又发起了一次新的请求，这下好了，大家的等待时间要 +18s 了。em... 那就大家一起等 36s 吧，停下来喝杯茶就好了。但是等待 C 接口返回的人发起的这个新的请求又等了好久，实在是忍不住了，再动起了鼠标，再发了几次请求。

em... 这下可好了，完完全全 “宕机” 了，救火的人出现了。拿起键盘一把梭，重启服务器的 php 进程，重启之后，发起 C 接口请求的人正在喝茶，这个时候其他人的请求得以正常处理了一会，让大家稍微喘了口气。

“宕机” 是如何恢复的

但是好景不长，那个等待 C 接口返回的人，杯里的茶喝完了，回到浏览器看了一眼，但是发现服务器返回了错误。这下彻底坐不住了，键盘一摔，拿起鼠标又继续之前的操作，又来了几次 C 接口请求，然后服务器又开始 “宕机”，再次重启。如此来回几次之后，那个人最后发现自己的请求终于生效了，也就不再发起新的请求了。

至此，“宕机” 得以暂时的恢复了。直到下一个请求 C 接口的人出现...

解决问题

打开问题代码所在源文件之后，删除了一些几年前写的不再使用的代码之后。发现上面的 B 函数也是不再需要的了，也就是说 A 和 B 函数都是不再需要的了。

所以，解决问题的方法极其简单，将 B 函数的调用去掉就解决了。有点难以置信困扰这么久的就这么简单的被解决了，之前一度以为要做很多很多优化才能不会再出现类似的 “宕机” 的问题，但现在看来似乎并不是这样。

去掉这函数调用之后，服务器算是真正的稳定下来了，持续了几年的间歇性 “宕机” 问题至此总算得到解决。

启示

  • 那段代码是将近四年前的，然后后面有人修改过之后，其实那个函数不需要再调用，但是调用并没有去除。所以，是否可以考虑一下，修改过后，将那些不再需要的代码删除。
  • 几年以来，对 php 的进程的监控做了很多完善，到后面都可以看到当前正在处理什么请求，正在处理的请求 MySQL 操作花费了多少时间、MongoDB 操作花了多少时间，但是 redis 被完完全全地忽略了。事实证明，应该对所有的外部依赖（简单来说就是一切 io 操作）都做相应的监测，如果能监测当前在什么操作上阻塞那就最好不过了。因为排除了这些网络、磁盘的操作之外，剩余的问题就没那么难发现了，无非就是 CPU、内存。
  • 当问题出现的时候，如果找不到很明显的原因，可以逐一进行排查，不应该对某些外部依赖太过于信任，也许这些外部的依赖本身没有问题，但是使用不当就会造成问题。
  • em... 不要在线上环境使用 keys *