深入perf4j源码

前言

引用一老程序员同事的一句话：“项目做到最后就是监控了。”在一天和那同事打电话聊天时他突然冒出来的一句话。后来我仔细回味这句话，越来越觉得挺有道理的。自己在现在的项目里就做了好几个监控相关的任务，而且也一直在想办法获取更多的监控数据，如每个进程内存使用情况、线程使用状态、某些方法的性能等。不过这句话只说了一半，监控是为了获取数据，但是有了数据后还要根据这些数据来做相应的决策，比如判断机器、进程的健康状况，如何改进系统等。最近对性能调优特别感兴趣，但是在性能调优前首先要收集性能数据，因而本文打算研究一下perf4j的实现和使用，以获取性能数据，后期可以继续写一些如何调优的文章。

性能调优分三步骤：1. 性能数据收集；2. 性能数据分析；3. 根据分析后的数据、代码以及系统特性进行调优，perf4j主要用于处理前两种情况，并且这两部分分开。

性能数据收集

性能数据收集是一件比较简单的事情，说白了就是在一段逻辑开始和结束的时间差值，一般可以将该值输出日志文件中，供后继分析。比如最简单的一种方式：

long startTime = System.currentTimeMillis();
methodToMeasure();
long timeSpend = System.currentTimeMillis() - startTime;
System.out.println("methodToMeasure took: " + timeSpend);

当然这种代码太原始，也太麻烦，在实际项目中，一般都把这部分逻辑抽象出一个StopWatch类：

StopWatch stopWatch = new StopWatch();
methodToMeasure();
System.out.println(stopWatch.stop("methodToMeasure"));
//output: start[1429350898550] time[66] tag[methodToMeasure]
也可以在日志中添加额外的信息：
System.out.println(stopWatch.stop("methodToMeasure", "A simple test method"));
//output: start[1429351112097] time[3] tag[methodToMeasure] message[A simple test method]

perf4j中StopWatch的实现非常简单，它只是对上面代码的一个简单封装，为了提高精确度，它使用System.nanoTime()来纪录时间差值，另外它引入了tag的概念，从而在后期分析的时候可以将相同的操作组合在一起形成一些统计数据，在perf4j的日志分析支持tag的层级结构，它使用dot来分隔，而message只是对当前日志的一种额外说明，这里不再赘述。另外在Guava和Apache Commons Lang项目中都提供了StopWatch类，而且他们打印的格式更具可读性，perf4j这里打印的简单格式主要为了后期统计分析，因而采用了更加简单的格式。

其实以上的代码还可以进一步封装：既然最后都是要打印这些信息的，直接在stop()方法中打印不就可以了？因而perf4j提供了LoggingStopWatch类，它将日志信息输出到System.err中：

StopWatch stopWatch = new LoggingStopWatch();
methodToMeasure();
stopWatch.stop("methodToMeasure", "A simple test method");

LoggingStopWatch添加了两个额外特性：可以设置打印阀值，只有当某段逻辑超过这个阀值后才打印日志，或者将这个阀值一下和以上的tag使用不同的后缀分开（默认后缀：.normal/.slow），并且它可以同时打印Exception信息：

stopWatch.setTimeThreshold(50);
stopWatch.setNormalAndSlowSuffixesEnabled(true);
//output:
// start[1429352833043] time[71] tag[methodToMeasure.slow]
// start[1429352833115] time[46] tag[methodToMeasure.normal]

然而既然要保存这些性能数据以供后期分析就不能把他们打印在System.err中，perf4j采用各种日志框架将这些性能信息打印在日志文件中，因而它提供了多种日志框架的实现：Slf4JStopWatch、Log4JStopWatch、JavaLogStopWatch、CommonsLogStopWatch。在所有这些StopWatch的实现中，它们只是将原本打印在System.err中的性能日志打印到Logger(Log)中，我们可以使用：

setNormalPriority(int normalPriority)
setExceptionPriority(int exceptionPriority)

来设置在打印性能日志时使用的Log Level(Priority)。默认使用的Logger Name：org.perf4j.TimingLogger，正常Level：INFO，异常Level：WARN。
如果将上述的LoggingStopWatch换成Slf4JStopWatch，并且配置相应的Log4J配置文件，则有如下输出：

