Spring之AOP實現日誌輸出，記錄方法執行時間
阿新 • • 發佈：2018-11-16
為了更好的瞭解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結束==
頁面顯示
