边界判断缺失

发布时间:2023年12月28日

作者简介:大家好,我是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年的某一天,突然抡起一锤子砸向了俺,尽管这个需求不是俺做的...

坑啊!!

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

个人建议

  • 注意边界判断,不要做产品语言的翻译机,要从开发的角度考虑设计是否合理
  • 养成打日志的习惯有利于问题排查

文章来源:https://blog.csdn.net/smart_an/article/details/135259870
本文来自互联网用户投稿,该文观点仅代表作者本人,不代表本站立场。本站仅提供信息存储空间服务,不拥有所有权,不承担相关法律责任。