用Perf4J进行性能分析与监测

当前位置：维客笔记>> 用Perf4J进行性能分析与监测 >> 正文

用Perf4J进行性能分析与监测

作者：Alex Devine 翻译：Smalt (梅春@互动百科)
(转载请注明出处)

这是一个许多开发者都熟悉的墨菲定律的具体的例子：在花费了大量的时间来确保应用程序在当前环境中是快速而且可伸缩之后，一发布到生产环境，性能就令人费解的直线暴降。甚至更糟糕的是，只有老板或重要客户在抱怨他们的业务运营总是象蜗牛爬一样，其实这个东西平时运行的挺快。当涉及到跟踪这些间歇性的性能瓶颈的时候，详细的日志和分析就变得至关重要。

然而，在广泛采用面相服务的架构(SOA)和分布式应用的当今世界，给负责响应的组件监测性能瓶颈变得极其困难。仔细考虑一下在相对常见的典型web2.0的应用下，服务器上都发生了什么：
·收到的一个web请求，被分发到负责响应的组件并生成响应。
·这个请求可能需要到一个LDAP服务器上进行权限认证。
·控制组件在数据库上进行几次查询。
·控制组件还调用了第三方Web service。
·控制组件把所有的检索数据聚合成了一套业务对象用于显示。
·业务对象被渲染并返回给用户浏览器。
·浏览器运行AJAX代码导致了有附加请求送回给服务器。

要回答“为什么我的网页这么慢”，需要调查多种组件和执行路径，以及生产环境中所有应用组件输出的详细性能数据。

Perf4J就是这样一个开源的工具，通过在Java服务端加入代码，给状态计时，并记录日志、分析和监控结果。对于熟悉日志框架(如log4j或者java.util.logging)的开发者同学，可以这样比喻和描述Perf4J：

Perf4J对于System.currentTimeMillis() 就像log4j 对于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的目标是用开源包的方式提供这些功能，并且容易集成、容易扩展。我们在Homeaway.com开发出Perf4J，我们的网站是广泛的分布式结构，它必须是高可用性高性能的，需要深入的性能分析。

一些Perf4J的特点

·用于计时的简单的stop watch机制。
·从原始日志文件生成聚合统计和性能图表的命令行工具
·可定制的log4j appenders(输出源)，可以在正在运行的应用中生成统计信息（随后还会支持java.util.logging和logback）
·可以用JMX属性的方式展现性能统计，并且当统计超出阀值时发出通知。
·在整合AOP框架(AspectJ或者Spring AOP)时，可以使用@Profiled注释和一套定制的切面很不起眼的加入计时语句。

下面给出的例子明示了你如何很容易的利用这些特性。
更多关于如何把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流。大多数情况下，尽管，你可能想继承LoggingStopWatch，生成一个子类，这个子类集成了某种流行的java日志框架或者日志外壳，变成Log4JStopWatch、CommonsLogStopWatch或者Slf4JStopWatch。下面是一些stopwatch输出的例子：

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]

用Log Parser创建统计和图表
因为默认stop watch不比直接调用System.currentTimeMillis()输出增长快很多，所以这样就能够分析这些输出来生成聚合统计和图表，真是不错啊。LogParser按照标签和时间片聚合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服务器生成平均执行时间和每秒事务数的图表：

而且，因为LogParser默认从标准输入读取，所以你可以从正在运行的服务器把日志文件用管道方式发给LogParser，让输出变成实时的：

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

直接集成Log4J
借助一套定制的log4j appenders，出现了很多Perf4J的扩展功能。这将允许开发者在开发的时候借助许多java开发都熟悉的日志框架添加分析和监控的小功能(未来Perf4J将支持定制的logback appenders和java.util.logging接口)。这么一个有价值的功能允许Perf4J通过JMX MBean来显示性能数据，当性能下降到低于可接受的值的时候发送JMX通知。由于JMX成了管理和监控java应用的标准接口，正说明了Perf4J MBean可以使用各式各样的第三方监控程序提供的功能。例如，在Homeaway，我们的IT部门在Nagios和Cacti上进行系统监控的标准化；这些工具支持把MBean当作一个数据域来查询。

