从零开始SpringCloud Alibaba实战（79）——Spring-Boot+AOP+统计单次请求方法的执行次数和耗时

liu1002880404

已于 2022-05-26 11:06:01 修改

阅读量1k

点赞数 1

分类专栏：项目实战文章标签： java

于 2021-09-19 08:33:21 首次发布

本文链接：https://blog.csdn.net/liuerchong/article/details/120376991

版权

项目实战专栏收录该内容

139 篇文章 53 订阅

订阅专栏

文章目录

前言

作为工程师，不能仅仅满足于实现了现有的功能逻辑，还必须深入认识系统。一次请求，流经了哪些方法，执行了多少次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");
                }
            }

        }
    }

}