使用 SpringAOP和SpringIOC一个bean调用另一个bean耗时超过1分钟什么情况？获取一次请求流经方法的调用次数和调用耗时

我就是我 2022-12-27 08:25 86阅读 0赞

前言描述：

在一个Service的实现类里面，

声明另一个bean如下：

@Autowired
    private NewsProcessingVo2NewsBusVo newsProcessingVo2NewsBusVo;

然后添加日期时长监控：如图所示

![watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTE0ODgwMDk_size_16_color_FFFFFF_t_70][]

使用了JDK8版本的监控时长程序：
    
    Instant endTimeMark = Instant.now();
    Long period = Duration.between(startTimeMark, endTimeMark).toMillis();
    log.error("5--1公开资讯id ：【{}】newPushPublishBus--newsProcessingVo2NewsBusVo.transform，耗时{} 毫秒", newsId, period);

调用的方法：

public News2BusDTO transform(TbmNewsProcessing newsProcessing, TbmNewsInfo newsInfo, List<TbmNewsTags> tagList, TbmNewsDupFilter newsDup, Integer opType) {
            Instant endTimeMark1 = Instant.now();
            Map<String, String> hwDimAreaMap = ContantData.getHwDimAreaMap();
            News2BusDTO news2BusDTO = new News2BusDTO();
            BeanUtils.copyProperties(newsInfo, news2BusDTO);
            news2BusDTO.setId(newsProcessing.getNewsId());
            if(StringUtils.isNotBlank(newsInfo.getContentText())){
                news2BusDTO.setContentText(newsInfo.getContentText().replace("\n", "\r\n"));
            }
            Instant endTimeMark2 = Instant.now();
            Long period1 = Duration.between(endTimeMark1, endTimeMark2).toMillis();
            log.error("5--1----1公开资讯id ：【{}】newsProcessingVo2NewsBusVo.transform---copyProperties，耗时{} 毫秒", newsProcessing.getNewsId(), period1);
    
            news2BusDTO.setSubtitle(newsInfo.getSubTitle());
            news2BusDTO.setAppIds(JSONObject.parseArray(newsInfo.getAppIds(), Integer.class));
            news2BusDTO.setStdNewsId(newsInfo.getParentNewsId());
            news2BusDTO.setMediaSourceCode(newsProcessing.getMediaSourceCode());
            news2BusDTO.setAuthorOrg(newsInfo.getAuthorOrg());
            news2BusDTO.setAuthorOrgCode(newsProcessing.getAuthorOrgCode());
            if (newsProcessing.getHandleStatus().equals(HandleProcessing.REMOVED.getType())) {
                news2BusDTO.setPublishStatus(PublicProcessing.OFF.getType().intValue());
            } else if (newsProcessing.getHandleStatus().equals(HandleProcessing.PUBLISH.getType())) {
                news2BusDTO.setPublishStatus(PublicProcessing.PUBLISH.getType().intValue());
            }
            if (newsInfo.getSrcPublishDate() != null) {
                news2BusDTO.setPublishDate(System.currentTimeMillis());
            }
            news2BusDTO.setSrcPublishDate(DateUtil.toDate(newsInfo.getSrcPublishDate()));
            if (opType == null) {
                if (newsInfo.getParentNewsId() != null) {
                    news2BusDTO.setOpType(OpType.PUBLISH.getType());
                } else {
                    news2BusDTO.setOpType(OpType.CREATE.getType());
                }
            } else {
                news2BusDTO.setOpType(opType);
            }
            Instant endTimeMark3 = Instant.now();
            Long period3 = Duration.between(endTimeMark2, endTimeMark3).toMillis();
            log.error("5--1---2公开资讯id ：【{}】newsProcessingVo2NewsBusVo.transform---直接复制，耗时{} 毫秒", newsProcessing.getNewsId(), period3);
    
            news2BusDTO.setInfoLevel(newsInfo.getLevel());
            List<TagInfo> tagInfoList = Lists.newArrayList();
            if (CollectionUtils.isNotEmpty(tagList)) {
                tagInfoList = getTagInfoList(tagList);
            }
            Instant endTimeMark4 = Instant.now();
            Long period4 = Duration.between(endTimeMark3, endTimeMark4).toMillis();
            log.error("5--1----3公开资讯id ：【{}】newsProcessingVo2NewsBusVo.transform---getTagInfoList，耗时{} 毫秒", newsProcessing.getNewsId(), period4);
    
            List<Duplicate> dupList = Lists.newArrayList();
            if (newsDup != null) {
                Duplicate duplicate = new Duplicate();
                duplicate.setId(newsDup.getNewsId());
                duplicate.setAuditConfirm(Integer.valueOf(newsDup.getDuplicate()));
                duplicate.setContentSimilarity(newsDup.getSimilarity());
                duplicate.setTitleSimilarity(newsDup.getTitleSimilarity());
                dupList.add(duplicate);
            }
            news2BusDTO.setDuplicates(dupList);
            news2BusDTO.setTagInfo(tagInfoList);
            Instant endTimeMark5 = Instant.now();
            Long period5 = Duration.between(endTimeMark4, endTimeMark5).toMillis();
            log.error("5--1----4公开资讯id ：【{}】newsProcessingVo2NewsBusVo.transform---dupList，耗时{} 毫秒", newsProcessing.getNewsId(), period5);
            List<ClassUnify> newsClass = Lists.newArrayList();
            if (newsProcessing.getArea() != null) {
                HwDimArea area = hwBusinessService.getAreaById(newsProcessing.getArea());
                hwDimAreaMap.get(newsProcessing.getArea());
                ClassUnify areaUnify = new ClassUnify();
                areaUnify.setBusinessId(area.getId());
                areaUnify.setClassName(area.getAreaName());
                news2BusDTO.setRegionClass(areaUnify);
            }
            Instant endTimeMark6 = Instant.now();
            Long period6 = Duration.between(endTimeMark5, endTimeMark6).toMillis();
            log.error("5--1----5公开资讯id ：【{}】newsProcessingVo2NewsBusVo.transform---newsClass，耗时{} 毫秒", newsProcessing.getNewsId(), period6);
            Instant startTimeMark = Instant.now();
            if (newsProcessing.getForm() != null) {
                getTypeClass(newsClass, newsProcessing.getForm());
            }
            if (newsProcessing.getRangeBase() != null) {
                getTypeClass(newsClass, newsProcessing.getRangeBase());
            }
            if (newsProcessing.getRangePlus() != null) {
                getTypeClass(newsClass, newsProcessing.getRangePlus());
            }
            if (newsProcessing.getFinancial() != null) {
                getTypeClass(newsClass, newsProcessing.getFinancial());
            }
            if (newsProcessing.getFinancialPlus() != null) {
                getTypeClass(newsClass, newsProcessing.getFinancialPlus());
            }
            if (newsProcessing.getTradingMarket() != null) {
                getTypeClass(newsClass, newsProcessing.getTradingMarket());
            }
            Instant endTimeMark7 = Instant.now();
            Long period7 = Duration.between(endTimeMark6, endTimeMark7).toMillis();
            log.error("5--1----6公开资讯id ：【{}】newsProcessingVo2NewsBusVo.transform---getTypeClass，耗时{} 毫秒", newsProcessing.getNewsId(), period7);
            news2BusDTO.setNewsClass(newsClass);
            news2BusDTO.setDupNewsId(newsInfo.getDupNewsId());
            //20201023添加俩个字段
            news2BusDTO.setNewsImportance(newsProcessing.getNewsImportance());
            news2BusDTO.setSentiment(newsProcessing.getSentiment());
            Instant endTimeMark8 = Instant.now();
            Long period8 = Duration.between(endTimeMark7, endTimeMark8).toMillis();
            Long period9 = Duration.between(endTimeMark1, endTimeMark8).toMillis();
            log.error("5--1----7公开资讯id ：【{}】newsProcessingVo2NewsBusVo.transform--- ，耗时{} 毫秒", newsProcessing.getNewsId(), period8);
            log.error("5--1这里面统计 资讯id ：【{}】newsProcessingVo2NewsBusVo.transform---返回数据 ，耗时{} 毫秒", newsProcessing.getNewsId(), period9);
            return news2BusDTO;
        }