//output:
// 150418 19:12:21,764 [INFO ] [main] o.p.TimingLogger - start[1429355541719] time[44] tag[methodToMeasure.normal]
// 150418 19:12:21,812 [WARN ] [main] o.p.TimingLogger - start[1429355541765] time[47] tag[methodToMeasureException.normal]
// java.lang.Exception: test
// at lev-in.learn.perf4j.SimplePerfCollector.main(SimplePerfCollector.java:17)

性能数据收集AOP

上一节中的性能数据收集虽然比较简单，但是需要手动的向代码中添加很多代码，侵入性比较大，一旦某天因为各种原因需要将它们移除会有很大的代码改动，另外对那些没有源码的方法来说无法添加这些代码，因而perf4j提供了AOP方式的性能收集方式。perf4j采用AspectJ库实现AOP，AspectJ支持运行时和编译时的AOP织入（weaver），perf4j同时支持这两种方式。另外perf4j还支持Spring中代理方式的AOP。

在perf4j目前只实现了注解方式的AOP织入，因而对所有想要打印性能数据的方法需要添加@Profiled注解，它可以用于方法或构造函数之上：

@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD, ElementType.CONSTRUCTOR})
public @interface Profiled {
    String message() default "";
    String level() default "INFO";
    boolean el() default true;
    boolean logFailuresSeparately() default false;
    long timeThreshold() default 0;
    boolean normalAndSlowSuffixesEnabled() default false;
}

@Profiled注解除了支持所有XXStopWatch的所有属性外，它还支持区分方法执行成功还是抛出异常(logFailuresSeparately, <tag>.success, <tag>.failure)以及对tag和message值的EL(Expression Language，Apache Commons JEXL语法)解析，且默认该解析为ON。这里的EL可以作用于方法的参数（$0, $1, $2…）、调用该方法的类（$this，静态方法该值为null）、方法的返回值（$return，方法返回void或抛异常时该值为null）、方法抛出的异常（$exception，方法正常返回时该值为null）。如文档中的例子：

@Profiled(tag = "servlet{$this.servletName}_{$0.pathInfo}")

有了@Profiled注解的方法以后，在运行时加载或编译时，AspectJ会根据perf4j中实现的TimingAspect将性能收集代码织入。perf4j不同包中定义的TimingAspect只是一个工厂类的角色，它用于创建相应功能的XXStopWatch，而主要实现在AbstractTimingAspect中。该类定义了一个@Around类型的PointCut，它作用与所有带@Profiled注解的方法，并传入ProceedingJointPoint和@Profiled参数：

@Around(value = "execution(* *(..)) && @annotation(profiled)", argNames = "pjp,profiled")

该PointCut的实现使用子工厂类创建相应的XXStopWatch实力，然后调用AgnosticTimingAspect的runProfiledMethod，该方法的实现也比较简单：在方法调用前配置StopWatch实力，方法调用结束后根据方法参数、返回值、抛出的异常使用Apache Commons JEXL语法解析出tag和message，然后调用StopWatch的stop方法（内部自动使用当前的Log框架输出log日志）。

然而有了这些@Profiled注解的方法以后，如何将TimingAspect织入这些方法中呢？首先从运行时动态加载说起：运行时织入首先在项目的META-INF目录中添加aop.xml文件，内容为（官方文档中AspectJ的版本为1.6.1，我在使用这个版本时不识别profiled注解，然后如果使用1.7.x以后的办班，绿色那个配置是必须的，不然会出现NoSuchMethod的错：java.lang.NoSuchMethodError: org.perf4j.log4j.aop.TimingAspect.aspectOf()Lorg/perf4j/log4j/aop/TimingAspect; 黄色部分用于调试，在实际运行时可以去除，不然会有一些干扰性的输出。）：

<!DOCTYPE aspectj PUBLIC "-//AspectJ//DTD//EN" "http://www.eclipse.org/aspectj/dtd/aspectj.dtd">
<aspectj>
  <aspects>
    <aspect name="org.perf4j.log4j.aop.TimingAspect"/>
  </aspects>
  <weaver options="-verbose -showWeaveInfo">
    
    <include within="org.perf4j.log4j.aop.TimingAspect" />
    <include within="levin.learn.perf4j.*" />
  </weaver>
</aspectj>

并且在运行时要配置-javaagent参数：-javaagent:libs/aspectjweaver-1.8.5.jar以实现类加载时动态织入。

对编译时织入比较简单，你只需要perf4j-0.9.16-log4jonly.jar而不是perf4j-0.9.16.jar，否则你的类会被织入多个Aspect；然后使用AspectJ编译器（ajc）编译即可，在编译时需要aspectjrt.jar包依赖。对于maven编译可以使用aspectj-maven-plugin：

