使用Perf4J进行性能分析和监控

作者 Alex Devine 译者 崔康

 

许多开发人员都很熟悉墨菲法则的一个例子：他们发现在花费了大量时间确保应用程序在开发环境中快速和灵活之后，在发布到生产环境的时候性能会不可思议的大幅下降。更糟糕的是，应用程序平时运行正常，老板或者重要客户操作应用的时候却反应缓慢。详细的日志记录和分析对于追踪这些间歇性的性能瓶颈尤为重要。

然而，当今世界充满了面向服务的架构和分布式的应用，查找性能瓶颈对应的组件极其困难。考虑一个典型Web 2.0风格应用的服务器端的常见场景：

1. 服务器接收一个Web请求，分发给负责产生响应的组件。
2. 该请求也许需要通过LDAP服务器进行安全验证。
3. 控制器组件对数据库执行查询。
4. 控制器组件也会调用第三方Web服务。
5. 控制器组件将所有获得的数据进行汇总，组成一系列业务对象用于显示。
6. 业务对象被展现，响应内容传回用户浏览器。
7. 运行于浏览器的AJAX代码产生其他的请求，与服务器端交互。

对于“为何我的网页反应迟钝？”这样问题的回答需要研究多个组件和执行路径，同时需要生产环境中所有应用组件的详细性能数据。

Perf4J是一款开源工具包，用于添加Java服务器端计时代码、记录日志和监控结果。对于熟悉诸如log4j日志框架的开发人员来说，可以这样类比：

Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()

如何利用这个类比理解Perf4J呢？回想一下过去还没有广泛应用Java日志记录框架的糟糕岁月，我们大多数人如何添加日志记录语句。我们使用System.out.println()作为一种“简陋的调试器”，利用这种快捷但糟糕的方式记录信息。我们很快意识到，这是不够的。我们希望把记录语句输出到专门的日志文件中（如果可能的话，多个不同文件），也许可以每天覆盖日志。我们需要能够设定重要性的不同级别以输出不用的日志语句，可以选择在不改变代码的情况下在特定环境下只输出特定日志，或者在不同环境中改变日志格式。因此，log4j提供的丰富功能来源于原始想法，是一种“更好的 ”System.out.println()日志语句。

类似的，当Java新手发现他们需要添加性能监控代码时，他们经常这样做：

long start = System.currentTimeMillis();
// execute the block of code to be timed
log.info("ms for block n was: " + (System.currentTimeMillis() - start));

但是很快，这些开发人员发现他们需要更多的信息，综合的性能统计数据如平均、最小、最大、标准差和特定时间段内每秒的事务处理量。他们希望将这些数据绘成实时图表监控运行服务器上的问题，或者通过JMX输出性能指标以便于启动监控器在性能下降的情况下发出警报。此外，他们还希望计时语句可以和类似 log4j的框架配合使用。

Perf4J的目标是通过易于集成（和扩展）的开源软件包提供这些功能。Per4J是由Homeaway.com开发的，其基础设施的分布式特性和网站的高可用性及性能需求需要深入的性能分析。Perf4J的特点包括：

• 简洁的 stop watch计时机制。
• 提供命令行工具，从原始的日志文件中生成汇总的统计数据和性能图表。
• 定制的log4j appender，可以在运行时应用中生成数据和图表，计划在以后的版本中支持java.util.logging和logback。
• 能够以JMX属性的形式发布性能数据，在数据超过指定阈值时发送通知。
• 提供@Profiled注解和一套自定义机制，允许在与AOP框架（如AspectJ或者Spring AOP）集成时巧妙的计时。

下面的例子展现了如何轻松利用这些功能。可以通过Perf4J开发人员指南来了解集成Perf4J的详细信息。

利用StopWatch类开发计时代码

org.perf4j.LoggingStopWatch类用于在代码中添加计时语句并打印到标准输出或者日志文件中：

StopWatch stopWatch = new LoggingStopWatch();
//... execute code here to be timed
stopWatch.stop("example1", "custom message text");	

对stop()方法的调用记录了执行时间并打印日志信息。默认情况下，基类LoggingStopWatch将输出打印到System.err流中。但是大多数情况下，你需要使用一个集成到现有Java日志框架（如Log4JStopWatch、CommonsLogStopWatch或者Slf4JStopWatch）的子类。下面是一些stop watch的输出示例：