下面的范例文件log4j.xml显示了如何为JMX开启Perf4J appenders：

    <?xml version="1.0" encoding="UTF-8" ?>
    <!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
    <log4j:configuration debug="false" xmlns:log4j=http://jakarta.apache.org/log4j/>
    
    
    <appender name="CoalescingStatistics"
                class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">
         
        <param name="TimeSlice" value="10000"/>
       <appender-ref ref="fileAppender"/>
        <appender-ref ref="perf4jJmxAppender"/>
</appender>
   
    <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>
    
    <appender name="perf4jJmxAppender"
        class="org.perf4j.log4j.JmxAttributeStatisticsAppender">
       
      <param name="TagNamesToExpose" value="firstBlock,secondBlock"/>
      
       <param name="NotificationThresholds" value="firstBlockMax(0-800),secondBlockMax(<1500)"/>
    </appender>
    
    
    <logger name="org.perf4j.TimingLogger" additivity="false">
        <level value="INFO"/>
        <appender-ref ref="CoalescingStatistics"/>
    </logger>
    
    <root>
        <level value="INFO"/>
        <appender name="console" class="org.apache.log4j.ConsoleAppender">
            <layout class="org.apache.log4j.SimpleLayout"/>
        </appender>
    </root>
</log4j:configuration>

除了JMX appender，Perf4J也提供生成性能图表的图形化appender，它可以通过Perf4J的graphing 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的装载时织入功能在特定的类运行时选择性的生效。因此，采用装载时织入的方式，丝毫不会因为那些没有开启profile的方法引起额外的系统开销。

一个简单的例子：一个基于web的Prime Number Generator(素数生成器)

这个例子带你一步步的创建一个实例，它用到了Perf4J库的大部分特性。你可以下载perf4jPrimes.war，自己在servlet容器中运行这个程序。注意这个war文件也包含用来创建应用程序的源代码。

简单起见，这个例子只包含两个主代码文件：primes.jsp，用来显示生成的素数和接受用户指定的参数，PrimeNumberGenerator类包含真正的生成代码(大部分情况下授权给了java.math.BigInteger类)。有3个地方用Perf4J来计时代码块：
·在primes.jsp的代码中创建一个Log4JStopWatch来给整个页面生成计时。
·PrimeNumberGenerator.generatePrime()方法中有一个@Profiled注解。
·PrimeNumberGenerator.randomFromRandomDotOrg()方法中也有一个@Profiled注解。

如果你查看WEB-INF/classes/log4j.xml，就会发现Perf4J可以使用这些功能：

所有单独的stop watch日志将被写到标准输出(注意：你的servlet容器可以将标准输出通过管道输出到硬盘上的文件)。如果愿意，你可以用LogParser直接处理这些输出。
已经创建了一个AsyncCoalescingStatisticsAppender来聚合stop watch日志，并把他们发送到下游的一组GraphingStatisticsAppenders和一个JmxAttributeStatisticsAppender。
已经创建了两个GraphingStatisticsAppenders，一个用来输出平均执行时间，一个用来输出每秒事务数。
一旦你在web服务器上启动了web应用，你可以访问素数生成页面：http://servername//primes.jsp，rootContextLocation取决于你的web服务器的配置(而且，为了便于访问，你可以查看PrimeNumberGenerator的源码：http://servername//PrimeNumberGenerator.java)。在primes.jsp页面上，你将看到若干不同的参数控制生成素数的方式。你可以修改这些参数，并点击"Generate Prime Number"按钮来看这些参数如何影响以及它花了多少时间去生成这些数。在生成了一坨数字以后，你应该可以看见Perf4J在三个地方输出：