<plugin>
  <groupId>org.codehaus.mojo</groupId>
  <artifactId>aspectj-maven-plugin</artifactId>
  <version>1.7</version>
  <configuration>
    <complianceLevel>1.7</complianceLevel>
    <showWeaveInfo>true</showWeaveInfo>
    <verbose>true</verbose>
    <weaveDependencies>
      <dependency>
        <groupId>org.perf4j</groupId>
        <artifactId>perf4j</artifactId>
        <classifier>slf4jonly</classifier>
      </dependency>
    </weaveDependencies>
  </configuration>
  <dependencies>
    <dependency>
      <groupId>org.aspectj</groupId>
      <artifactId>aspectjtools</artifactId>
      <version>${aspectj.version}</version>
    </dependency>
  </dependencies>
  <executions>
    <execution>
      <goals>
        <goal>compile</goal>
        <goal>test-compile</goal>
      </goals>
    </execution>
  </executions>
</plugin>

对于Spring的Proxy方式AOP织入属于比较常见的用法，这里不再赘述，可以参考官网的文档，应该可以用。

性能数据分析

在使用perf4j收集到性能数据后，接下来就要对这些数据进行分析，不然这些数据本身并没有多少用处。perf4j提供了一个简单的分析类LogParser来做这个工作。可以使用命令行方式对日至文件分析：
java -jar /Users/dinglevin/.m2/repository/org/perf4j/perf4j/0.9.16/perf4j-0.9.16.jar -t 300000 perf4j-sample.log
输出结果（-t 300000表示每5分钟统计一次）：

Tag Avg(ms)         Min         Max     Std Dev       Count
dynamicTag_iIsEven                                     513.4          23         957       236.3          24
dynamicTag_iIsOdd                                      552.3         100         937       272.4          24
failuresSeparatelyExample.failure   635.8         138         946       222.7          23
failuresSeparatelyExample.success   433.8          21         903       271.4          24
loggerExample 487.0          25         957       293.3          47
messageExample 746.9          34        1912       500.9          47
simpleBlock 467.7          14         951       307.9          48
simpleExample 533.0           1         995       306.1          48

或者使用tail命令实时分析：
tail -f perf4j-sample.log | java -jar /Users/dinglevin/.m2/repository/org/perf4j/perf4j/0.9.16/perf4j-0.9.16.jar
LogParser的具体使用方法如它自己所描述：

Usage: LogParser [-o|--out|--output outputFile] [-g|--graph graphingOutput-File] [-t|--timeslice timeslice] [-r] [-f|--format text|csv] [logInputFile]
Arguments:
  logInputFile - The log file to be parsed. If not specified, log data is read from stdin.
  -o|--out|--output outputFile - The file where generated statistics should be written. If not specified, statistics are written to stdout.
  -g|--graph graphingOutputFile - The file where generated perf graphs should be written. If not specified, no graphs are written.
  -t|--timeslice timeslice - The length of time (in ms) of each timeslice for which statistics should be generated. Defaults to 30000 ms.
  -r - Whether or not statistics rollups should be generated. If not specified, rollups are not generated.
  -f|--format text|csv - The format for the statistics output, either plain text or CSV. Defaults to text.
                         If format is csv, then the columns output are tag, start, stop, mean, min, max, stddev, and count.

Note that out, stdout, err and stderr can be used as aliases to the standard output streams when specifying output files.

这里的图片输出采用Google Chart API，该API使用URL将数据上传给Google服务器，然后Google会将它们转换成PNG图片返回，但是大家都懂的Google已经被天朝封了，因而这个功能没法使用（不知道会不会有足够的时间，不然打算使用jung实现一个类似的功能），不想周末去公司，因而贴一张来自官网的结果图：

对Google Chart API有兴趣的可以阅读这里：http://www.haijd.net/archive/computer/google/google_chart_api/api.html。

