增加日志打印执行时间

src/main/java/com/persagy/service/impl/AlarmHandleServiceImpl.java

@@ -26,6 +26,7 @@ import org.quartz.JobDataMap;
 import org.springframework.beans.factory.annotation.Autowired;
 import org.springframework.beans.factory.annotation.Value;
 import org.springframework.stereotype.Service;
+import org.springframework.util.StopWatch;
 
 import java.time.LocalDate;
 import java.time.LocalDateTime;
@@ -89,8 +90,11 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
         }
 
         log.info("接收到采集值：[{}]", msg);
+        StopWatch stopWatch = new StopWatch("handleIotMsg");
+        stopWatch.start("validateIotMsg");
         // 校验采集值
         boolean validateIotMsgResult = validateIotMsg(msg);
+        stopWatch.stop();
         if (!validateIotMsgResult) {
             log.error("采集值校验未通过");
             return;
@@ -101,6 +105,7 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
         // 每一条iot数据应该包含4个分号
         int groupCount = 4;
         int dataCounts = split.length / groupCount;
+        stopWatch.start("for dataCounts");
         for (int i = 0; i < dataCounts; i++) {
             int startIndex = i * groupCount;
             String dataTime = split[startIndex];
@@ -113,6 +118,8 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
                 handleIotData(dataTime, meterId, funcId, value);
             }
         }
+        stopWatch.stop();
+        log.info(stopWatch.prettyPrint());
     }
 
 //    public static void main(String[] args) throws Exception {
@@ -135,10 +142,12 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
      * @version: V1.0
      */
     private void handleIotData(String dataTime, String meterId, String funcIdStr, String valueStr) throws Exception {
+        StopWatch stopWatch = new StopWatch("handleIotData");
         /* 如果iot数据为一组数据，先更新缓存中这组iot数据值，然后将这一组iot数据拆分为一条条iot数据处理 */
         String funcIdSeparator = ",";
         String[] funcIdArray = funcIdStr.split(funcIdSeparator);
         String[] values = valueStr.split(funcIdSeparator);
+        stopWatch.start("currentDataCache.putCurrentData");
         // 更新缓存中的设备信息点当前采集值
         for (int i = 0; i < funcIdArray.length; i++) {
             // 如果有对应的报警定义
@@ -148,6 +157,7 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
                 log.info("未获取到对应的报警定义, meterId:{}, funcId:{}", meterId, funcIdArray[i]);
             }
         }
+        stopWatch.stop();
 
 //        // 将一组数据拆分为单条处理
 //        for (String funcId : funcIdArray) {
@@ -159,11 +169,14 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
 //        }
         // 因为所有功能点的数据都被缓存了，所以这里只处理一个功能点即可
         String funcId = funcIdArray[0];
+        stopWatch.start("handleSingleIotData");
         if (alarmInfoCache.hasKey(meterId, funcId)) {
             handleSingleIotData(dataTime, meterId, funcId);
         } else {
             log.info("未获取到对应的报警定义, meterId:{}, funcId:{}", meterId, funcId);
         }
+        stopWatch.stop();
+        log.info(stopWatch.prettyPrint());
 
     }
 
