Spring之AOP实现日志输出，记录方法执行时间
为了更好的了解AOP，进行实践，用AOP实现日志输出，记录方法执行时间。
项目总体结构
项目简介；项目采用SpringBoot简单的实现一个访问模块。再用AOP实现此模块的日志输出，记录方法的执行时间。
pom.xml
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<groupId>com.yj</groupId>
<artifactId>Aspect2</artifactId>
<version>0.0.1-SNAPSHOT</version>
<packaging>jar</packaging>
<name>Aspect2</name>
<url>http://maven.apache.org</url>
<properties>
<project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
</properties>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>1.5.2.RELEASE</version>
<relativePath />
</parent>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-test</artifactId>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-aop</artifactId>
</dependency>
</dependencies>
</project>
这里需要注意如果是第一次使用springboot导包的时间可能会比较长，具体看网速。
UserController 测试用的控制层
package com.yj.controller;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.web.bind.annotation.RequestBody;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;
import com.yj.model.RespHead;
import com.yj.model.Result;
import com.yj.model.User;
import com.yj.service.UserService;
/**
* UserController 测试用的控制层
* @author Administrator
*
*/
@RestController
public class UserController {
@Autowired
private UserService userService;
@RequestMapping("/getUser")
public Result<User> getUser(User user){
System.out.println("#####################################");
user=userService.getUser(user);
Result<User> result =new Result<User>();
RespHead respHead=new RespHead();
result.setRespHead(respHead);
result.setContent(user);
return result;
}
}
到这里其实一个简单的访问模块已经可以了，这也是SpringBoot方便的地方。
控制层拦截，记录请求的开始，跟请求的结束
package com.yj.aspect;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.springframework.stereotype.Component;
import com.yj.utils.CommUtils;
/**
* ControllerAspect 控制层拦截，记录请求的开始，跟请求的结束
* @author Administrator
*
*/
@Component
@Aspect
public class ControllerAspect {
private static final Log LOG = LogFactory.getLog(ControllerAspect.class);
@Before(value = "controllerPointCut()")
public void doBefore(JoinPoint joinPoint) {
LOG.info("==" + CommUtils.getTimeStr() + " 开始请求" + joinPoint.getSignature().getDeclaringTypeName() + "."
+ joinPoint.getSignature().getName() + "==");
}
@After(value = "controllerPointCut()")
public void doAfter(JoinPoint joinPoint) throws Throwable {
LOG.info("==" + CommUtils.getTimeStr() + " 请求" + joinPoint.getSignature().getDeclaringTypeName() + "."
+ joinPoint.getSignature().getName() + "结束==");
}
@Pointcut("execution(* com.yj.controller..*.*(..))")
private void controllerPointCut() {
}
}
服务层拦截，记录方法调用的执行时间，参数等
package com.yj.aspect;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
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.Pointcut;
import org.springframework.stereotype.Component;
/**
* MethodAspect 服务层拦截，记录方法调用的执行时间，参数等
* @author Administrator
*
*/
@Component
@Aspect
public class MethodAspect {
private static final Log LOG = LogFactory.getLog(MethodAspect.class);
@Pointcut("execution(public * com.yj.service..*.*(..))")
public void methodPointcut() {
}
@Around("methodPointcut()")
public Object doAround(ProceedingJoinPoint joinPoint) throws Throwable {
long start = System.currentTimeMillis();
try {
Object result = joinPoint.proceed();
long end = System.currentTimeMillis();
LOG.info("执行" + joinPoint.getSignature().getDeclaringTypeName() + "." + joinPoint.getSignature().getName()
+ "方法," + parseParames(joinPoint.getArgs()) + ",耗时:" + (end - start) + " ms!");
return result;
} catch (Throwable e) {
long end = System.currentTimeMillis();
LOG.error(joinPoint + ",耗时:" + (end - start) + " ms,抛出异常 :" + e.getMessage());
throw e;
}
}
@AfterReturning(returning = "ret", pointcut = "methodPointcut()")
public void doAfterReturning(Object ret) throws Throwable {
LOG.info("返回值:" + ret);
}
private String parseParames(Object[] parames) {
if (null == parames || parames.length <= 0) {
return "该方法没有参数";
}
StringBuffer param = new StringBuffer("请求参数 # 个:[ ");
int i = 0;
for (Object obj : parames) {
i++;
if (i == 1) {
param.append(obj.toString());
continue;
}
param.append(" ,").append(obj.toString());
}
return param.append(" ]").toString().replace("#", String.valueOf(i));
}
}
Order类
package com.yj.model;
public class Order {
private long orderId;
private String createTime;
public long getOrderId() {
return orderId;
}
public void setOrderId(long orderId) {
this.orderId = orderId;
}
public String getCreateTime() {
return createTime;
}
public void setCreateTime(String createTime) {
this.createTime = createTime;
}
@Override
public String toString() {
return "Order [orderId=" + orderId + ", createTime=" + createTime + "]";
}
}
自定义响应头RespHead类
package com.yj.model;
/**
* 自定义响应头
* @author Administrator
*
*/
public class RespHead {
private int code=0;
private String desc;
public int getCode() {
return code;
}
public void setCode(int code) {
this.code = code;
}
public String getDesc() {
return desc;
}
public void setDesc(String desc) {
this.desc = desc;
}
@Override
public String toString() {
return "RespHead [code=" + code + ", desc=" + desc + "]";
}
}
自定义响应结果Result类
package com.yj.model;
/**
* 自定义响应结果
* @author Administrator
*
* @param <T>
*/
public class Result<T> {
private RespHead respHead;
private T content;
public RespHead getRespHead() {
return respHead;
}
public void setRespHead(RespHead respHead) {
this.respHead = respHead;
}
public T getContent() {
return content;
}
public void setContent(T content) {
this.content = content;
}
@Override
public String toString() {
return "Result [respHead=" + respHead + ", content=" + content + "]";
}
}
User类
package com.yj.model;
import java.util.List;
public class User {
private String name;
private int age;
private List<Order> orders;
public String getName() {
return name;
}
public void setName(String name) {
this.name = name;
}
public int getAge() {
return age;
}
public void setAge(int age) {
this.age = age;
}
public List<Order> getOrders() {
return orders;
}
public void setOrders(List<Order> orders) {
this.orders = orders;
}
@Override
public String toString() {
return "User [name=" + name + ", age=" + age + ", orders=" + orders + "]";
}
}
OrderService类
package com.yj.service;
import org.springframework.stereotype.Service;
import com.yj.model.Order;
import com.yj.utils.CommUtils;
@Service
public class OrderService {
public Order getOrder(Long orderId){
Order order =new Order();
order.setOrderId(orderId);
order.setCreateTime(CommUtils.getTimeStr());
return order;
}
}
UserService类
package com.yj.service;
import java.util.ArrayList;
import java.util.List;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Service;
import com.yj.model.Order;
import com.yj.model.User;
@Service
public class UserService {
@Autowired
private OrderService orderService;
public User getUser(User user){
Order order=orderService.getOrder(1L);
List<Order> orders =new ArrayList<Order>();
orders.add(order);
user.setOrders(orders);
return user;
}
}
时间工具类
package com.yj.utils;
import java.text.SimpleDateFormat;
import java.util.Calendar;
/**
* 时间工具类
* @author Administrator
*
*/
public class CommUtils {
public static final String format = "yyyy-MM-dd HH:mm:ss";
public static String getTimeStr() {
Calendar cal = Calendar.getInstance();
return new SimpleDateFormat(format).format(cal.getTime());
}
}
启动Application类
package com.yj;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
@SpringBootApplication
public class Application {
public static void main(String[] args) throws Exception {
SpringApplication.run(Application.class, args);
}
}
验证
访问
http://localhost:8080/getUser
控制台显示
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v1.5.2.RELEASE)
2018-09-30 23:44:36.964 INFO 2972 --- [ main] com.yj.Application : Starting Application on WIN-20180311JVI with PID 2972 (D:\workspace\Aspect2\target\classes started by Administrator in D:\workspace\Aspect2)
2018-09-30 23:44:36.968 INFO 2972 --- [ main] com.yj.Application : No active profile set, falling back to default profiles: default
2018-09-30 23:44:37.067 INFO 2972 --- [ main] ationConfigEmbeddedWebApplicationContext : Refreshing org.springframework.boot[email protected]176dcec: startup date [Sun Sep 30 23:44:37 CST 2018]; root of context hierarchy
2018-09-30 23:44:40.145 INFO 2972 --- [ main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat initialized with port(s): 8080 (http)
2018-09-30 23:44:40.196 INFO 2972 --- [ main] o.apache.catalina.core.StandardService : Starting service Tomcat
2018-09-30 23:44:40.197 INFO 2972 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet Engine: Apache Tomcat/8.5.11
2018-09-30 23:44:40.583 INFO 2972 --- [ost-startStop-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
2018-09-30 23:44:40.584 INFO 2972 --- [ost-startStop-1] o.s.web.context.ContextLoader : Root WebApplicationContext: initialization completed in 3532 ms
2018-09-30 23:44:40.894 INFO 2972 --- [ost-startStop-1] o.s.b.w.servlet.ServletRegistrationBean : Mapping servlet: 'dispatcherServlet' to [/]
2018-09-30 23:44:40.909 INFO 2972 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'characterEncodingFilter' to: [/*]
2018-09-30 23:44:40.910 INFO 2972 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'hiddenHttpMethodFilter' to: [/*]
2018-09-30 23:44:40.910 INFO 2972 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'httpPutFormContentFilter' to: [/*]
2018-09-30 23:44:40.910 INFO 2972 --- [ost-startStop-1] o.s.b.w.servlet.FilterRegistrationBean : Mapping filter: 'requestContextFilter' to: [/*]
2018-09-30 23:44:41.912 INFO 2972 --- [ main] s.w.s.m.m.a.RequestMappingHandlerAdapter : Looking for @ControllerAdvice: org.springframework.boot[email protected]176dcec: startup date [Sun Sep 30 23:44:37 CST 2018]; root of context hierarchy
2018-09-30 23:44:42.054 INFO 2972 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/getUser]}" onto public com.yj.model.Result<com.yj.model.User> com.yj.controller.UserController.getUser(com.yj.model.User)
2018-09-30 23:44:42.058 INFO 2972 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error]}" onto public org.springframework.http.ResponseEntity<java.util.Map<java.lang.String, java.lang.Object>> org.springframework.boot.autoconfigure.web.BasicErrorController.error(javax.servlet.http.HttpServletRequest)
2018-09-30 23:44:42.059 INFO 2972 --- [ main] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped "{[/error],produces=[text/html]}" onto public org.springframework.web.servlet.ModelAndView org.springframework.boot.autoconfigure.web.BasicErrorController.errorHtml(javax.servlet.http.HttpServletRequest,javax.servlet.http.HttpServletResponse)
2018-09-30 23:44:42.161 INFO 2972 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-09-30 23:44:42.161 INFO 2972 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-09-30 23:44:42.278 INFO 2972 --- [ main] o.s.w.s.handler.SimpleUrlHandlerMapping : Mapped URL path [/**/favicon.ico] onto handler of type [class org.springframework.web.servlet.resource.ResourceHttpRequestHandler]
2018-09-30 23:44:42.648 INFO 2972 --- [ main] o.s.j.e.a.AnnotationMBeanExporter : Registering beans for JMX exposure on startup
2018-09-30 23:44:42.942 INFO 2972 --- [ main] s.b.c.e.t.TomcatEmbeddedServletContainer : Tomcat started on port(s): 8080 (http)
2018-09-30 23:44:42.946 INFO 2972 --- [ main] com.yj.Application : Started Application in 6.481 seconds (JVM running for 7.448)
2018-09-30 23:44:43.611 INFO 2972 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring FrameworkServlet 'dispatcherServlet'
2018-09-30 23:44:43.611 INFO 2972 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started
2018-09-30 23:44:43.657 INFO 2972 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization completed in 46 ms
2018-09-30 23:44:43.776 INFO 2972 --- [nio-8080-exec-1] com.yj.aspect.ControllerAspect : ==2018-09-30 23:44:43 开始请求com.yj.controller.UserController.getUser==
#####################################
2018-09-30 23:44:43.813 INFO 2972 --- [nio-8080-exec-1] com.yj.aspect.MethodAspect : 执行com.yj.service.OrderService.getOrder方法,请求参数 1 个:[ 1 ],耗时:16 ms!
2018-09-30 23:44:43.814 INFO 2972 --- [nio-8080-exec-1] com.yj.aspect.MethodAspect : 返回值:Order [orderId=1, createTime=2018-09-30 23:44:43]
2018-09-30 23:44:43.814 INFO 2972 --- [nio-8080-exec-1] com.yj.aspect.MethodAspect : 执行com.yj.service.UserService.getUser方法,请求参数 1 个:[ User [name=null, age=0, orders=[Order [orderId=1, createTime=2018-09-30 23:44:43]]] ],耗时:25 ms!
2018-09-30 23:44:43.814 INFO 2972 --- [nio-8080-exec-1] com.yj.aspect.MethodAspect : 返回值:User [name=null, age=0, orders=[Order [orderId=1, createTime=2018-09-30 23:44:43]]]
2018-09-30 23:44:43.815 INFO 2972 --- [nio-8080-exec-1] com.yj.aspect.ControllerAspect : ==2018-09-30 23:44:43 请求com.yj.controller.UserController.getUser结束==
页面显示