在LogParser的实现中，LogParser类本身主要用于解析传入的参数，然后使用parseLog()方法处理所有逻辑，在该方法中它将日志文件的解析代理给StopWatchLogIterator类，该Iterator使用StopWatchParser解析每一行日志，它只是简单的采用正则表达式匹配性能日志（start\\[(\\d+)\\] time\\[(\\d+)\\] tag\\[(.*?)\\](?: message\\[(.*?)\\])?）；将相同tag的性能日志组合代理给GroupingStatisticsIterator，该Iterator生成给定时间间隔内的tag到TimingStatistcs的Map，其中TimingStatistics纪录了该时间间隔内时间消耗的最小值、最大值、平均值、标准方差等；将输出格式代理给GroupedTimingStatisticsFormatter，它支持text和csv两种格式；最后将Chart输出代理给StatisticsChartGenerator，默认实现采用GoogleStatisticsChartGenerator。

Log4J实时性能数据分析

perf4j还提供了几个Log4J的Appender实现用于实时的性能数据分析，可以输出txt、csv、png等格式的分析数据：AsyncCoalescingStatisticsAppender，它主要用于配置实时统计时使用的参数，如timeSlice、createRollupStatistics、downStreamLogLevel、queueSize等，以及内部实际Appender，并且提供了StatisticsCsvLayout类以输出csv格式的文件。这里之所以要用Async方式是为了减少该Appender对实际性能的影响，该Appender只是做一些简单的检查，然后将消息添加到内部Queue中，由一个Daemon线程处理这个Queue并做统计信息。

<appender name="CoalescingStatistics"
          class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">
    
    <param name="TimeSlice" value="10000"/>
    <appender-ref ref="fileAppender"/>
</appender>


<appender name="fileAppender" class="org.apache.log4j.FileAppender">
    <param name="File" value="logs/perfStats.log"/>
    <layout class="org.perf4j.log4j.StatisticsCsvLayout">
        <param name="Columns" value="tag,start,stop,mean,count,tps"/>
    </layout>
</appender>



<logger name="org.perf4j.TimingLogger" additivity="false">
    <level value="INFO"/>
    <appender-ref ref="CoalescingStatistics"/>
</logger>

也可以向AsyncCoalescingStatisticsAppender添加GraphingStatisticsAppender以实现Google Chart方式的输出，GraphingStatisticsAppender用于生成Google Chart API格式的数据，而实际输出由内部包含的Appender决定：

<appender name="graphExecutionTimes"
          class="org.perf4j.log4j.GraphingStatisticsAppender">
    
    <param name="GraphType" value="Mean"/>
    
    <param name="TagNamesToGraph" value="firstBlock,secondBlock"/>
    <appender-ref ref="graphsFileAppender"/>
</appender>


<appender name="graphExecutionTPS"
          class="org.perf4j.log4j.GraphingStatisticsAppender">
    <param name="GraphType" value="TPS"/>
    <param name="TagNamesToGraph" value="firstBlock,secondBlock"/>
    <appender-ref ref="graphsFileAppender"/>
</appender>


<appender name="graphsFileAppender" class="org.apache.log4j.FileAppender">
    <param name="File" value="logs/perfGraphs.log"/>
    <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%m%n"/>
    </layout>
</appender>

所有定义的GraphingStatisticsAppender可以通过暴露GraphingServlet获取信息。

最后perf4j还提供JMX方式的性能统计数据处理与获取，首先在AsyncCoalescingStatisticsAppender中定义一个JmxAttributeStatisticsAppender，该Appender注册StatisticsExposingMBean，并实时更新该MBean性能统计数据以供其他管理程序查询或设置阀值而主动发送JMX Notification。JMX的Notification机制好像用的不多，因而不再详述。

参考

1. perf4j源码（0.9.16）

2. http://perf4j.codehaus.org/devguide.html#Perf4J_Developer_Guide

3. http://www.infoq.com/articles/perf4j#.VTHH4dZ8WVc.sinaweibo

部分事例代码可以从这里找到：
https://github.com/dinglevin/levin-learn/tree/master/levin-learn-perf4j

posted on 2015-04-19 13:35 DLevin 阅读(7764) 评论(1) 编辑收藏所属分类: 深入源码

常用链接

留言簿(4)

随笔分类(157)

随笔档案(125)

收藏夹(13)

Java GC

Java General

NoSQL

Tech General

Tech Master

最新随笔

搜索

积分与排名

最新评论

阅读排行榜

评论排行榜

前言

性能数据收集

性能数据收集AOP

性能数据分析

Log4J实时性能数据分析

参考


只有注册用户登录后才能发表评论。




网站导航: 博客园 IT新闻知识库 C++博客博问管理
相关文章: 深入perf4j源码深入ASM源码之ClassReader、ClassVisitor、ClassWriter