likes
comments
collection
share

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

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

需求场景

先上一张功能结构图

一个小小的时间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
评论
请登录