记一次 Laravel 定时任务不按时执行的 Bug 追查记录及修复方案

背景

我司的某个 Laravel 项目，通过 Laravel 的定时任务模块在每天晚上 8 点钟群发消息给用户，之前一直运行良好。前天发现用户收到通知的时间大约在晚上 10 点多，当时以为只是服务器负载比较高而导致的发送较慢，就没有太在意，然而昨天的消息居然延迟到了次日凌晨一点多才送达，而且是所有用户都是在那个时间点收到的，而不是想象中从晚上 8 点开始逐渐收到。

山穷水尽

首先看出问题的定时任务的执行逻辑：

1. 从数据库中查询出所有符合条件的用户
2. 逐个调用 Laravel 的 Notification 模块进行消息通知，对应的 Notification 类开启了 ShouldQueue，因此真正的消息推送会由给队列来处理。

由于我们这个项目才刚启动不久，用户量在万级别，因此不太可能是第一步出问题，通过查看相对应的 SQL 执行记录，耗时在数百毫秒，因此可以排除步骤 1。

接下来看步骤 2，由于定时任务本身不执行具体的发送消息动作，只是把任务序列化之后存储到 Redis，这个步骤的效率完全取决于 Redis 服务器的吞吐量，于是查看晚上 8 点到次日凌晨 1 点 Redis 服务器的负载，发现都不高，因此可以排除是因为 Redis 服务器负载过高而导致的问题。

既然定时任务本身没有问题，那就开始排查具体执行推送任务的队列处理器。

由于这个项目业务量还不大，只用了一台服务器来执行队列处理器，使用 Supervisor 启动了 4 个队列处理器，启动命令是

php artisan queue:work --sleep=3 --tries=3 --timeout=3600 --memory=512

查看该服务器在晚上 8 点到次日凌晨 1 点的负载，也属于正常水平，不像是因为其他队列任务占用了队列处理器资源而导致推送队列没有被及时处理。

这下有点懵逼，感觉一切指标都正常，但就是出毛病了。

柳暗花明

在各项指标没有问题的情况下，那只好通过日志来尝试复原当时服务器上发生的事情。

根据之前的分析，我先假定在晚上 8 点的时候，定时任务已经完成了自己的工作，将需要推送的消息存入了 Redis，所以我查看了队列处理器的输出日志，这个是通过 Supervisor 的配置实现的，在 Supervisor 的配置中通过

stdout_logfile=/project_path/storage/logs/worker.log

可以将队列的输出重定向到这个日志文件。

使用 less 命令查看这个日志文件，并跳转到晚上 8 点左右的日志，里面的内容类似：

[2018-08-18 20:06:54][ZyW9eRuMLB5goQyCO2EKv3hBkb77Ong0] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:07:05][pXcIaQ93sLx5XH9NJYpbb3CDqVtMhT40] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:07:10][IFedJb6OZwUaV5dlhFodoXk56SNk7RLE] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:07:14][wyK42WyxaF5DR7J4O61h4p7Pud85VK2g] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:07:15][FL7HERldD93pRYdrwG0xUMNo1TFpWpuI] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:08:11][FL7HERldD93pRYdrwG0xUMNo1TFpWpuI] Processed:  App\Jobs\ParseUserIP
[2018-08-18 20:08:11][EIUznJysjWbOt5MlzmMJVsan2nnD9XgK] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:08:51][EIUznJysjWbOt5MlzmMJVsan2nnD9XgK] Processed:  App\Jobs\ParseUserIP
[2018-08-18 20:08:51][ZTlzghKI7vPTIcNodu0yMwSDTcK5PsJi] Processing: App\Jobs\ParseUserIP
[2018-08-18 20:09:04][ZTlzghKI7vPTIcNodu0yMwSDTcK5PsJi] Processed:  App\Jobs\ParseUserIP

当队列处理器开始处理某个任务时就会输出一条 Processing，当执行完毕时会输出 Processed，当有很多个任务在同时执行时，我们可以根据中括号里面的那个字符串（即任务 ID）来区别不同的任务。

仔细观察上面的日志，可以发现 ParseUserIP 这个任务耗时比较长，比如 ID 为 FL7HERldD93pRYdrwG0xUMNo1TFpWpuI 的任务，开始执行的时间是 20:07:15，而结束时间是 20:08:11，花了将近一分钟的时间。持续往下翻可以发现有大量的 ParseUserIP 任务出现长耗时的情况，而且一直持续，耗时 1 分钟以上的不在少数。

于是我查看了一下这个任务的代码，是调用淘宝的 IP 接口来查询用户 IP 归属地：

$ret = (new \GuzzleHttp\Client())->get('http://ip.taobao.com/service/getIpInfo.php?'.http_build_query(['ip' => $ip]));

之前这个接口都是秒回，现在这种情况应该是淘宝的这个接口本身出现了不稳定的情况。

这下有点明白问题出现在哪里了，由于每次用户登录都会触发 ParseUserIP 这个任务，所以系统里一直有大量的 ParseUserIP 任务待处理，在淘宝接口没有出现不稳定之前，这些任务几乎都是瞬间完成，因此一切正常。

而当淘宝接口开始不稳定，返回数据的时间从秒级变成分钟级，ParseUserIP 任务就开始大量积压，而 Laravel 的队列处理器是按照入队列的时间逐个去处理异步任务的，因此即使我们在晚上 8 点就将推送任务存入 Redis，也需要等待队列处理将之前积压的 ParseUserIP 任务全部完成才会开始被处理。

调用 Http 接口不会大量占用 CPU 和内存资源，这也解释了为什么服务器负载不高。

解决方案

找到问题之后，解决起来就很简单了：

1. 调用淘宝接口时设定一个超时时间，比如 3 秒；
2. 新增本地 IP 解析逻辑，当通过淘宝接口解析失败时使用本地解析；
3. 修改 Supervisor 的配置，将 4 个队列处理器调整为 8 个；
4. 排查所有涉及调用 Http 接口的代码，强制加上超时时间。

本作品采用《CC 协议》，转载必须注明作者和本文链接