最后展示的监控结果，如下所示，感觉特别震惊！

2020-12-09 13:38:24.221|:当前基准资讯： 1181776897672基准资讯获取的实时公开库查询结果：\[\]  
2020-12-09 13:38:24.954|:1公开资讯id ：【1181776897672】勾选重复资讯id基准资讯，耗时0 毫秒  
2020-12-09 13:38:25.057|:2公开资讯id ：【1181776897672】查询操作1、TbmNewsInfo 2、TbmNewsProcessing 3、TbmNewsTags，耗时103 毫秒  
2020-12-09 13:38:25.200|:3公开资讯id ：【1181776897672】更新操作-newPublish---> processingDao.update(newsProcessing)，耗时143 毫秒  
2020-12-09 13:38:25.200|:4公开资讯id ：【1181776897672】tranformNewsEditorOperate组装操作，耗时0 毫秒  
2020-12-09 13:38:31.193|5--1----1公开资讯id ：【1181776897672】newsProcessingVo2NewsBusVo.transform---copyProperties，耗时14 毫秒  
2020-12-09 13:38:31.194|5--1---2公开资讯id ：【1181776897672】newsProcessingVo2NewsBusVo.transform---直接复制，耗时1 毫秒  
2020-12-09 13:38:31.195|5--1----3公开资讯id ：【1181776897672】newsProcessingVo2NewsBusVo.transform---getTagInfoList，耗时1 毫秒  
2020-12-09 13:38:31.195|:5--1----4公开资讯id ：【1181776897672】newsProcessingVo2NewsBusVo.transform---dupList，耗时0 毫秒  
2020-12-09 13:38:31.195|:5--1----5公开资讯id ：【1181776897672】newsProcessingVo2NewsBusVo.transform---newsClass，耗时0 毫秒  
2020-12-09 13:38:31.328|:5--1----6公开资讯id ：【1181776897672】newsProcessingVo2NewsBusVo.transform---getTypeClass，耗时133 毫秒  
2020-12-09 13:38:31.328|:5--1----7公开资讯id ：【1181776897672】newsProcessingVo2NewsBusVo.transform--- ，耗时0 毫秒  
**2020-12-09 13:38:31.328|:5--1这里面统计 资讯id ：【1181776897672】newsProcessingVo2NewsBusVo.transform---返回数据 ，耗时149 毫秒  
2020-12-09 13:38:31.329|:5--1公开资讯id ：【1181776897672】newPushPublishBus--newsProcessingVo2NewsBusVo.transform，耗时6128 毫秒**  
2020-12-09 13:39:31.399|发送消息错误topic:audit\_platform\_to\_bus详细的资讯id（key）:1181776897672  
org.apache.kafka.common.errors.TimeoutException: Failed to update metadata after 60000 ms.  
2020-12-09 13:39:31.401|:5公开资讯id ：【1181776897672】newPushPublishBus 发送kafka，耗时66201 毫秒  
2020-12-09 13:39:31.496|:6公开资讯id ：【1181776897672】专题操作--，耗时95 毫秒  
2020-12-09 13:39:31.509|:7公开资讯id ：【1181776897672】saveLog(oldProcessing, operateVo)操作--，耗时13 毫秒

猜测应该是，主要是是bean的声明在另一个工程下面，导致的不能实时注册，外环依旧存在@Round的调用。

解决办法是把另一个bean的方法，迁移到这个类下面，直接调用就可以

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3UwMTE0ODgwMDk_size_16_color_FFFFFF_t_70]: /images/20221120/daa6fde3fd654abf89f65207841a1d36.png