执行一个方法,时间明显过去了数秒,但是统计的运行时间只有176毫秒。时间都耗费在数据库查询、更新上,难道joinPoint.proceed()
是异步的?
2021-05-12 17:09:20.665 INFO 8468 --- [http-nio-8000-exec-1] c.y.l.c.s.impl.CameraInfoServiceImpl : 摄像机列表已过期,正在重新获取
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 = ?)
....
2021-05-12 17:09:31.379 DEBUG 8468 --- [http-nio-8000-exec-1] co.yixiang.config.MetaHandler : 自动插入 updateDate
2021-05-12 17:09:31.379 DEBUG 8468 --- [http-nio-8000-exec-1] co.yixiang.config.MetaHandler : 自动插入 delFlag
2021-05-12 17:09:31.379 DEBUG 8468 --- [http-nio-8000-exec-1] co.yixiang.config.MetaHandler : 自动插入 createTime
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 = ?)
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)
2021-05-12 17:09:31.482 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.SystemConfigMapper.update : <== Updates: 1
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 = ?)
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)
2021-05-12 17:09:31.557 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.l.c.s.m.CameraInfoMapper.selectList : <== Total: 55
2021-05-12 17:09:31.562 INFO 8468 --- [http-nio-8000-exec-1] c.y.l.c.s.impl.CameraInfoServiceImpl : 不存在cameraList缓存,正在准备
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 = ?)
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)
2021-05-12 17:09:31.615 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.S.selectOne : <== Total: 1
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 = ?)
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)
2021-05-12 17:09:31.680 DEBUG 8468 --- [http-nio-8000-exec-1] c.y.m.s.s.m.S.selectOne : <== Total: 1
2021-05-12 17:09:31.681 INFO 8468 --- [http-nio-8000-exec-1] c.y.l.c.service.impl.YingshiServiceImpl : 萤石云token未过期
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;
}