Perf4J

1 Overview
    Perf4j是一个用于计算和显示性能相关的统计信息（例如最大值、最小值、算数平均均值、标准方差和TPS等）的工具集。除了将统计信息输出到标准错误流或者日志中之外，Perf4j也支持输出为图表（使用Google Chart API），以及通过JMX公开。其主要的功能如下：

• 以StopWatch这种简洁的方式进行计时。
• 提供了一个命令行工具，用于分析日志以及生成统计信息或图表。
• 易于集成到大部分已有的日志工具中，例如log4j, java.util.logging, Apache Commons Logging and SLF4J。
• 提供了定制的log4j appenders用于实时地生成统计信息。
• 支持以JMX的方式公开统计信息，在特定的统计信息超过指定阀值时可以发送通知。
• 提供了一个servlet，用于在web应用中以图表的形式显示统计信息。
• 支持以AOP的方式进行计时。

    以下是个使用Perf4j的简单的例子：

StopWatch stopWatch = new Log4JStopWatch("tag0");
Thread.sleep(1000L);
stopWatch.stop();

    需要注意的是这里的StopWatch不是Jakarta Commons的StopWatch。目前比较流行的Slf4j的扩展包中也包含个StopWatch。Slf4j的扩展包中同样也提供了基本的profiling功能（笔者感觉比Perf4j还要全面一些），但是目前Slf4j还不支持生成统计信息。

 

    以上的代码执行后会在日志中打印如下的信息：

    2009-06-11 20:46:59,833 INFO  [main - Log4JStopWatch.java:304] start[1244724418833] time[1000] tag[tag0]

    其中与start对应的方括号中的内容是StopWatch在构造时的系统时间（毫秒数）。与time对应的方括号中的内容是调用其stop方法前经过的时间（毫秒数）。与tag对应的方括号中的内容是构造StopWatch时指定的标签名。

 

    如果使用org.perf4j.LoggingStopWatch，那么会在标准错误流中输出如下的信息：
    start[1244724581786] time[1000] tag[tag0]

    除了指定标签名之外，也可以指定一个可选的消息。例如：

StopWatch stopWatch = new LoggingStopWatch();
try {
   ...
    stopWatch.stop("tag0.success", "normal case");
} catch (Exception e) {
    stopWatch.stop("tag0.failure", "exceptional case");
}

 

 

2 Generating Performance Statistics
    Perf4j提供了LogParser用于分析日志以生成统计信息。假设terminal.log日志中的内容如下：
    start[1244726067645] time[297] tag[tag1]
    start[1244726067958] time[546] tag[tag1]
    start[1244726068504] time[454] tag[tag1]
    start[1244726068989] time[219] tag[tag1]
    start[1244726069208] time[125] tag[tag1]
    start[1244726069333] time[500] tag[tag1]
    start[1244726069833] time[859] tag[tag1]
    start[1244726070692] time[422] tag[tag1]
    start[1244726071114] time[62] tag[tag1]
    start[1244726071176] time[875] tag[tag1]

 

    在命令行上执行java -jar perf4j-0.9.10.jar terminal.log 后输出如下：
Performance Statistics   21:14:00 - 21:14:30  Tag    Avg(ms)    Min    Max    Std Dev    Count
                                                                         tag1 428.6        125    859    226.2       7

Performance Statistics   21:14:30 - 21:15:00  Tag    Avg(ms)    Min    Max     Std Dev    Count
                                                                         tag1 453.0          62    875      332.6      3

    以上的统计信息使用了默认的取样间隔，即30秒。Perf4j也支持以csv或者图表的方式输出统计信息，例如：
    java -jar perf4j-0.9.10.jar -f csv terminal.log
    java -jar perf4j-0.9.10.jar --graph perfGraphs.html terminal.log

 

 

3 Generating Read-Time Performance Statistics
3.1 Using LogParser
    如果没有指定日志文件，那么LogParser默认会从标准输入流中读取数据，因此可以使用tail命令和管道来生成实时的统计信息，例如：
    tail -f terminal.log | java -jar perf4j-0.9.10.jar
    此外如果使用Log4j，那么可以通过Log4j的SocketAppender等将日志发送到远程的机器后再进行日志的分析。Log4j的SocketAppender默认是将LoggingEvent序列化后发送到远程的机器。如果担心性能问题，那么可以考虑使用定制的消息和定制的序列化方式。笔者曾写过两个定制的SocketAppender（使用plain socket或者mina），可以减少一半以上的数据传输量。

