一个小小的时间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
;
然后照着下面的思路,就开始敲代码了。
-
用2个redis无序集合将设备划分为两类:运行的和停机的。(后面又补充了离线和中断两种)
-
根据mongodb里设备最新状态,判断设备的状态是否有变化,然后再执行相对应的工作,具体可见下图所示:
我开了一个每分钟执行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小时的情况。
经过检查,发现上面程序疏漏之处在此处: 结合上图来说明,设备前一天早上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