用Perf4j做全局性能统计

今天下午听Kevin提到Perf4j，想起昨晚在InfoQ瞟到过这个名词，晚上回家改完系统，等着看数据更新状况，百般无聊，于是决定下载 Perf4j玩玩，聊以解闷

（前言：不知道怎么搞的，codehaus.org在公司访问好好的，回家来就访问不了了，显然是被墙间了，只好翻墙上了 perf4j.codehaus.org下载jar包，又找了半天的HTTP PROXY配到SVN里下载了源码——始筑墙者，其无后乎？）

首先试用了下perf4j直接写代码的方式：

public UserDTO getUserByUsername(String username) {
    StopWatch stopWatch = new Slf4JStopWatch("getUserByUsername", username);
    User user = userService.getUserByUsername(username);
    logger.debug("Supported user {}", user);
    stopWatch.stop();
    return user == null ? null : mapper.map(user, UserDTO.class);
}

其中getUserByUsername是我的方法名，作为tag，username是方法参数作为message。跑了一下，slf4j出结果了，OK一切正常。

但是这种方法实在是太累赘了，每个方法都得去加代码，而且最后一行的性能还统计不到-_-（除非改代码）

遂改用@Profiled注解方式，方法里改成：

@Profiled
public UserDTO getUserByUsername(String username) {
    User user = userService.getUserByUsername(username);
    logger.debug("Supported user {}", user);
    return user == null ? null : mapper.map(user, UserDTO.class);
}

同时在Spring配置文件里配置上AOP自动代理与perf4j：

这回舒服多了，@Profile可以携带多个参数，甚至包含el表达式，不过我感觉默认就挺够用的了，呵呵，具体使用可以参见源码的 Javadoc，里面写的很详细。执行代码，pass

于是着手开始改项目，结果发现。。。要加注释的方法太多了-_-。想起Spring的@Transactional，可惜@Profiled不能加在类上

身为一个慵懒的程序员，这种Annotation的方式显然还不够适合我，于是删掉Annotation们重新来搞

先在Spring的applicationContext里加一个AOP的bean：

<bean class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator">
    <property name="beanNames">
        <list>
            <value>*RemoteImpl</value>
        </list>
    </property>
    <property name="interceptorNames">
        <list>
            <value>perf4jInterceptor</value>
        </list>
    </property>
</bean>

其中*RemoteImpl是我需要统计用的类，类名都是以RemoteImpl结尾；perf4jInterceptor是用于拦截的拦截器 bean，代码如下：

@Service
public class Perf4jInterceptor implements MethodBeforeAdvice, AfterReturningAdvice {

private Map<String, StopWatch> watches = new HashMap<String, StopWatch>();

    public void before(Method method, Object[] args, Object target) throws Throwable {
        String completeMethodName = getCompleteMethodName(target, method);

        // 创建性能日志记录器
        StopWatch stopWatch;
        if (watches.containsKey(completeMethodName)) {
            stopWatch = watches.get(completeMethodName);
            stopWatch.start();
        } else {
            stopWatch = new Slf4JStopWatch(completeMethodName, Arrays.toString(args));
            watches.put(completeMethodName, stopWatch);
        }

}

public void afterReturning(Object returnValue, Method method, Object[] args, Object target) throws Throwable {
String completeMethodName = getCompleteMethodName(target, method);

        // 记录性能
        if (watches.containsKey(completeMethodName)) {
            StopWatch stopWatch = watches.get(completeMethodName);
            stopWatch.stop();
        }
    }

    /**
     * 根据目标对象与方法获取方法完整名称.
     * @param target 目标对象
     * @param method 方法
     * @return 方法完整名称
     */
    private String getCompleteMethodName(Object target, Method method) {
        String className = "";
        if (target != null) {
            className = target.toString();
            int loc = className.indexOf("@");
            if (loc >= 0) {
                className = className.substring(0, loc);
            }
        }

        return className + "." + method.getName();
    }
}

OK，这样项目中所有以RemoteImpl结尾的类的所有方法均被列入了性能记录行列

再次执行代码调用方法进行测试，pass

最后将系统日志文件拷贝出来，执行：

grep perf4j publication.log > a
java -jar perf4j-0.9.10.jar -g g.html a

即可看到统计结果：

Performance Statistics   02:47:00 - 02:47:30
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
com.baidu.uic.publication.remoting.impl.UserRemoteImpl.getAllUsersByContactWithPage      2098.0          94       14625      4088.8          11
com.baidu.uic.publication.remoting.impl.UserRemoteImpl.getUserByUsername       153.3           0        1297       382.6          10

Performance Statistics   02:47:30 - 02:48:00
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
com.baidu.uic.publication.remoting.impl.UserRemoteImpl.getAllUsersByContactWithPage      2985.8          63        7406      2979.8          10
com.baidu.uic.publication.remoting.impl.UserRemoteImpl.getUserByUsername         1.6           0          16         4.8          10

下面是生成的图表:

点击查看原始尺寸