Spring-Boot+AOP+统计单次请求方法的执行次数和耗时情况

   本篇结合aop（面向切面编程）的特性，对spring-boot项目下后端开发人员所关心的java代码的性能做了一次简单的统计，比如，前端发了一个post请求（一连串数据的保存），到了后端，首先是指定Controller的某个方法做接收，本篇称之为接入点方法；其次就是以接入点方法为线索，继续向下执行剩余模块（包）里面的方法，而这些方法就是我们所关心的数据业务的实现部分。

   如果利用aop技术对这些方法进行相应的切点操作的话，我们会清晰的看到，每个方法所在的包+类名，每个方法的名称，每个方法的参数类型以及每个方法的执行耗时情况等等，就如单元测试验证项目的可行性一样，我们拿到了这些信息后，就可以利用给出的信息去定位优化，虽然起决定性因素的还是整个项目的架构和数据库层面上的优化，显然本篇还是小试牛刀，就当做是自我娱乐吧。

一、Spring-Boot 添加 aop依赖

<dependency>
	<groupId>org.springframework.boot</groupId>
	<artifactId>spring-boot-starter-aop</artifactId>
</dependency>

二、Spring-Boot项目树

（1）

（2）添加Controller级别的拦截器（Class）

ControllerInterceptor.java

package com.appleyk.interceptor;

import java.util.HashMap;
import java.util.Map;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

/**
 * 拦截器
 */
@Aspect
@Component
public class ControllerInterceptor {

	static Logger logger = LoggerFactory.getLogger(ControllerInterceptor.class);
    //ThreadLocal 维护变量 避免同步	
	//ThreadLocal为每个使用该变量的线程提供独立的变量副本，所以每一个线程都可以独立地改变自己的副本，而不会影响其它线程所对应的副本。
    ThreadLocal<Long> startTime = 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.*..*(..))";

	@Pointcut(value = pCutStr)
	public void logPointcut() {
	}

	@Around("logPointcut()")
	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.appleyk.controller.*.*(..))")
	public void beforMehhod(JoinPoint jp) {
		startTime.set(System.currentTimeMillis());
	}

	//对Controller下面的方法执行后进行切入，统计方法执行的次数和耗时情况
	//注意，这里的执行方法统计的数据不止包含Controller下面的方法，也包括环绕切入的所有方法的统计信息
	@AfterReturning(value = "execution(* com.appleyk.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");
				}
			}
			
		}
	}


}

（3）说明

A.

B.

C.

D.

E.

D.其他见代码注释，还有一个地方需要注意

三、本次请求（保存players）测试的入口（Controller）

（1）对应Controller

（2）再往下走一层，见证一下对应的ServiceImpl的实现部分

四、请求测试

（1）数据准备

（2）mysql数据库 查看数据（暂时无）

（3） 清空项目中的Console控制台输出信息

（4）Send 测试数据进行 post请求

（5）查看项目控制台输出内容

（6）post请求数据（存储）验证

（7）再来个大数据量的post数据请求（存储）

（8）本地日志查看

   本篇涉及两个知识点，一个就是spring-boot日志的配置，一个就是aop的配置，前者在我的博文里有，后者的配置也很简单，总得来说，spring-boot作为spring的孩子，其在配置方面，真的是简化了不少，基本上就是零xml配置。