start[1233364397765] time[499] tag[example1] message[custom message text]
start[1233364398264] time[556] tag[example1] message[custom message text]
start[1233364398820] time[698] tag[example1] message[custom message text]

使用LogParser创建统计数据和图表

虽然默认的stop watch输出相比直接调用System.currentTimeMillis()来说没有很大的改进，但真正的好处在于能够解析这些输出以生成统计数据和图表。LogParser通过tag和时间片把stop watch输出分组，生成详细的统计信息和可选的时间序列图（使用Google Chart API）。下面是一些使用默认文本格式（也支持csv格式）的示例输出：

Performance Statistics   20:32:00 - 20:32:30
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
codeBlock1                                             249.4           2         487       151.3          37
codeBlock2.failure                                     782.9         612         975       130.8          17
codeBlock2.success                                     260.7           6         500       159.5          20

Performance Statistics   20:32:30 - 20:33:00
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
codeBlock1                                             244.0           7         494       150.6          41
codeBlock2.failure                                     747.9         531         943       125.3          21
codeBlock2.success                                     224.1          26         398       106.8          21

Performance Statistics   20:33:00 - 20:33:30
Tag                                                  Avg(ms)         Min         Max     Std Dev       Count
codeBlock1                                             289.3          10         464       141.1          22
codeBlock2.failure                                     781.1         599         947       135.1           8
codeBlock2.success                                     316.2         115         490       112.6          13

平均执行时间和每秒事务处理量的图表以指向Google Chart Server的URL的形式生成。

同时，虽然LogParser默认从标准输入中读取数据，但是你也可以指定一个来自运行时服务器的日志文件，用LogParser实时输出：

tail -f performance.log | java -jar perf4j-0.9.8.1.jar	

集成Log4J

Perf4J的扩展功能大部分通过一套定制的log4j appender提供。这样开发人员就能在部署阶段通过非常熟悉的日志框架来零零散散的添加分析和监控功能（未来的Perf4J将提供定制logback appender和java.util.logging处理器）。其中一个重要的功能是允许Perf4J作为JMX MBeans的属性展示性能数据，同时在性能低于可接受的阈值时发送JMX通知。因为JMX已经成为处理和监控Java应用的标准接口，提供Perf4J MBean开启了广泛的由第三方监控应用提供的功能。举例来说，我们Homeaway的IT部门标准化了Nagios和Cacti用于系统监控，这两个工具都支持把MBeans作为数据源查询。

下面的log4j.xml文件示例显示了如何启用用于JMX的Perf4J appender：

<?xml version="1.0" encoding="UTF-8"  ?>
	<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">


	<log4j:configuration debug="false"  xmlns:log4j="http://jakarta.apache.org/log4j/">


	    <!-- Perf4J appenders -->
	    <!--
	      This AsyncCoalescingStatisticsAppender groups  StopWatch log messages
	      into GroupedTimingStatistics messages which it  sends on the
	      file appender and perf4jJmxAppender defined  below
	    -->
	    <appender name="CoalescingStatistics"
	               class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">
	        <!--
	          The TimeSlice option  means timing logs are aggregated every 10 secs.
	        -->
	        <param name="TimeSlice"  value="10000"/>
	        <appender-ref  ref="fileAppender"/>
	        <appender-ref  ref="perf4jJmxAppender"/>
	    </appender>


	    <!--
	      This file appender is used to output aggregated  performance statistics
	      in a format identical to that produced by the LogParser.
	    -->
	    <appender name="fileAppender"  class="org.apache.log4j.FileAppender">
	        <param name="File"  value="perfStats.log"/>
	        <layout  class="org.apache.log4j.PatternLayout">
	            <param  name="ConversionPattern" value="%m%n"/>
	        </layout>
	    </appender>


	    <!--
	      This JMX appender creates an MBean and publishes  it to the platform MBean
 server by
	      default.
	    -->
	    <appender name="perf4jJmxAppender"
