AspectJ+Javasist记录日志

发表于 | | 阅读次数:

在项目中碰到这样一个需求，对一个服务类的每一个方法，在方法开始和结束的时候分别记录一条日志，内容包括方法名，参数名+参数值以及方法执行的时间。

1
2
3
4
5
6
7
8
@Override  
public String get(String key) {  
//  long start = System.currentTimeMillis();  
//  System.out.println("Begin Method = get, Args = [key=" + key + "]");  
    String value = props.getProperty(key);  
//  System.out.println("End Method = get, Args = [key=" + key + "], Cost=" + (System.currentTimeMillis() - start)+ "ms");  
    return value;  
}

以上注释的代码能够满足要求，但是如果类中的方法比较多得时候，会有大量的冗余代码，不利于维护。这个时候可以用AspectJ实现日志代码的嵌入，但是JointPoint只能拿到参数值，无法拿到参数名。因此考虑用Javasist在初始化的时候先把参数名保存到内存中。以下是代码：

服务实现类（接口略）：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
package test;  
  
import java.util.Properties;  
  
public class ServiceImpl implements Service {  
    private Properties props = new Properties();  
  
    @Override  
    public String get(String key) {  
        return props.getProperty(key);  
    }  
  
    @Override  
    public void put(String key, String value) {  
        props.put(key, value);  
    }  
  
    @Override  
    public void putAll(Properties props) {  
        this.props.putAll(props);  
    }  
}

Aspect类：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
package test;  
  
import java.util.Map;  
  
import javassist.ClassClassPath;  
import javassist.ClassPool;  
import javassist.CtClass;  
import javassist.CtMethod;  
import javassist.Modifier;  
import javassist.NotFoundException;  
import javassist.bytecode.CodeAttribute;  
import javassist.bytecode.LocalVariableAttribute;  
import javassist.bytecode.MethodInfo;  
  
import org.apache.log4j.Logger;  
import org.aspectj.lang.ProceedingJoinPoint;  
import org.aspectj.lang.annotation.Around;  
import org.aspectj.lang.annotation.Aspect;  
import org.aspectj.lang.annotation.Pointcut;  
  
import com.google.common.collect.Maps;  
  
@Aspect  
public class LogHelper {  
    final static private Logger logger = Logger.getLogger(ServiceImpl.class);  
    private static final String DELIMITER = " | ";  
  
    private Map<String, String[]> paraMap = Maps.newHashMap();  
  
    public void init() throws NotFoundException {  
        reflectGetParamName(ServiceImpl.class);  
    }  
  
    @Pointcut("execution(* (test.*+).*(..))")  
    public void aspectjMethod() {  
    }  
  
    @Around("aspectjMethod()")  
    public Object around(ProceedingJoinPoint call) throws Throwable {  
        long startTime = System.nanoTime();  
        String methodName = call.getSignature().getName();  
        String className = call.getTarget().getClass().getSimpleName();  
        Object[] args = call.getArgs();  
        StringBuilder begin = new StringBuilder("Begin ").append("Method=").append(methodName).append(", Args=[")  
                .append(argsToString(className, methodName, args)).append("]");  
        logger.info(begin);  
  
        Object result = call.proceed(args);  
        long costTime = (System.nanoTime() - startTime) / 1000;// μs  
        StringBuilder end = new StringBuilder("End ").append("Method=").append(methodName).append(", Args=[")  
                .append(argsToString(className, methodName, args)).append("], Cost=").append(costTime).append("μs");  
        logger.info(end);  
        return result;  
    }  
  
    private String argsToString(String className, String methodName, Object[] args) {  
        String[] paraNames = paraMap.get(className + methodName);  
        boolean appendParaName = true;  
        if (paraNames == null || paraNames.length != args.length) {  
            logger.warn("Fail to get parameter(s)' name. ClassName = " + className + ", MethodName = " + methodName  
                    + ", Expected ParaNum = " + args.length);  
            appendParaName = false;  
        }  
        StringBuilder sb = new StringBuilder();  
        for (int i = 0; i < args.length; i++) {  
            Object obj = args[i];  
            String paraName = paraNames[i];  
            if (sb.length() != 0) {  
                sb.append(DELIMITER);  
            }  
            if (appendParaName) {  
                sb.append(paraName).append("=");  
            }  
            sb.append(String.valueOf(obj));  
        }  
        return sb.toString();  
    }  
  