原始日志输出被发送到标准输出。
图表servlet：http://servername//perf4jGraphs。访问它，你应该可以看到平均执行时间和每秒事务数图表。
还有JMX监控。你可以使用Java的SDK自带的Jconsole应用程序来查看Perf4J MBean的值。你需要用-D com.sun.management.jmxremote命令行方式，启动你的webserver。然后，如果你在正在运行的服务器上启动jconsole，你应该可以在MBeans这一栏看到"org.perf4j.StatisticsExposingMBean.Perf4J"的数据值。
因为这时你还没有开启任何TimingAspects(计时切面)来支持@Profiled注释，你看到的仅有的stop watch输出是关于"fullPageGeneration"标签的。你可以用AspectJ装载时织入来开启计时切面。你需要这样用AspectJ的织入代理命令行参数启动你的webserver：

-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的最大好处，来最小化任何非预期的影响：

当决策要profile注解什么方法或代码块的时候，请专注于最重要的大鱼。在企业级应用中，当遇到性能瓶颈的时候，有很多“惯犯”：数据库调用、远程方法调用、磁盘I/O，以及在巨大数据集上的重量级计算操作。因此，你在决定如何进行profile注解的时候，应该聚焦在这些类型的操作上。而且，因为这些典型操作花费数十到数百毫秒，Perf4J在这些操作上额外增加的开支比他们执行时间低好几个量级，在实用上可以忽略。事实上，这就是为什么Perf4J在给代码块计时上故意使用System.currentTimeMillis(而没有用System.nanoTime)的原因之一：在可能有问题的企业级应用的代码块上计时，根本不用纳秒级。
设计Perf4J是为了对独立的线程或进程进行性能分析。当使用AsyncCoalescingStatisticsAppender时，正在执行的线程将一个日志事件推送到内存里的队列，这个队列消耗了一个独立的线程来发送日志消息到下游的appender。因此，虽然那些下游appender做了大量密集的工作，比如创建图标或者更新MBean属性或者保存到数据库，在代码块上的影响确实爆低的并且和下游appender做的一坨工作都无关。类似的，当把计时日志写入到一个文件，以便稍候解析和分析(比如使用Unix的tail命令来查看)时，对被计时的进程的影响只和它写日志花去的时间相关，和日志分析无关。

不要忘记性能回归测试的好处。除实时的检测测性能瓶颈之外，Perf4J对创建性能回归测试非常有用，它可以确定代码的改变是否对性能有很大的影响(积极或消极)。用代码的最初版本创建一个基线，你可以很快的确定新版本对性能有什么样的影响。
利用@Profiled注解和AspectJ的装载时织入来判断部署的时候需要对哪些方法计时。如果你用@Profiled注解，你可以很容易的在方法调用周围添加计时注解，然后可以在你使用AspectJ的aop.xml配置文件时，决定实际上要对什么方法计时。但在结束时总有一次都没被执行的方法，它们将不能被计时。虽然这些被计时的方法比直接在代码里使用StopWatch开销略高一点(AspectJ其实是在被计时的方法外创建一个闭环)，这点额外的开销在方法至少执行几毫秒时应该仍然微不足道。

不要忘记你的那部分在JVM之外执行的应用。例如，非常多web2.0应用是以Javascript方式在客户的浏览器端执行的。虽然能用Perf4J来测量AJAX远程调用的服务器上的应答的方法，如果Javascript自己执行的很慢，你还是需要额外的客户端调试工具。

未来Perf4J的方向
Perf4J正积极开发以及频繁增加新功能。例如，未来Perf4J版本将允许你用一个独立的配置文件来指定要profile的方法，因此，甚至允许当你未访问源代码就可以对方法执行计时。所有功能都根据用户反馈和需要排优先级，所以如果你想决定Perf4J的未来，今天就试试它。更强的是Perf4J完全开源(用的是Apache2的license)，代码的注释非常完全，你可以对它随意扩展。

现在就下载Perf4J，让我们知道你觉得怎么样！
标签： Perf4J 性能监控翻译
打印导出Word 复制地址
评论：用Perf4J进行性能分析与监测

Smalt

2009-06-16 13:01:08

我顶。

Smalt

2009-09-27 00:46:16