在项目中碰到这样一个需求,对一个服务类的每一个方法,在方法开始和结束的时候分别记录一条日志,内容包括方法名,参数名+参数值以及方法执行的时间。
@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在初始化的时候先把参数名保存到内存中。以下是代码:
服务实现类(接口略):
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类:
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);
}
}
}
- 首先初始化的时候调用reflectGetParamName,运用反射获取所有方法的参数名,并保存到paraMap中。
- 在方法执行的前后分别打印日志并计算执行时间,方法名和参数值从JoinPoint中获取,参数名从paraMap中获取
配置文件applicationContext.xml:
<?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>
测试代码:
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
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