3.2 Using Custom Appender
    目前Perf4j支持通过使用定制的Log4j appenders来生成实时的统计信息。其中最重要的appender是AsyncCoalescingStatisticsAppender。以下是个Log4j配置文件的例子：

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
  <appender name="console" class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d %-5p [%t - %F:%L] %m%n" />
    </layout>
  </appender>
  
  <appender name="CoalescingStatistics" class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">
    <param name="TimeSlice" value="2000"/>
    <appender-ref ref="console"/>
  </appender>
  
  <logger name="org.perf4j.TimingLogger" additivity="false">
    <level value="INFO"/>
    <appender-ref ref="CoalescingStatistics"/>
  </logger>
  
  <root>
    <level value="INFO"/>
    <appender-ref ref="console"/>
  </root>
</log4j:configuration>

    AsyncCoalescingStatisticsAppender的TimeSlice属性指定了统计的采样时间，默认是30秒。org.perf4j.TimingLogger的additivity属性指定了除了统计信息之外，原始的计时信息是否也要输出到日志中。

    应用程序的代码片段如下：

for(int i = 0; i < 10; i++) {
	StopWatch stopWatch = new Log4JStopWatch("tag1");
	Thread.sleep((long)(Math.random() * 1000L));
	stopWatch.stop();
}

 

    以下是日志中输出的内容：

2009-06-11 21:59:22,676 INFO [perf4j-async-stats-appender-sink-CoalescingStatistics - ?:?] Performance Statistics   21:59:20 - 21:59:22
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
tag1                                                   828.0         656        1000       172.0           2

2009-06-11 21:59:24,676 INFO  [perf4j-async-stats-appender-sink-CoalescingStatistics - ?:?] Performance Statistics   21:59:22 - 21:59:24
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
tag1                                                   515.8         172         954       331.4           4

 

3.3 Using JMX
    通过使用JmxAttributeStatisticsAppender，可以将统计信息公开为JMX MBeans。此外可以在统计信息超过指定阀值的时候发送notifications。以下是个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="console" class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d %-5p [%t - %F:%L] %m%n" />
    </layout>
  </appender>
  
  <appender name="CoalescingStatistics" class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">
    <param name="TimeSlice" value="2000"/>
    <appender-ref ref="jmxAppender"/>
  </appender>
  
  <appender name="jmxAppender" class="org.perf4j.log4j.JmxAttributeStatisticsAppender">
    <param name="TagNamesToExpose" value="tag1"/>
  </appender>

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

    Perf4j通过JMX公开的MBean的ObjectName是org.perf4j:type=StatisticsExposingMBean,name=Perf4J。

 

 

4 Unobtrusive Logging with @Profiled and AOP
    如果不希望在应用程序中加入LoggingStopWatch之类的计时语句，那么可以考虑使用Perf4j提供的@Profiled，当然还需要一个AOP的framework，例如AspectJ或者Spring AOP。以下是个使用Spring AOP的例子:

<?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"
       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">

    <aop:aspectj-autoproxy/>

    <bean id="timingAspect" class="org.perf4j.log4j.aop.TimingAspect"/>

    <bean id="primeGenerator" class="PrimeGenerator">
        <property name="currentPrime" value="13"/>
    </bean>
</beans>

 

    程序的代码片段如下：

public class PrimeGenerator {
    private BigInteger currentPrime = new BigInteger("0");

    public void setCurrentPrime(BigInteger currentPrime) {
        this.currentPrime = currentPrime;
    }

    @Profiled
    public BigInteger nextPrime() {
        currentPrime = currentPrime.nextProbablePrime();
        return currentPrime;
    }
    
    public static void main(String[] args) throws Exception {
        ApplicationContext applicationContext = new ClassPathXmlApplicationContext("classpath:spring.xml");
        PrimeGenerator pg = (PrimeGenerator) applicationContext.getBean("primeGenerator");
        pg.nextPrime();
    }
}

    日志中的输出如下：
    2009-06-11 22:52:11,833 INFO  [main - Log4JStopWatch.java:304] start[1244731931411] time[422] tag[nextPrime]