@@ -180,21 +193,26 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
      * @version: V1.0
      */
     private void handleSingleIotData(String dataTime, String meterId, String funcId) throws Exception {
+        StopWatch stopWatch = new StopWatch("handleSingleIotData");
         // 获取和采集值相关的报警定义
+        stopWatch.start("getAlarmDefinitionsByMeterFuncId");
         List<AlarmDefine> alarmDefines = alarmInfoCache.getAlarmDefinitionsByMeterFuncId(meterId, funcId);
+        stopWatch.stop();
         for (AlarmDefine alarmDefine : alarmDefines) {
+            StopWatch stopWatch1 = new StopWatch("for alarmDefines");
+            stopWatch1.start("infoCodesFullFill");
             Condition condition = alarmDefine.getCondition();
             String defineId = AlarmInfoCache.getAlarmDefineId(alarmDefine);
             log.info("defineId: [{}]", defineId);
-
             // 判断报警定义所包含的信息点在缓存中是否都有值
             List<JSONObject> infoCodes = condition.getInfoCodes();
             boolean infoCodesFullFill = infoCodes.stream().allMatch(
                     p -> currentDataCache.hasKey(p.getString("meterId"), p.getString("funcId"))
             );
-
+            stopWatch1.stop();
             //报警定义的所有信息点都有采集数值，具备判断条件
             if (infoCodesFullFill) {
+                stopWatch1.start("triggerResult endResult");
                 // 解析触发和恢复条件
                 String trigger = condition.getTrigger();
                 Expression triggerExp = AviatorEvaluator.compile(trigger, true);
@@ -229,6 +247,8 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
                 if (triggerResult && endResult) {
                     log.error("报警触发条件和报警恢复条件同时满足，请检查，报警定义详情【{}】", alarmDefine);
                 }
+                stopWatch1.stop();
+                stopWatch1.start("handleAlarmTriggerData, handlerNormalData");
                 synchronized (defineId.intern()) {
                     //报警产生值满足（这里的满足不考虑报警持续时间）
                     if (triggerResult) {
@@ -241,10 +261,13 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
                         handlerNormalData(alarmDefine, dataTime, endResult, paramMap);
                     }
                 }
+                stopWatch1.stop();
             } else {
                 log.warn("部分信息点没有数值");
             }
+            log.info(stopWatch1.prettyPrint());
         }
+        log.info(stopWatch.prettyPrint());
     }
 
     /**
@@ -381,9 +404,11 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
     private void handlerNormalData(
             AlarmDefine alarmDefine, String dataTime,
             Boolean endResult, HashMap<String, Object> paramMap) throws InterruptedException {
+        StopWatch stopWatch = new StopWatch("handlerNormalData");
+        stopWatch.start("getAlarmDefineStateFromCacheOrDb");
         String defineId = AlarmInfoCache.getAlarmDefineId(alarmDefine);
         AlarmDefineState alarmDefineState = getAlarmDefineStateFromCacheOrDb(defineId);
-
+        stopWatch.stop();
         Condition condition = alarmDefine.getCondition();
         //当前数据正常，报警状态为正常：清空之前的报警计时，重置回默认状态
         if (AlarmDefineState.State.NORMAL.getType().equals(alarmDefineState.getState())) {
@@ -393,6 +418,7 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
             if (!endResult) {
                 return;
             }
+            stopWatch.start("alarmSuspendLastTime");
             /* 判断是否满足报警恢复持续时间 */
             String alarmSuspendStartTime = alarmDefineState.getAlarmSuspendStartTime();
             if (StringUtil.isEmpty(alarmSuspendStartTime)) {
@@ -404,37 +430,46 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
             long alarmSuspendLastTime = DateUtils.betweenTwoTimeSecond(alarmSuspendStartTime, dataTime);
             // 设定的报警恢复持续时间
             int uphold = condition.getEndUphold();
+            stopWatch.stop();
             if (alarmSuspendLastTime < uphold) {
                 return;
             }
 
             /* 超过报警恢复设置的持续时间 */
             log.info("报警恢复持续时间大于设定时间：[{}]>[{}]", alarmSuspendLastTime, uphold);
-
+            stopWatch.start("getZktAlarmRecordDOWhenAlarmSuspend");
             ZktAlarmRecordDO alarmRecordDO = getZktAlarmRecordDOWhenAlarmSuspend(defineId, dataTime, paramMap);
             String alarmId = alarmRecordDO.getAlarmId();
+            stopWatch.stop();
             // 报警恢复时，alarmLastTimeCache中对应的报警标记为可删除
             alarmLastTimeCache.setDeleteAvailable(defineId);
             // 如果云端已经完成报警记录的创建，直接发送更新报警状态消息，并删除数据库中的报警信息
             if (createdAlarmIdsCache.contains(alarmId)) {
+                stopWatch.start("sendAlarmRecoverMessage");
                 deleteZktAlarmRecordWhenAlarmSuspend(defineId);
                 log.info("发送报警恢复消息，报警id: [{}]", alarmId);
                 // 发送报警恢复消息
                 sendAlarmRecoverMessage(alarmDefine.getProjectId(), dataTime, paramMap, alarmId);
                 // 报警恢复后，从缓存中移除报警id
                 createdAlarmIdsCache.remove(alarmId);
+                stopWatch.stop();
             } else {
+                stopWatch.start("createAlarmRecoverTimingJob");
                 log.info("已创建的报警id中不包含[{}], 3分钟后重试发送报警恢复消息", alarmId);
                 // 创建恢复定时任务
                 createAlarmRecoverTimingJob(dataTime, paramMap, alarmRecordDO);
+                stopWatch.stop();
             }
+            stopWatch.start("cancelRelatedExpireJob");
             // 取消过期任务
             cancelRelatedExpireJob(alarmId);
             //报警恢复，报警状态重置回默认
             alarmDefineState.reset();
+            stopWatch.stop();
         }
         // 更新报警定义缓存
         alarmInfoCache.setAlarmState(defineId, alarmDefineState);
