边界判断缺失

作者简介：大家好，我是smart哥，前中兴通讯、美团架构师，现某互联网公司CTO

联系qq：184480602，加我进群，大家一起学习，一起进步，一起对抗互联网寒冬

学习必须往深处挖，挖的越深，基础越扎实！

阶段1、深入多线程

阶段2、深入多线程设计模式

阶段3、深入juc源码解析

阶段4、深入jdk其余源码解析

阶段5、深入jvm源码解析

事故场景

我们在做需求开发时，经常会遇到一些边界条件的判断：

查询身高大于180cm、年龄大于18岁的学生
筛选出公司P7以上的程序员

大多数时候，我们只需要把产品语言转化为程序语言即可：

SELECT * FROM t_student WHERE height>180 and age>18;
SELECT * FROM t_employee WHERE level>=7;

但产品语言与程序语言并不完全等同，直接翻译有时会引发意想不到的BUG。

假设现在有一个需求：

下单24小时以后，为用户发放奖励

一般来说，我们可以采用定时任务完成这个需求，具体做法是：

用户下单后，在order_task表插入一条记录（为了方便记忆，type和status都用字符串代替）：

# 一张任务表不止一种类型的任务，所以用type区分，和当前需求关系不大
INSERT INTO order_task (order_id, task_type, task_status, gmt_create, gmt_modify) 
VALUES(10000001, 'complete_order_prize', 'wait', 'xxxx-xx-xx', 'xxxx-xx-xx');

定时任务扫描需要发放下单奖励的任务、为用户发放奖励、更新任务状态：

# 伪代码 86400=24*60*60
SELECT * FROM order_task WHERE order_type='complete_order_prize' and task_status='wait' and gmt_create < now-86400;

注意时间条件，由于产品需求是下单24小时后才发放奖励，所以要满足条件：gmt_create < now-86400。

正常来说，上面的做法是没有问题的。但是，昨天产品找我说，用户反馈自己一个月以前的3笔订单奖励至今未发放。

这位产品很优秀，比较懂开发，甚至自己会写SQL，他的第一反应是定时任务挂了。

好了，现在问题出现了，如果是你，打算怎么开始排查呢？

解决方案

先介绍一下背景，我们公司由于业务调整，上面业务所在的平台已经很久没迭代，我抓包看了下，发现底层逻辑是PHP写的。于是找到对应的工程及代码，确认近期确实没有人更改过代码逻辑。

紧接着，我打开公司的定时任务平台，查看了该任务过去一个月的执行日志，发现全都执行失败了。

定时任务是否执行成功，其实有两个指标：

调度成功
执行成功

调度成功只能说明定时任务没问题，机器也没挂，但具体本次操作是否执行完毕，需要看执行结果。

从上图可以看到，定时任务每五分钟执行一次，可以调度成功（尽管也有调度失败的），但执行结果无一例外都是失败的。

这说明定时任务本身是好的，只是执行过程出了问题。查看定时任务的执行策略，我发现采用的是丢弃后续调度：

这是一种什么策略呢？举个例子，假设定时任务每隔5分钟执行一次，而上一个任务A本次执行超时了（超过5分钟还在执行），当下一个任务B启动时结果发现上一个任务还在进行中，那么任务B就会被丢弃，等待下次任务C执行。

那么，现在就有个矛盾摆在我们面前：

定时任务是好的，但执行过程出问题了
然而我们排查后，确定代码近期没有变更

代码没动过，定时任务也没挂，然而却没有达到预期。一个线上的功能好端端的突然崩了，无非几点原因：

用户行为改变，恰好命中之前没测到的bug

其他人发布新代码，对当前功能产生影响
数据出问题了

订单奖励属于定时任务，不存在用户行为，这个原因基本可以排除。只有第二、第三个原因，其实归根到底都是数据问题，A功能要想影响B功能，一定是两者有共同的数据，也就是有共同的表。但不论哪种原因，我们可以得出结论：一个运行好几年的定时任务跑着跑着突然崩了，大概率是数据出问题了。