    private void reflectGetParamName(Class<?> clazz) throws NotFoundException {  
        ClassPool pool = ClassPool.getDefault();  
        pool.insertClassPath(new ClassClassPath(clazz));  
        CtClass cc = pool.get(clazz.getName());  
        for (CtMethod cm : cc.getDeclaredMethods()) {  
            String methodName = cm.getName();  
            // 使用javaassist的反射方法获取方法的参数名  
            MethodInfo methodInfo = cm.getMethodInfo();  
            CodeAttribute codeAttribute = methodInfo.getCodeAttribute();  
            LocalVariableAttribute attr = (LocalVariableAttribute) codeAttribute  
                    .getAttribute(LocalVariableAttribute.tag);  
            if (attr == null) {  
                throw new NotFoundException("CodeAttribute Not Found. ClassName = " + clazz.getName()  
                        + ", MethodName = " + methodName);  
            }  
            String[] paramNames = new String[cm.getParameterTypes().length];  
            int pos = Modifier.isStatic(cm.getModifiers()) ? 0 : 1;  
            for (int i = 0; i < paramNames.length; i++)  
                paramNames[i] = attr.variableName(i + pos);  
            paraMap.put(clazz.getSimpleName() + methodName, paramNames);  
        }  
    }  
}
  1. 首先初始化的时候调用reflectGetParamName，运用反射获取所有方法的参数名，并保存到paraMap中。
  2. 在方法执行的前后分别打印日志并计算执行时间，方法名和参数值从JoinPoint中获取，参数名从paraMap中获取

配置文件applicationContext.xml：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
<?xml version="1.0" encoding="UTF-8"?>    
    
<beans xmlns="http://www.springframework.org/schema/beans"    
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"    
         xmlns:aop="http://www.springframework.org/schema/aop"    
         xmlns:tx="http://www.springframework.org/schema/tx"    
         xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-2.0.xsd    
           http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-2.0.xsd    
           http://www.springframework.org/schema/tx http://www.springframework.org/schema/tx/spring-tx-2.0.xsd">    
               
    <!-- 启用AspectJ对Annotation的支持 -->           
    <aop:aspectj-autoproxy/>                    
    <bean id="service" class="test.ServiceImpl"/>    
    <bean id="aspcejHandler" class="test.LogHelper" init-method="init"/>    
</beans>

测试代码：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
package test;  
  
import java.util.Properties;  
  
import org.springframework.context.ApplicationContext;  
import org.springframework.context.support.ClassPathXmlApplicationContext;  
  
public class Test {  
    public static void main(String[] args) {  
        ApplicationContext context = new ClassPathXmlApplicationContext("applicationContext.xml");  
        Service service = (Service) context.getBean("service");  
        service.put("1", "one");  
        service.putAll(new Properties());  
        System.out.println(service.get("1"));  
    }  
  
}

测试结果：

15/07/16 10:19:38 INFO test.ServiceImpl: Begin Method=put, Args=[key=1 | value=one]
15/07/16 10:19:38 INFO test.ServiceImpl: End Method=put, Args=[key=1 | value=one], Cost=1539μs
15/07/16 10:19:38 INFO test.ServiceImpl: Begin Method=putAll, Args=[props={}]
15/07/16 10:19:38 INFO test.ServiceImpl: End Method=putAll, Args=[props={}], Cost=148μs
15/07/16 10:19:38 INFO test.ServiceImpl: Begin Method=get, Args=[key=1]
15/07/16 10:19:38 INFO test.ServiceImpl: End Method=get, Args=[key=1], Cost=86μs