Perf4j的使用

perf4j介绍

Perf4j是一个应用性能分析工具，它能输出方法的调用耗时，以便帮助开发者了解系统里性能耗时的情况。
Perf4j的输出文件，按tag分类，从不同的方面对一段时间内的调用，从数量上进行了分析和统计，稍后将会提到。
此外，Perf4j还可以和JMX结合，作为JMX MBean的属性展示数据，同时在性能低于可接受阈值的情况下发送JMX通知。
它能跟Spring 结合，并且使用切面+注解的方式进行方法级别的性能监控(ms级别)。
除此之外，它还提供了关联Google Chart API (http://code.google.com/apis/chart/) 的Servlet，开发者只需要配置
GraphingServlet并为之设置访问路径，就能实时地将日志以图像的形式显示出来。

相关资源：
Github：https://github.com/codehaus/perf4j（代码已经很久没维护了）
官网：http://perf4j.codehaus.org （codehaus.org无法访问，developer guide可以戳这里：
https://web.archive.org/web/20150508124059/http://perf4j.codehaus.org/devguide.html）
官方DEMO：https://github.com/perf4j/perf4j/blob/master/src/site/apt/devguide.apt.vm
最新版本为：0.9.16

Perf4j的使用方法介绍

在知道Perf4j之前，调用一个方法的耗时，本人一般会按这样的方式去做：

void method(String param){    long start = System.currentTimeMillis();    System.out.println("method is invoked, param is "+param);    System.out.println("method1 is finish, elapsed time is "+(System.currentTimeMillis()-start));}

这样做可以打印出耗时，如果愿意，也可以输出到日志文件中，不过这样做有些不好的地方：
1、会产生大量的重复代码，而且代码对逻辑的入侵性很高。
2、难以控制输出日志的格式，对以后的日志分析带来很大的困难。
但是无可厚非，这样做确实非常随意，能在任何地方添加执行时间输出。

Perf4j也提供了类似的实现方式：

void method1(String param) {    StopWatch stopWatch = new LoggingStopWatch();    System.out.println("method1 is invoked, param is "+param);    stopWatch.stop("method1","cost time");    }

先看控制台输出：

start[1505287912971] time[1] tag[method1] message[cost time]method1 is invoked, param is xyz

start：开始调用的时间戳
time：执行时间
使用StopWatch之后，日志规范了不少，但是还是需要写不少代码，并且stop方法只是调用了System.err 输出到了控制台。
如果需要输出到日志文件，需要增加日志框架的支持，这里使用log4j来说明。
修改method1：

void method1(String param) throws InterruptedException {    StopWatch stopWatch = new Log4JStopWatch();    System.out.println("method1 is invoked, param is "+param);    stopWatch.stop("method1","cost time");    }

增加log4j配置文件：

<?xml version="1.0" encoding="UTF-8"?><!DOCTYPE log4j:configuration SYSTEM "log4j.dtd"><log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">    <appender name="CoalescingStatistics"              class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">        <!-- TimeSlice配置多少时间间隔去做一次汇总写入文件中 默认值是 30000 ms-->        <param name="TimeSlice" value="20000"/>        <appender-ref ref="performanceAppenderLOG"/>    </appender>    <!-- 汇总的perf4j的日志信息-->    <appender name="performanceAppenderLOG" class="org.apache.log4j.FileAppender">        <param name="File" value="D:/logs/perf4j/perfStats.log"/>        <param name="Append" value="true"/>15        <layout class="org.apache.log4j.PatternLayout">            <param name="ConversionPattern" value="%m%n"/>17        </layout>    </appender>    <root>        <priority value="INFO"/>        <appender-ref ref="CoalescingStatistics"/>    </root></log4j:configuration>

运行method1，日志将生成到perfStats.log之中。

Performance Statistics   2017-09-13 15:51:20 - 2017-09-13 15:51:40Tag                                                  Avg(ms)         Min         Max     Std Dev       Countmethod1                                                  7.0           7           7         0.0           1

按tag做了统计的区分，在该时间段内，各个性能指标分别为：
Avg：平均执行时间
Min：最小执行时间
Max：最大执行时间
Std Dev：标准差
Count：执行次数
其实按照上面的方式，代码量也还是很大的，Perf4j还提供了注解+Spring AOP的方式来简化使用。增加aop的配置

<aop:aspectj-autoproxy />    <bean id="timingAspect" class="org.perf4j.log4j.aop.TimingAspect" />

需要增加commons-jexl依赖，来提供对表达式的支持。
将method1所在的类添加到Spring到管理之中，并且将method1方法修改成：

@Profiled(tag="method1-11")    public void method1(String param){//        StopWatch stopWatch = new Log4JStopWatch();        System.out.println("method1 is invoked, param is "+param);//        stopWatch.stop("method1","cost time");    }

编写测试用例：

@RunWith(SpringJUnit4ClassRunner.class)@ContextConfiguration(locations={"classpath:springmvc.xml"})public class TestCase {    @Resource    private Original original;    @Test public void testPerf4j(){     original.method1("Spring"); }}

输出日志到文件：
Performance Statistics 2017-09-13 16:37:40 - 2017-09-13 16:38:00
Tag Avg(ms) Min Max Std Dev Count
method1-11 21.0 21 21 0.0 1

到这里，Perf4j的日志输出部分就已经介绍完了，使用起来还是挺简单的。

Perf4j的图表展示

统计出来的数据，能够用图表很直观地表现出现来。Perf4j自身提供了一个实现，先看看这个实现如何用。
配置Servlet：

<servlet>    <servlet-name>perf4j-google</servlet-name>    <servlet-class>org.perf4j.log4j.servlet.GraphingServlet</servlet-class>  </servlet>  <servlet-mapping>    <servlet-name>perf4j-google</servlet-name>    <url-pattern>/gchart</url-pattern>  </servlet-mapping>

修改log4j的xml配置，添加新的append，并由CoalescingStatistics提供它的数据来源：

<appender name="CoalescingStatistics"            class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">        <!-- TimeSlice配置多少时间间隔去做一次汇总写入文件中 默认值是 30000 ms ,设置为2分钟-->        <param name="TimeSlice" value="20000"/>        <appender-ref ref="performanceAppenderLOG"/>        <appender-ref ref="record"/>    </appender>        <appender name="record" class="org.perf4j.log4j.GraphingStatisticsAppender">        <param name="GraphType" value="Max"/>        <appender-ref ref="graphsFileAppender"/>    </appender>

运行web项目，触发几次添加@Profiled的方法。
访问servlet路径，如果能翻过GFW，你将看到类似如下显示的图片：

自定义结合Echarts显示监控结果的项目

以上的介绍，最不如人意的应该就是GFW了。
有没有一种办法能不使用Google Chart API也能显示，最好是实时动态显示监控结果？
答案是肯定的。
由于perf4j是开源的，如果我们可以修改其GraphingStatisticsAppender的实现，然后按照我们需要的方式在Servlet中组装显示参数，然后在调用页面上显示图像，而不用跑到Google去实时生成。
Echarts是一个非常优秀的前端图表显示框架，提供具体的参数，就能实时渲染出图表。
由于需要监控后台方法的执行时间并且把数据实时显示出来，在原来perf4j的基础上做了一些修改，仅供参考。
Github：https://github.com/IrvingSun/perf4j-charts
效果图：

GitHub上对使用方式做了比较详细的说明，这里就不再赘述了，欢迎提出建议。

其他

1、由于@Profiled注解依赖Spring AOP，Spring AOP底层是以动态代理原理来实现的，这就避免不了Spring AOP不能嵌套拦截的事实。
也就是说，代理对象的方法可以被拦截，但是代理对象方法调用的方法是无法被拦截的。
举个栗子，将一开始的例子修改为：

    @Profiled(tag="method1-11")    public void method1(String param){//        StopWatch stopWatch = new Log4JStopWatch();        System.out.println("method1 is invoked, param is "+param);//        stopWatch.stop("method1","cost time");        method(param);    }    @Profiled(tag="method1-12")    public void method(String param){        long start = System.currentTimeMillis();        System.out.println("method is invoked, param is "+param);        System.out.println("method1 is finish, elapsed time is "+(System.currentTimeMillis()-start));    }

方法method1调用method，并且两个方法都使用了Profiled注解。
但是我们在测试用例中，打印的日志并没有tag为method1-12的记录。

Performance Statistics   2017-09-13 17:20:00 - 2017-09-13 17:20:20Tag                                                  Avg(ms)         Min         Max     Std Dev       Countmethod1-11                                              20.0          20          20         0.0           1

-EOF-