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:40
Tag Avg(ms) Min Max Std Dev Count
method1 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:20
Tag Avg(ms) Min Max Std Dev Count
method1-11 20.0 20 20 0.0 1
-EOF-
网友评论