+        log.info(stopWatch.prettyPrint());
     }
 
     /**
@@ -598,17 +633,22 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
     private void handleAlarmTriggerData(
             AlarmDefine alarmDefine, String dataTime,
             HashMap<String, Object> paramMap) throws Exception {
+        StopWatch stopWatch = new StopWatch();
+        stopWatch.start("getAlarmDefineStateFromCacheOrDb");
         // 根据defineId获取报警定义状态
         String defineId = AlarmInfoCache.getAlarmDefineId(alarmDefine);
         AlarmDefineState alarmDefineState = getAlarmDefineStateFromCacheOrDb(defineId);
-
+        stopWatch.stop();
+        stopWatch.start("inEffectTime");
         Condition condition = alarmDefine.getCondition();
         // 判断报警是否在有效期内
         boolean inEffectTime = ConditionUtils.inEffectiveTime(condition, dataTime);
+        stopWatch.stop();
 
         if (inEffectTime) {
             // 已经产生报警
             if (AlarmDefineState.State.NOT_DEAL.getType().equals(alarmDefineState.getState())) {
+                stopWatch.start("alarmContinue");
                 // 获取报警持续时间
                 String alarmStartTime = alarmDefineState.getAlarmStartTime();
                 long lastTime = DateUtils.betweenTwoTimeSecond(alarmStartTime, dataTime);
@@ -618,9 +658,11 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
                     log.info("开始拼装报警持续消息");
                     initAlarmContinueMsg(alarmId, lastTime, paramMap, alarmDefine.getProjectId());
                 }
+                stopWatch.stop();
             }
             //之前是是正常状态
             if (AlarmDefineState.State.NORMAL.getType().equals(alarmDefineState.getState())) {
+                stopWatch.start("getTriggerUphold");
                 // 报警持续时间
                 long alarmLastTime = 0;
                 if (StringUtil.isNotEmpty(alarmDefineState.getAlarmStartTime())) {
@@ -634,7 +676,9 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
                 LocalDateTime expireDateTime = getExpireLocalDateTime(dataTime, condition);
                 log.info("报警持续时间：[{}]", alarmLastTime);
                 log.info("设定的持续时间：[{}]", condition.getTriggerUphold());
+                stopWatch.stop();
                 if (alarmLastTime >= condition.getTriggerUphold()) {
+                    stopWatch.start("saveZktAlarmRecordWhenAlarmStart");
                     String alarmId = StringUtil.getUUID();
                     log.info("报警持续时间大于设定的持续时间，产生一条报警: [{}]", alarmId);
                     // 有新的报警产生，alarmLastTimeMap中报警标记为可删除
@@ -644,16 +688,20 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
                     saveZktAlarmRecordWhenAlarmStart(alarmId, alarmDefine, dataTime);
                     // 报警定义状态更新为未处理
                     alarmDefineState.setState(AlarmDefineState.State.NOT_DEAL.getType());
+                    stopWatch.stop();
+                    stopWatch.start("sendCreateAlarmRecordMessage");
                     // 发送创建报警记录的消息
                     sendCreateAlarmRecordMessage(alarmId, alarmDefine, dataTime, paramMap,
                             DateUtils.localDateTime2Date(expireDateTime));
-
+                    stopWatch.stop();
                     //有过期时间，生成报警过期消息
                     if (expireDateTime != null) {
+                        stopWatch.start("createExpireJob");
                         //过期时间
                         log.info("产生一条定时过期报警消息, 过期时间为：{}", expireDateTime);
                         // 创建一条过期任务
                         createExpireJob(alarmId, alarmDefine, alarmDefineState, expireDateTime);
+                        stopWatch.stop();
                     }
                 }
             }
@@ -664,6 +712,7 @@ public class AlarmHandleServiceImpl implements AlarmHandleService {
             alarmDefineState.reset();
         }
         alarmInfoCache.setAlarmState(defineId, alarmDefineState);
+        log.info(stopWatch.prettyPrint());
     }
 
     /**