likes
comments
collection
share

一个小小的时间bug，居然花了我3天3夜

作者站长头像
站长
· 阅读数 45

需求场景

先上一张功能结构图

一个小小的时间bug，居然花了我3天3夜

前一段时间，已经通过go脚本将设备数据（ini形式存储）采集到mongodb里面去。

然后用户提出了设备利用率的需求，也就是他们需要知道每台设备每天运行了多长时间，以方便借此了解设备的使用情况，避免设备资源的浪费。

解决思路

我觉得这很简单，于是我在mysql里创建了下面这张数据表，用来存储设备状态变化的每一笔记录，后面直接简称online表：

CREATE TABLE `zhai14_history_online` (
	`id` INT(10) UNSIGNED NOT NULL AUTO_INCREMENT,
	`device_id` VARCHAR(50) NULL DEFAULT NULL COMMENT 'device id' COLLATE 'utf8mb4_general_ci',
	`data_time` INT(10) NOT NULL DEFAULT '0' COMMENT '数据时间结点，采用INT型提高查询速度',
	`data_time_date` DATETIME NOT NULL DEFAULT CURRENT_TIMESTAMP,
	`value` INT(10) NOT NULL DEFAULT '0' COMMENT '时长（开机/关机）单位秒',
	`type` TINYINT(1) NOT NULL DEFAULT '1' COMMENT '1-开机（绿色） 0-关机（黄色） 3-offline（灰色） 4-异常中断（暗红色）',
	`is_stable` TINYINT(3) UNSIGNED NOT NULL DEFAULT '0' COMMENT '是否处于稳定期：1-是，0-否',
	`joint_data` VARCHAR(1000) NULL DEFAULT NULL COMMENT '节点采集数据，json格式存储' COLLATE 'utf8mb4_general_ci',
	`remark` VARCHAR(255) NULL DEFAULT NULL COMMENT '备注' COLLATE 'utf8mb4_general_ci',
	`status` TINYINT(3) UNSIGNED NOT NULL DEFAULT '1' COMMENT '0-删除 1-有效',
	`create_time` DATETIME NULL DEFAULT CURRENT_TIMESTAMP,
	`update_time` DATETIME NULL DEFAULT NULL ON UPDATE CURRENT_TIMESTAMP,
	PRIMARY KEY (`id`) USING BTREE,
	UNIQUE INDEX `uindex_history_online` (`device_id`, `data_time`) USING BTREE
)
COMMENT='设备开关机记录表'
COLLATE='utf8mb4_general_ci'
ENGINE=InnoDB
AUTO_INCREMENT=0
;

然后照着下面的思路，就开始敲代码了。

  1. 用2个redis无序集合将设备划分为两类：运行的和停机的。（后面又补充了离线和中断两种）                   一个小小的时间bug，居然花了我3天3夜

  2. 根据mongodb里设备最新状态，判断设备的状态是否有变化，然后再执行相对应的工作，具体可见下图所示： 一个小小的时间bug，居然花了我3天3夜

我开了一个每分钟执行1次的定时计划任务Monitor，于是胸有成竹地按照上面思路写了下面这一段代码：

if( ('run' == $statusText && $redis->sismember(Redis::KEY_SET_EQUIPMENT_RUN, $deviceId) )
    || ('run' != $statusText && $redis->sismember(Redis::KEY_SET_EQUIPMENT_STOP, $deviceId)) ){
    //状态保持不变，更新持续时长
    $newestRecord = $serviceOnline->getDeviceNewestRecord($deviceId);
    $newestRecord['update_time'] = DateUtil::getCurrentDatetime();
    $newestRecord['value'] = strtotime($newestRecord['update_time']) - $newestRecord['data_time'];
    if(1 == $type && $newestRecord['value'] > intval($bootMinute)*60){
        $newestRecord['is_stable'] = 1;
    }
    $serviceOnline->update($newestRecord);
}else {
    ...
}

结果统计设备每天的运行时长，出现超过24小时的情况。 一个小小的时间bug，居然花了我3天3夜

经过检查，发现上面程序疏漏之处在此处： 结合上图来说明，设备前一天早上7点启动，一直运行到第二天早上8点才停止，我的定时计划任务监测到设备状态有变化，于是我就在online表中新增一笔记录，同时我会更新online表中该设备的上一笔记录，也就是头天早上7点这笔记录，更新持续时长为“2023-03-02 08:00:00 - 2023-03-01 07:18:52”，一共25个小时，从而导致前一天设备运行时长多统计了8小时。

于是我就另外加了一个定时计划任务Daily，每天给设备插入第一笔数据，daily init作为标志。

public function addCurrentDayInitData()
{
    $serviceEquipmentLems = new SysEquipmentLemsService();
    $list = $serviceEquipmentLems->getFilterEquipmentList(['elems.is_collect=1']);
    $arrDeviceId = array_column($list, 'device_id');
    $service = new EquipmentService();
    $listDeviceInfo = $service->getMultiDeviceCurrentInfo($arrDeviceId);
    $currentInitTime = DateUtil::getCurrentDatetime("Y-m-d 00:00:01");
    $currentDayDate  = DateUtil::getCurrentDatetime("Y-m-d");
    $serviceOnline = new SysHistoryOnlineService();
    foreach($listDeviceInfo as $item) {
        $type = $service::WORK_STATUS[$item['status_run_text']] ?? 0;
        $deviceId = $item['device_id'];
        $isExist = $serviceOnline->isExistDayData($deviceId, $currentDayDate);
        if(!$isExist){
            $rowData = array(
                'device_id' => $deviceId,
                'data_time' => strtotime($currentInitTime),
                'data_time_date' => $currentInitTime,
                'value' => 0,
                'type' => $type,
                'remark' => 'daily init'
            );
            $this->add($rowData);
        }
    }
}

