background

To perform performance tests on method execution in your project, add the following code before and after each method

long beginTime = System.currentTimeMillis(); 
long endTime = System.currentTimeMillis(); 
long timeConsume = endTime - beginTime; 
Copy the code

Obviously, it will make the code very jumbled, and there may be a lot of statistical performance. If you can simply add a note on the method, it can realize the record of method execution time, so as to reduce a lot of simple and tedious code, more convenient expansion

Technology selection

A scenario like this is typical of AOP, and a search for SpringAOP turns up plenty of code samples, but the project does not rely on Spring, and there is no need to introduce it. Typically, there are two approaches to implementing this functionality: one is to dynamically generate proxy-class objects at object creation time through CGLib dynamic proxies or JDK dynamic proxies, as SpringAOP does, and the other is AspectJ, which wearies the logic to be executed into bytecode at compile time.

For dynamic proxies, you need to create the proxy class of objects, can be enhanced, and projects, there are a lot of static methods that are not called through objects, when in use and even by the method of object to invoke no Spring IOC mechanism of convenient, also have to modify all the code in the processing of new objects, can use the enhanced proxy objects, A little trouble. And if you create objects frequently, there is a performance penalty because there is a step to create a proxy object.

In AspectJ’s case, you can weave enhanced logic wherever the pointcut expression is met, but rely on the help of weaving tools to enhance the compiled bytecode. Fortunately, maven already has an AspectJ compilation plug-in that can handle weaving easily

All things considered, we decided to use the Maven compilation plug-in with custom annotations (specifying the target) + ApsectJ(Aop enhanced) + AspectJ

The technical implementation

1. Custom annotations

@Retention(RetentionPolicy.RUNTIME) 
@Target(ElementType.METHOD) 
public @interface TimeConsumeLogAnnotation { 

} 
Copy the code

2. Introduce Aspectj dependencies

<dependency> <groupId>org.aspectj</groupId> <artifactId> aspectJrt </artifactId> <version>1.8.9</version> </dependency>Copy the code

3. Aspectj facets

@aspect public class TimeConsumeLogAspectJ {ThreadLocal<Long> timeRecord = new ThreadLocal<>(); @Pointcut("execution(* *(..) ) && @annotation(cn.freekiddo.annotation.TimeConsumeLogAnnotation)") 
​    public void jointPoint(){} 

​    @Before("jointPoint()") 
​    public void doBefore(JoinPoint joinPoint){ 
​        MethodSignature signature = (MethodSignature) joinPoint.getSignature(); 
​        Method method = signature.getMethod(); 
​        System.out.println("Method" + method.getName() + "Start"); 
​        timeRecord.set(System.currentTimeMillis()); 
​    } 

​    @After("jointPoint()") 
​    public void doAfter(JoinPoint joinPoint){ 
​        long beginTime = timeRecord.get(); 
​        System.out.println("Method" +joinPoint.getSignature().getName()+ "End, time"+(System.currentTimeMillis()-beginTime) +"ms"); }}Copy the code

4. Introduce maven compiler plugins

Work after maven-Compiler-plugin is done

< plugin > < groupId > org. Codehaus. Mojo < / groupId > < artifactId > aspectj maven - plugin < / artifactId > < version > 1.10 < / version > <configuration> <source> 1.8 < /source> <executions> <executions> <executions> <executions> <phase>compile</phase> <goals> <goal>compile</goal> </goals> </execution> </executions> </plugin>Copy the code

5. Add the @TimeconSumelogAnnotation annotation to the target method to compile and run

@TimeConsumeLogAnnotation(a)public static void sayHelloWorld(String name) { 
​    System.out.println("Hello " + name); 
} 
Copy the code

Compiled bytecode

@TimeConsumeLogAnnotation 
public static void sayHelloWorld(String name) { 
​    JoinPoint var1 = Factory.makeJP(ajc$tjp_0, (Object)null, (Object)null, name); 
​    try { 
​        TimeConsumeLogAspectJ.aspectOf().doBefore(var1); 
​        System.out.println("Hello " + name); 
​    } catch (Throwable var4) { 
​        TimeConsumeLogAspectJ.aspectOf().doAfter(var1); 
​        throw var4; 
​    } 
​    TimeConsumeLogAspectJ.aspectOf().doAfter(var1); 
} 
Copy the code

The effect

The sayHelloWorld method starts the Hello world method ends the sayHelloWorld method, which takes 1msCopy the code

Step on the pit

(1) Section execution twice

At the beginning of the section, the expression is zero

@Pointcut("@annotation(cn.freekiddo.annotation.TimeConsumeLogAnnotation)") 
Copy the code

Aspectj’s compiler recognizes the pointcut for both the method call and method execution phases because it executes in both phases

By changing the section expression to

@Pointcut("execution(* *(..) ) && @annotation(cn.freekiddo.annotation.TimeConsumeLogAnnotation)") 
Copy the code

You can limit this phase to identifying only the methods that perform it

(2) Multi-module project AspectJ compilation failed

If in a multi-module project, a specific submodule declares a section class and defines a pointcut expression, but the pointcut expression is scattered among other modules, AJC scans only the corresponding join point in this module when it scans the pointcut expression, and there is no way to edit the pointcut of other modules. Ajc does not scan for a pointcut expression that matches the current join point while compiling other modules

Compile problems can be solved by adding custom annotations and facets to each module

More operations

Since custom annotations support assignment, and Aspectj sections can intercept methods and get method parameters through reflection, more customized optimizations can be made from this base

Refer to the link

Spring AOP implementation principle and CGLIB application

Things you may not know about AspectJ

The AspectJ section performs two cause analyses

The multi-module Maven project uses Eclipse’s AspectJ weaving