class="org.perf4j.log4j.JmxAttributeStatisticsAppender">
	        <!-- The tag names whose  statistics should be exposed as MBean attributes. -->
	        <param name="TagNamesToExpose"  value="firstBlock,secondBlock"/>
	        <!--
	          The  NotificationThresholds param configures the sending of JMX notifications
	          when statistic values  exceed specified thresholds. This config states that
	          the firstBlock max value  should be between 0 and 800ms, and the secondBlock max
	          value should be less  than 1500 ms. You can also set thresholds on the Min,
	          Mean, StdDev, Count and  TPS statistics - e.g. firstBlockMean(<600).
	        -->
	        <param name="NotificationThresholds"  value="firstBlockMax(0-800),secondBlockMax(<1500)"/>
	    </appender>


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


	    <!--
	      The root logger sends all log statements EXCEPT  those sent to the perf4j
	      logger to System.out.
	    -->
	    <root>
	        <level  value="INFO"/>
	        <appender  name="console" class="org.apache.log4j.ConsoleAppender">
	            <layout  class="org.apache.log4j.SimpleLayout"/>
	        </appender>
	    </root>
	</log4j:configuration>

除了JMX插件，Perf4J也支持生成性能图表的画图appender，使用前端的Perf4J画图Servlet。定制的csv布局可以轻松的导入Excel或者其他电子表格应用。

使用@Profiled注解简化性能日志

在代码中增加性能记录语句（通常的日志语句）的一个缺点是降低了代码的“信噪比”，难以在特定代码块中遵循严格的业务逻辑。为了改善这一不足，Perf4J提供了@Profiled注解，可以添加在需要记录执行时间的方法上，允许方法本身不添加StopWatch代码：

@Profiled(tag = "dynamicTag_{$0}")
public void profiledExample(String tagSuffix) {
    ... business logic only here
}
	

一旦添加了@Profiled注解，Perf4J的计时切面会通过一个面向切面的编程框架如AspectJ或者Spring AOP启用。这个切面在方法调用周围加入建立和停止StopWatch实例的字节码。计时切面甚至可以有选择的使用AspectJ的加载时编织（load-time weaving）功能。因此，通过使用加载时编织你可以保证那些没有启用性能监控的方法绝没有额外的负担。

一个简单的示例：基于Web的质数生成器

本示例将带你感受如何创建一个使用Perf4J库大多数功能的真实应用。你可以下载perf4jPrimes.war文件，然后Servlet容器中运行它。在war包中也包含该应用的源代码。

一切从简，本例子只包含两个主要的代码文件：primes.jsp用于显示生成的质数和接受用户指定的参数，PrimeNumberGenerator类包含真正的生成代码（大部分委托给java.math.BigInteger类）。其中有三处使用了Perf4J计时代码块：

1. 在primes.jsp创建Log4JStopWatch统计整个页面的生成时间。
2. PrimeNumberGenerator.generatePrime()方法具有一个Profiled注解。
3. PrimeNumberGenerator.randomFromRandomDotOrg()也含有Profiled注解。

如果查看WEB-INF/classes/log4j.xml文件，你会看到启用了下面的Perf4功能：

1. 所有单独的stop watch日志都被写入标准输出（请注意你的servlet容器可能把标准输出定向到磁盘的某个文件中）。如果需要的话，你可以直接使用LogParser。
2. AsyncCoalescingStatisticsAppender被创建以汇总stop watch日志并传递给下游的GraphingStatisticsAppenders和JmxAttributeStatisticsAppender。
3. 两个GraphingStatisticsAppender被创建，其中一个表示平均执行时间，另一个输出每秒事务数。

一旦在Web服务器上启动了该Web应用，你就可以通过http://servername/<rootContextLocation>/primes.jsp访问质数生成页面，其中rootContextLocation由你的Web服务器配置决定（当然，为了方便，你也可以通过http://servername/<rootContextLocation>/PrimeNumberGenerator.java查看PrimeNumberGenerator源代码）。在primes.jsp页面中，你会看到很多用于质数生成的不同参数。你可以改变参数，然后点击“ 生成质数”按钮，看看这些参数是如何影响质数产生时间的。在生成大量质数之后，你可以通过三种途径来查看Perf4J输出：

1. 原始的标准输出日志。
2. 通过http://servername/<rootContextLocation>/perf4jGraphs访问图形化Servlet。你应该能够看到平均执行时间和每秒事务数。
3. JMX 监控也启用了。你可以通过Java SDK附带的jconsole应用查看Perf4J MBean值。这需要在启动Web服务器时，使用-Dcom.sun.management.jmxremote命令行参数。然后，如果在运行Web服务器的同一台机器上启动jconsole就可以在“MBeans”标签中看到 “org.perf4j.StatisticsExposingMBean.Perf4J”的数据值。