同时调整程序如下：

//状态保持不变，更新持续时长
if( ('run' == $statusText && $redis->sismember(Redis::KEY_SET_EQUIPMENT_RUN, $deviceId) )
    || ('run' != $statusText && $redis->sismember(Redis::KEY_SET_EQUIPMENT_STOP, $deviceId)) ){
    
    //如果当天没有生成第一笔数据，此处就会导致抓的数据是前一天的，从而影响到历史统计，所以一定要确保有生成第一笔数据
    $newestRecord = $serviceOnline->getDeviceNewestRecord($deviceId); 
    $newestRecord['update_time'] = DateUtil::getCurrentDatetime();
    if(DateUtil::getCustomDatetime($newestRecord['update_time'], "Y-m-d") !=  DateUtil::getCustomDatetime($newestRecord['data_time'], "Y-m-d")){
        //不是同一天，说明当天第一笔数据没有生成，将其补上，然后结束
        $rowData = array(
            'device_id' => $deviceId,
            'data_time' => strtotime($newestRecord['update_time']),
            'data_time_date' => $newestRecord['update_time'],
            'value' => 0,
            'type' => $type,  //1-开机 0-关机,
            'remark' => 'init leave-out fix'  //生成第一笔数据
        );
        $serviceOnline->add($rowData);
        return ;
    }
    $newestRecord['value'] = strtotime($newestRecord['update_time']) - $newestRecord['data_time'];
    if(1 == $type && $newestRecord['value'] > intval($bootMinute)*60){
        $newestRecord['is_stable'] = 1;
    }
    $serviceOnline->update($newestRecord);
}else {
    ...
}

万一计划任务Daily遗漏了某些设备，计划任务Monitor还可以将设备当天第一笔数据补上。 这样就杜绝了上面统计超时的问题了。

怎么样，是不是很棒？ 就这，能坑我3天3夜？ 那当然不是啦。

接下来才是我真正想跟大家分享的。

上面程序运行了一阵子，用户又发现了一个统计超时的设备。 经过数据检查，发现这时候只是有几台设备是有问题的，大多数设备是正常的。 而这些有问题的设备，都奇怪的有个共同点：

当天第一笔数据的时间都不是00:00:01，有的甚至都过了2个多小时，例如02:10:33这样子，数据备注就是代码中的“init leave-out fix”。

这一下子就把我整懵了。

如果说定时计划任务Daily本身有问题呢，大部分设备却又是正常的。 如果说程序出问题了呢，我白天加日志调试，if语句判断也没有问题。

正是因为对问题没有任何思路，瞎鼓捣了好久。

最后实在没办法，就把程序中所有变量数据全部写入日志。

第二天分析凌晨的日志数据，才最终发现了问题所在。只可惜在我选择这种最原始的调试方法之前，我一直是期待着自己能通过自己大脑模拟程序，来缕出程序漏洞，以至于浪费了很多时间。

在我揭晓原因之前，大家可以先在这里停下来，思考一下，你们觉得问题会是出在哪里呢？

bug原因

我一直没能找出自己程序的漏洞，谁能想到，那是因为我的程序本来就没有逻辑漏洞。

问题是出在数据上：采集数据的时间。

开篇结构图就跟大家分享了，我是在用户工厂里每台设备电脑部署了go脚本，然后把采集数据写到mongodb里去。mongodb不像mysql能够自动填充服务器时间戳，所以我们采集数据的时间，都是go脚本所在设备电脑的时间。

用户那边大部分设备电脑时间都跟北京时间一致，只有很少的设备电脑时间偏差较大，以至于下面的if语句判断会出问题：

if(DateUtil::getCustomDatetime($newestRecord['update_time'], "Y-m-d") 
    !=  DateUtil::getCustomDatetime($newestRecord['data_time'], "Y-m-d")){

(update_time是online表中数据更新时间, data_time是设备电脑的时间)

这也是为何我白天上班，怎么也看不出上面if语句的问题的原因。

到这里，再回看之前的一切现象，就都可以做出合理的解释了。剩下的，就交给大家自己思考了，这里就不赘述了。

最终解决

if语句条件换成如下：

if(empty($newestRecord) 
    || (DateUtil::getCustomDatetime($currentTime, "Y-m-d") 
         !=  DateUtil::getCustomDatetime($newestRecord['create_time'], "Y-m-d")) ){

拿定时计划任务Job执行的当前时间跟online表里创建数据时间做比较（定时计划任务和mysql都在同一台服务器里运行的）

另外，之前更新设备状态持续时长也有问题：

$newestRecord['value'] = strtotime($newestRecord['update_time']) - $newestRecord['data_time'];

其中data_time是设备电脑的时间，这个时间一旦不准确，上面统计就会偏多或偏少。

修复如下：

$newestRecord['value'] = strtotime($item['time']) - $newestRecord['data_time'];

两个时间都采用设备电脑的时间，就算时间不准，也不影响状态持续时长的计算。

心得体会

所以，关于我们的程序逻辑对不对，我们也需要学会去质疑，数据是否也会超出意料之外呢

转载自:https://juejin.cn/post/7239282069750235193
评论
请登录