前言
作为工程师，不能仅仅满足于实现了现有的功能逻辑，还必须深入认识系统。一次请求，流经了哪些方法，执行了多少次DB操作，访问了多少次文件操作，调用多少次API操作，总共有多少次IO操作，多少CPU操作，各耗时多少 ？ 开发者应当知道这些运行时数据，才能对系统的运行有更深入的理解，更好的提升系统的性能和稳定性。
本文主要介绍使用AOP拦截器来获取一次请求流经方法的调用次数和调用耗时。
总体思路
使用AOP思想来解决。增加一个注解，然后增加一个AOP methodAspect ，记录方法的调用次数及耗时。
methodAspect 内部含有两个变量 methodCount, methodCost ，都采用了 ConcurrentHashMap 。这是因为方法执行时，可能是多线程写入这两个变量。
使用：
(1) 将需要记录次数和耗时的方法加上 MethodMeasureAnnotation 即可；
(2) 将 MethodMeasureAspect 作为组件注入到 ServiceAspect 中，并在 ServiceAspect 中打印 MethodMeasureAspect 的内容。
关注哪些方法
通常重点关注一个任务流程中的如下方法：
IO阻塞操作：文件操作， DB操作，API操作， ES访问；
同步操作：lock, synchronized, 同步工具所施加的代码块等；
CPU耗时：大数据量的format, sort 等。
一般集中在如下包：
service, core , report, sort 等。根据具体项目而定
代码
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.Signature;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import java.lang.reflect.Method;
import java.util.ArrayList;
import java.util.IntSummaryStatistics;
import java.util.List;
import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
import java.util.stream.Collectors;
/**
* 记录一次请求中,流经的所有方法的调用耗时及次数
*
*/
@Component
@Aspect
public class MethodMeasureAspect {
private static final Logger logger = LoggerFactory.getLogger(MethodMeasureAspect.class);
private Map<String, Integer> methodCount = new ConcurrentHashMap();
private Map<String, List<Integer>> methodCost = new ConcurrentHashMap();
@SuppressWarnings(value = "unchecked")
@Around("@annotation(MethodMeasureAnnotation)")
public Object process(ProceedingJoinPoint joinPoint) {
Object obj = null;
String className = joinPoint.getTarget().getClass().getSimpleName();
String methodName = className + "_" + getMethodName(joinPoint);
long startTime = System.currentTimeMillis();
try {
obj = joinPoint.proceed();
} catch (Throwable t) {
logger.error(t.getMessage(), t);
} finally {
long costTime = System.currentTimeMillis() - startTime;
logger.info("method={}, cost_time={}", methodName, costTime);
methodCount.put(methodName, methodCount.getOrDefault(methodName, 0) + 1);
List<Integer> costList = methodCost.getOrDefault(methodName, new ArrayList<>());
costList.add((int)costTime);
methodCost.put(methodName, costList);
}
return obj;
}
public String getMethodName(ProceedingJoinPoint joinPoint) {
Signature signature = joinPoint.getSignature();
MethodSignature methodSignature = (MethodSignature) signature;
Method method = methodSignature.getMethod();
return method.getName();
}
public String toString() {
StringBuilder sb = new StringBuilder("MethodCount:\n");
Map<String,Integer> sorted = MapUtil.sortByValue(methodCount);
sorted.forEach(
(method, count) -> {
sb.append("method=" + method + ", " + "count=" + count+'\n');
}
);
sb.append('\n');
sb.append("MethodCosts:\n");
methodCost.forEach(
(method, costList) -> {
IntSummaryStatistics stat = costList.stream().collect(Collectors.summarizingInt(x->x));
String info = String.format("method=%s, sum=%d, avg=%d, max=%d, min=%d, count=%d", method,
(int)stat.getSum(), (int)stat.getAverage(), stat.getMax(), stat.getMin(), (int)stat.getCount());
sb.append(info+'\n');
}
);
sb.append('\n');
sb.append("DetailOfMethodCosts:\n");
methodCost.forEach(
(method, costList) -> {
String info = String.format("method=%s, cost=%s", method, costList);
sb.append(info+'\n');
}
);
return sb.toString();
}
}
import java.lang.annotation.Documented;
import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;
/**
* 记录方法调用
*/
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
@Documented
public @interface MethodMeasureAnnotation {
}
public class MapUtil {
public static <K, V extends Comparable<? super V>> Map<K, V> sortByValue(Map<K, V> map) {
Map<K, V> result = new LinkedHashMap<>();
Stream<Map.Entry<K, V>> st = map.entrySet().stream();
st.sorted(Comparator.comparing(e -> e.getValue())).forEach(e -> result.put(e.getKey(), e.getValue()));
return result;
}
}
@Around(“@annotation(MethodMeasureAnnotation)”) 仅仅指定了在携带指定注解的方法上执行。实际上，可以指定多种策略，比如指定类，指定包下。可以使用逻辑运算符 || , && , ! 来指明这些策略的组合。 例如：
@Around("@annotation(MethodMeasureAnnotation) "
+ "|| execution(* BizOrderDataService.*(..))"
+ "|| execution(* core.service.*.*(..)) "
+ "|| execution(* .strategy..*.*(..)) "
+ "|| execution(* *.generate*(..)) "
)
指明了五种策略的组合： 带有 MethodMeasureAnnotation 注解的方法； BizOrderDataService 类的所有方法； zzz.study.core.service 下的所有类的方法； zzz.study.core.strategy 包及其子包下的所有类的方法；zzz.study.core.report 包下所有类的以 generate 开头的方法。
execution表达式
@Pointcut 中， execution 使用最多。 其格式如下：
execution(modifiers-pattern? ret-type-pattern declaring-type-pattern? name-pattern(param-pattern)throws-pattern?)
括号中各个pattern分别表示：
修饰符匹配（modifier-pattern?）
返回值匹配（ret-type-pattern）可以为*表示任何返回值,全路径的类名等
类路径匹配（declaring-type-pattern?）
方法名匹配（name-pattern）可以指定方法名 或者 代表所有, set 代表以set开头的所有方法
参数匹配（(param-pattern)）可以指定具体的参数类型，多个参数间用“,”隔开，各个参数也可以用“”来表示匹配任意类型的参数，如(String)表示匹配一个String参数的方法；(,String) 表示匹配有两个参数的方法，第一个参数可以是任意类型，而第二个参数是String类型；可以用(…)表示零个或多个任意参数
异常类型匹配（throws-pattern?）其中后面跟着“?”的是可选项。
ThreadLocal方案
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import java.util.HashMap;
import java.util.Map;
/**
* @author liu
* @date 2022年05月26日 10:31
*/
@Aspect
@Component
public class ControllerAspect {
//定义一个日志的全局的静态
private static Logger logger = LoggerFactory.getLogger(ControllerAspect.class);
//ThreadLocal 维护变量 避免同步
//ThreadLocal为每个使用该变量的线程提供独立的变量副本，所以每一个线程都可以独立地改变自己的副本，而不会影响其它线程所对应的副本。
ThreadLocal<Long> startTime = new ThreadLocal<>();// 开始时间
//ThreadLocal 维护变量 避免同步 ThreadLocal是一个关于创建线程局部变量的类、
//通常情况下，我们创建的变量是可以被任何一个线程访问并且修改的。而使用ThreadLocal创建的变量只能被当前线程访问，其他线程无法访问和修改。
//ThreadLocal为每个使用该变量的线程提供独立的变量副本,所以每一个线程都可以独以地改变自己的副本,而不会影响其它线程所对应的副本
//ThreadLocal<Long> startTimes=new ThreadLocal<>();//开始时间
/**
* map1存放方法被调用的次数O
*/
ThreadLocal<Map<String, Long >> map1 = new ThreadLocal<>();
/**
* map2存放方法总耗时
*/
ThreadLocal<Map<String, Long >> map2 = new ThreadLocal<>();
/**
* 定义一个切入点. 解释下：
*
* ~ 第一个 * 代表任意修饰符及任意返回值. ~ 第二个 * 定义在web包或者子包 ~ 第三个 * 任意方法 ~ .. 匹配任意数量的参数.
*/
/// static final String pCutStr = "execution(* com.appleyk.*..*(..))";
// static final String pCutStr = "execution(* com.yanshu.controller..*..*(..))";
static final String pCutStr = "execution(* com.andon.springbootdistributedlock.controller.*..*(..))";
@Pointcut(value = pCutStr)
public void logPointcut() {
}
/**
* Aop：环绕通知 切整个包下面的所有涉及到调用的方法的信息
* @param joinPoint
* @return
* @throws Throwable
*/
@Around(value = "execution(* com.andon.springbootdistributedlock.controller.*.*(..))")
public Object doAround(ProceedingJoinPoint joinPoint) throws Throwable {
//初始化 一次
if(map1.get() ==null ){
map1.set(new HashMap<>());
}
if(map2.get() == null){
map2.set(new HashMap<>());
}
long start = System.currentTimeMillis();
try {
Object result = joinPoint.proceed();
if(result==null){
//如果切到了 没有返回类型的void方法，这里直接返回
return null;
}
long end = System.currentTimeMillis();
logger.info("===================");
String tragetClassName = joinPoint.getSignature().getDeclaringTypeName();
String MethodName = joinPoint.getSignature().getName();
Object[] args = joinPoint.getArgs();// 参数
int argsSize = args.length;
String argsTypes = "";
String typeStr = joinPoint.getSignature().getDeclaringType().toString().split(" ")[0];
String returnType = joinPoint.getSignature().toString().split(" ")[0];
logger.info("类/接口:" + tragetClassName + "(" + typeStr + ")");
logger.info("方法:" + MethodName);
logger.info("参数个数:" + argsSize);
logger.info("返回类型:" + returnType);
if (argsSize > 0) {
// 拿到参数的类型
for (Object object : args) {
argsTypes += object.getClass().getTypeName().toString() + " ";
}
logger.info("参数类型：" + argsTypes);
}
Long total = end - start;
logger.info("耗时: " + total + " ms!");
if(map1.get().containsKey(MethodName)){
Long count = map1.get().get(MethodName);
map1.get().remove(MethodName);//先移除，在增加
map1.get().put(MethodName, count+1);
count = map2.get().get(MethodName);
map2.get().remove(MethodName);
map2.get().put(MethodName, count+total);
}else{
map1.get().put(MethodName, 1L);
map2.get().put(MethodName, total);
}
return result;
} catch (Throwable e) {
long end = System.currentTimeMillis();
logger.info("====around " + joinPoint + "\tUse time : " + (end - start) + " ms with exception : "
+ e.getMessage());
throw e;
}
}
//对Controller下面的方法执行前进行切入，初始化开始时间
@Before(value = "execution(* com.andon.springbootdistributedlock.controller.*.*(..))")
public void beforMehhod(JoinPoint jp) {
startTime.set(System.currentTimeMillis());
}
//对Controller下面的方法执行后进行切入，统计方法执行的次数和耗时情况
//注意，这里的执行方法统计的数据不止包含Controller下面的方法，也包括环绕切入的所有方法的统计信息
@AfterReturning(value = "execution(* com.andon.springbootdistributedlock.controller.*.*(..))")
public void afterMehhod(JoinPoint jp) {
long end = System.currentTimeMillis();
long total = end - startTime.get();
String methodName = jp.getSignature().getName();
logger.info("连接点方法为：" + methodName + ",执行总耗时为：" +total+"ms");
//重新new一个map
Map<String, Long> map = new HashMap<>();
//从map2中将最后的 连接点方法给移除了，替换成最终的，避免连接点方法多次进行叠加计算
//由于map2受ThreadLocal的保护，这里不支持remove，因此，需要单开一个map进行数据交接
for(Map.Entry<String, Long> entry:map2.get().entrySet()){
if(entry.getKey().equals(methodName)){
map.put(methodName, total);
}else{
map.put(entry.getKey(), entry.getValue());
}
}
for (Map.Entry<String, Long> entry :map1.get().entrySet()) {
for(Map.Entry<String, Long> entry2 :map.entrySet()){
if(entry.getKey().equals(entry2.getKey())){
System.err.println(entry.getKey()+",被调用次数："+entry.getValue()+",综合耗时："+entry2.getValue()+"ms");
}
}
}
}
}