因为到现在为止你还没有启用任何TimingAspects支持@Profiled注解，你能够看到的唯一stop watch输出就是“fullPageGeneration”标记。如果要启用TimingAspects，你可以使用AspectJ加载时编织。你需要做的是，在启动Web服务器时使用AspectJ weaving代理命令行参数：

-javaagent:/path/to/aspectjweaver-1.6.1.jar

你可以在这里下载jar包：http://mirrors.ibiblio.org/pub/mirrors/maven2/org/aspectj/aspectjweaver/1.6.1/aspectjweaver-1.6.1.jar

当代理启用时，你可以在“generatePrime”和“randomFromRandomDotOrg”标记中看到stop watch的输出。

陷阱与最佳实践

很多监控应用的方法，不论是针对性能、稳定性还是语义正确性，都无法最有效的体现它们的意图。要么生成了太多的信息以至于难以分析这些数据，要么在需要信息的地方却得不到关键的数据。虽然所有的监控都需要一些额外的开销，但是性能监控应该对这些引入的开销格外小心。以下建议可以帮助你最大限度地利用 Perf4J，同时又将副作用降到最低：

1. 在判断需要分析哪些方法和代码块时，首先把重点放在关键点上。在企业应用中，每当遇到性能瓶颈时，都会存在很多“通常的疑点”：数据库调用、运程方法调用、磁盘I/O、针对大型数据集的计算操作。因此，你应该首先集中分析这些类型的操作。同时，因为这些操作花费几十甚至几百毫秒的时间，Perf4J所带来的额外开销相对于本地执行时间来说微不足道，在实践中可以忽略不计。事实上，这也是Perf4J故意使用System.currentTimeMillis（而不是System.nanoTime）计时代码块的原因之一：纳秒的粒度在这种企业应用代码块中意 义并不大。
2. Perf4J把性能分析的工作委托给独立的线程或者进程。当使用AsyncCoalescingStatisticsAppender时，执行线程把日志事件推入到一个内存中的队列，由另外一个独立的线程发送这些日志消息到下游appender。因此，即使那些下游appender做了大量敏感的工作，如建立图表、更新MBean属性或者存储到数据库中，对计时的代码块的影响微乎其微，而且与这些下游appender做的工作多少无关。类似的，当把计时日志写入文件用于解析和分析时（例如，使用Unix tail命令），对于计时进程的影响也只与它写日志所花费的时间有关，与log分析器的时间无关。
3. 不要忘记性能回归测试的好处。除了监测运行时的性能瓶颈，Perf4J非常适合创建性能回归测试以判断代码更改是否对性能有显著影响（不论是积极或消极的）。通过创建一个原始代码的基准，你很快就能发现新代码对性能产生了何种影响。
4. 利用@Profiled注解和AspectJ的加载时编织来决定哪些方法应该在部署时计时。如果使用了 @Profiled 注解，你可以自由的在方法调用周围添加计时，然后决定在使用AspectJ的aop.xml配置文件进行部署时需要对哪些方法进行计时。没有计时的方法不 会被关注。虽然那些被计时的方法比直接在代码中使用StopWatches存在一些细微的额外开销（事实上AspectJ在计时方法的周围建立了一个闭 包），这些开销相对于那些需要花费几毫秒的方法来说是微不足道的。
5. 不要忘记应用程序中JVM之外执行的部分。举例来说，很多Web 2.0应用的大部分都是通过运行在客户端浏览器中的JavaScript实现，虽然Perf4J可以用于衡量运行在服务器端的方法（响应AJAX远程调用），但如果JavaScript执行性能下降，你仍然需要其他的客户端调试工具。

展望Perf4J

Perf4J目前正在积极的发展，新的功能层出不穷。举例来说，凭借新版本的Perf4J，我们可以通过单独的配置文件指定要分析的方法，这样即使无法获得某些方法的源代码也可以对其进行计时。我们始终将用户的反馈和需求放在第一位，如果你想打造它未来的功能，那现在就来尝试Perf4J吧。更重要的是，Perf4J在Apache 2协议下完全开源，代码都充分文档化，你可以随意扩展。

现在就下载Perf4J吧，告诉我们你的想法！