记一次 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 协议》,转载必须注明作者和本文链接
本帖由 Summer 于 1年前 加精
leo
《L01 基础入门》
我们将带你从零开发一个项目并部署到线上,本课程教授 Web 开发中专业、实用的技能,如 Git 工作流、Laravel Mix 前端工作流等。
《L04 微信小程序从零到发布》
从小程序个人账户申请开始,带你一步步进行开发一个微信小程序,直到提交微信控制台上线发布。
讨论数量: 15

使用的默认的Notification,刚开始我的群发使用的默认配置的队列,但人数一多,就产生超时问题了。于是,为群发通知是设置一个单独 redis-long-running 队列,设置PHP不限制最大执行时间,队列超时是 1 小时。现在解决了。
但总感觉有点问题。
问一下,你的群发的思路是如何设计的?按单位进行批次发送?

1年前 评论
leo

@努力做个技术男 我这边是一个推送就是一个异步任务,不存在超时问题

1年前 评论
Destiny

leo 的问题排查能力很强大,分析问题的思路很清晰。 :+1:

1年前 评论
nff93

我一直都用 https://github.com/zhuzhichao/ip-location-... 来解析IP的,不过作者的IP库更新不频繁

1年前 评论

すごい(si go i)
mark

1年前 评论

我想是不是可以通过自定义队列来解决呢?

1年前 评论
leo

@tegic 是的,可以根据优先级放到不同的队列里

1年前 评论

@nff93 推荐 https://github.com/lionsoul2014/ip2region 这个,用go封装一个web 服务,响应速度极快

1年前 评论

你这个问题我也遇到了,之前一直用淘宝的api解析ip地址,好像淘宝那边做了限制,批量发起api会有很大延迟,并且不返回结果。
之后去找了ipip.net的离线数据库,在本地解析,感觉还行。

1年前 评论

访问限制

为了保障服务正常运行,每个用户的访问频率需小于1qps。
1年前 评论
ALMAS

只用了一台服务器来执行队列处理器 意思是这个服务器只用来执行队列么?是同一个项目部署到多个服务器,在一个服务器上推送任务到队列,另一个服务器上执行处理麼?

1年前 评论
leo

@ALMAS 是的,这样可以避免因为有消耗资源的队列任务而影响到 Web 服务性能

1年前 评论
ALMAS

@leo 还有个问题想请教,执行队列处理的服务器上部署的是完整的项目代码还是只有只有处理队列逻辑的代码?

1年前 评论
leo

@ALMAS 完整的代码

1年前 评论

请勿发布不友善或者负能量的内容。与人为善,比聪明更重要!