执行一个方法,时间明显过去了数秒,但是统计的运行时间只有176毫秒。时间都耗费在数据库查询、更新上,难道joinPoint.proceed()是异步的?

    1. 2021-05-12 17:09:20.665 INFO 8468 --- [http-nio-8000-exec-1] c.y.l.c.s.impl.CameraInfoServiceImpl : 摄像机列表已过期,正在重新获取
    2. 2021-05-12 17:09:20.673 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.S.selectOne : ==> Preparing: SELECT id,menu_name,sort,value,status FROM yx_system_config WHERE (menu_name = ?)
    3. ....
    4. 2021-05-12 17:09:31.379 DEBUG 8468 --- [http-nio-8000-exec-1] co.yixiang.config.MetaHandler : 自动插入 updateDate
    5. 2021-05-12 17:09:31.379 DEBUG 8468 --- [http-nio-8000-exec-1] co.yixiang.config.MetaHandler : 自动插入 delFlag
    6. 2021-05-12 17:09:31.379 DEBUG 8468 --- [http-nio-8000-exec-1] co.yixiang.config.MetaHandler : 自动插入 createTime
    7. 2021-05-12 17:09:31.380 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.SystemConfigMapper.update : ==> Preparing: UPDATE yx_system_config SET value=? WHERE (menu_name = ?)
    8. 2021-05-12 17:09:31.380 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.SystemConfigMapper.update : ==> Parameters: 2021-05-18 17:09:31(String), yingshi_camera_passtime(String)
    9. 2021-05-12 17:09:31.482 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.SystemConfigMapper.update : <== Updates: 1
    10. 2021-05-12 17:09:31.488 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.l.c.s.m.CameraInfoMapper.selectList : ==> Preparing: SELECT id,channel_no,latitude,validate_code,update_time,camera_type,is_show,device_serial,area_id,create_time,area_name,area_type,view_url,channel_name,is_del,mark,longitude,status FROM c_camera_info WHERE (is_show = ? AND is_del = ?)
    11. 2021-05-12 17:09:31.488 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.l.c.s.m.CameraInfoMapper.selectList : ==> Parameters: 1(Integer), 0(Integer)
    12. 2021-05-12 17:09:31.557 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.l.c.s.m.CameraInfoMapper.selectList : <== Total: 55
    13. 2021-05-12 17:09:31.562 INFO 8468 --- [http-nio-8000-exec-1] c.y.l.c.s.impl.CameraInfoServiceImpl : 不存在cameraList缓存,正在准备
    14. 2021-05-12 17:09:31.564 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.S.selectOne : ==> Preparing: SELECT id,menu_name,sort,value,status FROM yx_system_config WHERE (menu_name = ?)
    15. 2021-05-12 17:09:31.564 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.S.selectOne : ==> Parameters: yingshi_token_passtime(String)
    16. 2021-05-12 17:09:31.615 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.S.selectOne : <== Total: 1
    17. 2021-05-12 17:09:31.617 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.S.selectOne : ==> Preparing: SELECT id,menu_name,sort,value,status FROM yx_system_config WHERE (menu_name = ?)
    18. 2021-05-12 17:09:31.617 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.S.selectOne : ==> Parameters: yingshi_token(String)
    19. 2021-05-12 17:09:31.680 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.S.selectOne : <== Total: 1
    20. 2021-05-12 17:09:31.681 INFO 8468 --- [http-nio-8000-exec-1] c.y.l.c.service.impl.YingshiServiceImpl : 萤石云token未过期
    21. 2021-05-12 17:09:31.733 INFO 8468 --- [http-nio-8000-exec-1] c.y.m.s.aspect.MethodRunningLogAspect : 耗时:查询陆家:摄像机信息 176毫秒

    切面:

    
        @Around("thisPointCut()")
        public Object logAround(ProceedingJoinPoint joinPoint) throws Throwable {
            currentTime.set(System.currentTimeMillis());
            MethodSignature signature = (MethodSignature) joinPoint.getSignature();
            Method method = signature.getMethod();
            ApiOperation apiOperation = method.getAnnotation(ApiOperation.class);
            RunningTime runningTime = method.getAnnotation(RunningTime.class);
            Object res = joinPoint.proceed();
    
            String methodNote = "";
            boolean flag=false;
            if(!"".equals(runningTime.value())){
                methodNote = runningTime.value();
                flag = true;
            }
    
            if(!flag && apiOperation !=null){
                methodNote = apiOperation.value();
            }
            if("".equals(methodNote)){
                methodNote = joinPoint.getTarget().getClass().getName() + "."+method.getName();
            }
            log.info("耗时:"+methodNote +" {}毫秒",System.currentTimeMillis() - currentTime.get());
            return res;
    
        }