但我得出这个结论，却是在2小时后。一方面，恰好这个功能的PHP代码以及远程调用的Java服务都没有打印日志，对问题排查造成了很大的困难。由于系统已经基本停止维护，为了找到当前工程的日志，花了将近1小时。另一方面，电商系统太大了，只能上预发环境测试。等给工程打上日志、重新发布，已经过去10分钟。希望大家吸取教训，实际开发时在必要的地方打上日志，方便日后排查问题。

那么，最终是什么原因导致定时任务不执行了呢？

下面是一段PHP代码，做了简化处理，具体细节不用理解：

/*** 定时任务脚本 处理签到下单任务奖励金的实质发放* @return bool*/
public function finishSignOrderTask() {load_module_model('xxx');$start_time = time() - 86400; // 24小时以后的订单// 查出符合条件的最老的一条的记录$oldest_record = $this->CI->xxx_sign_task->getWaitFinishTask(self::TASK_ID_ORDER_TASK, $start_time, \Xxx_sign_task::TASK_STATUS_COMPLETE, 'asc');if (empty($oldest_record)) {return TRUE;}$start = $oldest_record->id;// 查出符合条件最新的一条记录$end_id = $this->CI->xxx_sign_task->getWaitFinishTask(self::TASK_ID_ORDER_TASK, $start_time, \Xxx_sign_task::TASK_STATUS_COMPLETE, 'desc')->id;// 最新~最老记录之间都是需要执行的订单奖励，具体做法是 每次从中捞出100条执行（start_id + 100），直到退出（start_id+100>end_id）$page_size = 100;$xxxSignAwardService = XxxSignAwardService::getInstance();while (TRUE) {$where = ['id >= ' . $start,'id < ' . ($start + $page_size),'task_id = ' . self::TASK_ID_ORDER_TASK,'task_status < ' . \Xxx_sign_task::TASK_STATUS_FINISH,'gmt_begin < ' . $start_time,];$records = $this->CI->xxx_sign_task->get_by_where($where, '*', 1, $page_size);if (!empty($records)) {foreach ($records as $record) {// 再次校验订单状态$order = $this->CI->xxx_order->get_by_oid($record->biz_value);if (empty($order)) {$this->logger->error("oid_deal_not_found", [$record]);// 订单不存在 关闭任务$this->updateTaskStatus(FALSE, $record);continue;}// 发放奖励...}}if ($start > $end_id) {break;}$start += $page_size;}return TRUE;
}

我在观察表数据时，发现了一个现象：最早一条处理失败的奖励任务竟然是2020年12月的，它的状态仍旧是task_status='wait'！

这会产生一个什么现象呢？(划线表示已执行)

1000000 2020-12-27 任务1（start）
1000001 2020-12-27 任务2
1000002 2020-xx-xx 任务...
...
2000001 2021-04-27 任务N
...（后续新的任务）
...
2100001 2021-06-04 任务Z（end）

由于上面PHP代码的做法是：查出start~end之间所有数据，并从start开始每次查询100条数据。随着时间越来越长，到了2021-04-27时，任务1和任务N之间id号已经差了100w，即使除以pageSize=100，也需要循环查1w次，而这1w次SQL查询是查不到数据的（因为之前被处理过了）！

换句话说，每次定时任务开始，虽然目标是执行2021-04-27 ~ 2021-06-04之间的奖励任务，但却不得从2020-12-27的数据开始，以id+100的形式查询1w次后，才能到达任务N。

注意，while并不是空转，而是真的去查数据库了！空转1w次根本不算什么，但循环查询数据库1w次是不可接受的，即使分页查询一次200ms，整个过程也要耗时2000s，要30多分钟，而定时任务频率为5分钟。然而耗时长并不是任务失败的主要原因，最关键的是单任务循环次数过多导致日志输出及内存占用增加，最终每次还没执行到需要的数据，PHP自己就先挂了。

解决方法是，查询奖励任务时，加一个边界判断：下单24小时后，且最近3个月内的订单。

至于为什么2020年的那个任务一直没被执行掉，是因为它的任务流水不知为何被删除了（或者当初插入失败了），而Java远程服务会做流水校验，如果流水为空则抛异常跳过本次执行，所以2020年的那个数据躲过了一轮又一轮的定时任务，最终出现在2021年的某一天，突然抡起一锤子砸向了俺，尽管这个需求不是俺做的...

坑啊！！

之后隔天观察一下，发现任务已经正常了：