Perf4J介绍及使用、集成

程序员文章站 2022-06-13 14:33:58

...

1.Perf4J简述

Perf4J 是一个新的开放源码的性能记录，监测和分析库，主要用于企业Java应用程序。与之类似，为我们所熟悉的的是log4j。

Perf4J的重点功能：

1）一个简单的秒表计时机制，对timing进行简洁的声明。

2）一个命令行工具用来分析日志文件，并生成汇总统计和性能图表。。

3）易于与常见的记录框架和facades集成：log4j, java.util.logging, Apache Commons Logging和SLF4J。

4）在运行时自定义log4j appender 产生统计数据和图表。

5）揭露性能统计，作为JMX的属性，并在统计超出指定值时发出通知。

6）一个控制器，在Web应用中揭露性能图表。

7）可扩展。

2.应用场景

项目研发过程中常常发现在花费了大量时间确保应用程序在开发环境中快速和灵活之后，在发布到生产环境的时候性能会不可思议的大幅下降。因此，详细的日志记录和分析对于追踪这些间歇性的性能瓶颈尤为重要。

典型Web 2.0风格应用的服务器端的常见场景：

l 服务器接收一个Web请求，分发给负责产生响应的组件。

l 该请求也许需要通过LDAP服务器进行安全验证。

l 控制器组件对数据库执行查询。

l 控制器组件也会调用第三方Web服务。

l 控制器组件将所有获得的数据进行汇总，组成一系列业务对象用于显示。

l 业务对象被展现，响应内容传回用户浏览器。

l 运行于浏览器的AJAX代码产生其他的请求，与服务器端交互。

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

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

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

我们可以回忆一下，初学Java语言调试代码时，我们使用System.out.println()这种简陋的调试器，利用这种快捷但糟糕的方式记录信息，但这远远不够。

有时要把记录语句输出到专门的一个或多个日志文件中，可以每天覆盖日志。需要能够设定重要性的不同级别以输出不用的日志语句，可以选择在不改变代码的情况下在特定环境下只输出特定日志，或者在不同环境中改变日志格式。因此，log4j提供的丰富功能来源于原始想法，是一种“更好的 ”System.out.println()日志语句。

与之类似，当需要在Java代码中添加性能监控代码时，初始时经常这样做：

long start = System.currentTimeMillis();

log.info("ms for block n was: " + (System.currentTimeMillis() - start));

这种方式的缺点是：

1、这种方式输出内容比较单一，就是代码总的运行时间。但是我们代码需要查看的性能指标有更多，比如总的平均值，最小值，最大值，tps等等。

2、也许我们的代码在线上运行，我们想把这些值通过图表的形式展示出来。或者把这些内容通过jmx输出。

3、另外，我们可能把perf4j跟log4j，slf4j等日志框架和日志门面系统整合起来。

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

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

Perf4J的特点包括：

l 简洁的 stop watch计时机制。

l 提供命令行工具，从原始的日志文件中生成汇总的统计数据和性能图表。

l 定制的log4j appender，可以在运行时应用中生成数据和图表，计划在以后的版本中支持java.util.logging和logback。

l 能够以JMX属性的形式发布性能数据，在数据超过指定阈值时发送通知。

l 提供@Profiled注解和一套自定义机制，允许在与AOP框架（如AspectJ或者Spring AOP）集成时巧妙的计时。

3.应用实例

1)利用StopWatch类开发计时代码。

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

StopWatch stopWatch = new LoggingStopWatch();

//code

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]

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

stop watch输出比System.currentTimeMillis()有很大的改进，但更大的好处在于能够解析这些输出以生成统计数据和图表。LogParser通过tag和时间片把stop watch输出分组，生成详细的统计信息和可选的时间序列图（使用Google Chart API）。

3)集成Log4J

Perf4J的扩展功能通过一套定制的log4j appender提供。

开发人员可以在部署阶段通过日志框架来零零散散的添加分析和监控功能。其中一个重要的功能是允许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/">

<!--

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.

-->

<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.

-->

</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 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).

-->

</appender>

<appender-ref ref="CoalescingStatistics"/>

</logger>

<!--

The root logger sends all log statements EXCEPT those sent to the perf4j

logger to System.out.

-->

<root>

</appender>

</root>

</log4j:configuration>

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

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

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

@Profiled(tag = "dynamicTag_{$0}")

public void profiledExample(String tagSuffix) {

//code

}

在项目中使用Perf4J的最简便的方法就是直接在任何一个需要监控的方法上加上@Profiled 注释即可。

@Profiled 支持一些定制，在此记录几种@Profiled 写法：

1、最简写法

Java代码

@Profiled

由此产生的日志语句形如：

2013-04-07 14:37:23,734 [main] INFO org.perf4j.TimingLogger - start[开始时间] time[执行耗时] tag[方法名]

2、带logger标识

@Profiled(logger = "test.PriceService")

由此产生的日志语句形如：

2013-04-07 14:37:23,734 [main] INFO test.PriceService - start[开始时间] time[执行耗时] tag[方法名]

说明：不加该标识，则所有的日志类名均为 org.perf4j.TimingLogger ，当2个类中的方法重名时，无法区分是哪个方法。

3、带tag标识

@Profiled(tag = "search({$0},{$1},{$2})")

由此产生的日志语句形如：

2013-04-07 14:37:23,734 [main] INFO org.perf4j.TimingLogger - start[开始时间] time[执行耗时] tag[search(a,b,c)]

说明：当方法有参数时，可以通过{$x}输出参数值，当参数为一个对象时，可以通过{$x.属性}的方式法输出对象的属性值；

tag标识支持JEXL表达式。

4、带message标识

@Profiled(massage= "测试")

由此产生的日志语句形如：

2013-04-07 14:37:23,734 [main] INFO org.perf4j.TimingLogger - start[开始时间] time[执行耗时] tag[方法名] message[测试]

说明：message的作用即可以在输出的内容后加上任何自定义的内容。

5、带logFailuresSeparately标识

@Profiled(logFailuresSeparately= true)

由此产生的日志语句形如：

2013-04-07 14:37:23,734 [main] INFO org.perf4j.TimingLogger - start[开始时间] time[执行耗时] tag[方法名.failure]

说明：加上此标识，会输出方法执行结果，成功时为方法名.success ，当方法执行中出现异常时为方法名.failure。

4.Web实例

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

如下是基于Web的质数生成器的实例，展示创建一个使用Perf4J库大多数功能的真实应用。

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

在primes.jsp创建Log4JStopWatch统计整个页面的生成时间。

PrimeNumberGenerator.generatePrime()方法具有一个Profiled注解。

PrimeNumberGenerator.randomFromRandomDotOrg()也含有Profiled注解。

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

所有单独的stop watch日志都被写入标准输出（请注意你的servlet容器可能把标准输出定向到磁盘的某个文件中）。如果需要的话，你可以直接使用LogParser。

AsyncCoalescingStatisticsAppender被创建以汇总stop watch日志并传递给下游的GraphingStatisticsAppenders和JmxAttributeStatisticsAppender。

两个GraphingStatisticsAppender被创建，其中一个表示平均执行时间，另一个输出每秒事务数。

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

在生成大量质数之后，你可以通过三种途径来查看Perf4J输出：

1)原始的标准输出日志。

通过http://servername/<rootContextLocation>/perf4jGraphs访问图形化Servlet。你应该能够看到平均执行时间和每秒事务数。

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，同时又将副作用降到最低：

在判断需要分析哪些方法和代码块时，首先把重点放在关键点上。在企业应用中，每当遇到性能瓶颈时，都会存在很多“通常的疑点”：数据库调用、运程方法调用、磁盘I/O、针对大型数据集的计算操作。因此，你应该首先集中分析这些类型的操作。同时，因为这些操作花费几十甚至几百毫秒的时间，Perf4J所带来的额外开销相对于本地执行时间来说微不足道，在实践中可以忽略不计。事实上，这也是Perf4J故意使用System.currentTimeMillis（而不是System.nanoTime）计时代码块的原因之一：纳秒的粒度在这种企业应用代码块中意义并不大。

Perf4J把性能分析的工作委托给独立的线程或者进程。当使用AsyncCoalescingStatisticsAppender时，执行线程把日志事件推入到一个内存中的队列，由另外一个独立的线程发送这些日志消息到下游appender。因此，即使那些下游appender做了大量敏感的工作，如建立图表、更新MBean属性或者存储到数据库中，对计时的代码块的影响微乎其微，而且与这些下游appender做的工作多少无关。类似的，当把计时日志写入文件用于解析和分析时（例如，使用Unix tail命令），对于计时进程的影响也只与它写日志所花费的时间有关，与log分析器的时间无关。

不要忘记性能回归测试的好处。除了监测运行时的性能瓶颈，Perf4J非常适合创建性能回归测试以判断代码更改是否对性能有显著影响（不论是积极或消极的）。通过创建一个原始代码的基准，你很快就能发现新代码对性能产生了何种影响。

利用@Profiled注解和AspectJ的加载时编织来决定哪些方法应该在部署时计时。如果使用了 @Profiled 注解，你可以*的在方法调用周围添加计时，然后决定在使用AspectJ的aop.xml配置文件进行部署时需要对哪些方法进行计时。没有计时的方法不会被关注。虽然那些被计时的方法比直接在代码中使用StopWatches存在一些细微的额外开销（事实上AspectJ在计时方法的周围建立了一个闭包），这些开销相对于那些需要花费几毫秒的方法来说是微不足道的。

不要忘记应用程序中JVM之外执行的部分。举例来说，很多Web 2.0应用的大部分都是通过运行在客户端浏览器中的JavaScript实现，虽然Perf4J可以用于衡量运行在服务器端的方法（响应AJAX远程调用），但如果JavaScript执行性能下降，你仍然需要其他的客户端调试工具。

展望Perf4J

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

5. Maven中的使用

使用maven工程时，在pom文件中加入perf4j的依赖的方式如下：

<scope>compile</scope>

</dependency>

如果用的是普通工程，那么直接下载jar包放入lib目录下即可。

分析打印出来的日志文件

没有跟log4j集成时，日志文件打印在标准输出流，需要把标准输出流重定向到times.log文件中。重定向有两种方式：直接copy到文件中，或者在eclipse里指定下输出文件。用eclipse指定输出文件。

分析日志命令：

java -jar perf4j-0.9.16.jar times.log

集成

Perf4j最主要的一个好处就是可以跟log4j或者logback来性能分析和监控线上运行的程序。集成的方式主要是：自定义log4j的appenders通过标准的配置加入到log4j中去。

Perf4j最重要的appender就是AsyncCoalescingStatisticsAppender，它会把一段时间内StopWatch的信息汇总到一个独立的GroupedTimingStatistics日志信息，然后把这个独立的信息传给下游的appenders，比如fileappenders，这样就可以写到文件中去了。也可以传给per4j的其他自定义appenders。

但要使用AsyncCoalescingStatisticsAppender就只能使用xml文件而不能使用properties文件。

<?xml version="1.0" encoding="UTF-8" ?>

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

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

</layout>

</appender>

<!--

AsyncCoalescingStatisticsAppender收集StopWatch的日志信息并传送到下游的文件appenders。

-->

<appender name="CoalescingStatistics"

class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">

<!--

TimeSlice配置多少时间间隔去做一次汇总写入文件中

默认值是 30000 ms

-->

<appender-ref ref="fileAppender"/>

</appender>

</layout>

</appender>

<!--

配置perf4j logger

Additivity设置成false主要因为是不想让代码运行时间的日志输出给上游appenders，即不要在控制台输出。

-->

<appender-ref ref="CoalescingStatistics"/>

</logger>

<!--

Root logger打印所有日志，但不包含perf4j的信息。原因是在TimingLogger配置中设置了additivity为false

-->

<root>

<appender-ref ref="console"/>

</root>

</log4j:configuration>

可以以汇总形式查看日志，也可以通过图表来查看。Perf4j跟log4j集成后，其实也可以以图表的形式来查看性能状况。

log4j.xml的配置是在配置中加入了图表的配置：

<appender name="graphExecutionTimes"

class="org.perf4j.log4j.GraphingStatisticsAppender">

<appender-ref ref="graphsFileAppender"/>

</appender>

<appender name="graphExecutionTPS"

class="org.perf4j.log4j.GraphingStatisticsAppender">

<appender-ref ref="graphsFileAppender"/>

</appender>

</layout>

</appender>

另外还需要改一个地方，就是CoalescingStatistics的配置：

<appender name="CoalescingStatistics"

class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">

<!--

TimeSlice配置多少时间间隔去做一次汇总写入文件中

默认值是 30000 ms

-->

<appender-ref ref="fileAppender"/>

<appender-ref ref="graphExecutionTimes"/>

<appender-ref ref="graphExecutionTPS"/>

</appender>

黄色那段配置的意思就是把日志写入到图表日志去。

上面这种方式需要自己登录到服务器上，找到log文件，在放到浏览器中查看，总的过程还是比较麻烦。如果需要监控的工程是一个web工程的话，那就更方便了，直接配置一个servlet来查看。Web.xml的配置如下：

<!DOCTYPE web-app PUBLIC

"-//Sun Microsystems, Inc.//DTD Web Application 2.3//EN"

"http://java.sun.com/dtd/web-app_2_3.dtd" >

<web-app>

<display-name>Archetype Created Web Application</display-name>

<servlet-name>perf4j</servlet-name>

<servlet-class>org.perf4j.log4j.servlet.GraphingServlet</servlet-class>

<init-param>

<param-name>graphNames</param-name>

<param-value>graphExecutionTimes,graphExecutionTPS</param-value>

</init-param>

</servlet>

<servlet-mapping>

<servlet-name>perf4j</servlet-name>

<url-pattern>/perf4j</url-pattern>

</servlet-mapping>

</web-app>

可以打包工程，并放到web服务器下启动，然后访问下/perf4j这个uri。

Maven有一个jetty插件，可以方便启动web工程，只要大家在pom.xml文件中加入如下配置：

<groupId>org.mortbay.jetty</groupId>

<artifactId>jetty-maven-plugin</artifactId>

</plugin>

</plugins>

在控制台中输入：mvn jetty:run，即可。省去了打包发布，很省心喔。

第一次用http://localhost:8080/perf4j访问查看图表的时候没有生成任何东西，那是因为内存中没有收集到最新的性能数据。所以我在index.jsp里调用下以便产生性能数据。然后重新访问，这个时候就有图表生成了。

参考文献：

英文原文：Performance Analysis and Monitoring with Perf4J。

http://www.infoq.com/cn/articles/perf4j

http://coffeelover.iteye.com/blog/464063

Perf4J介绍及使用、集成

jquery delay（）介绍及使用指南

oracle的decode()含义及使用介绍

西瓜影音安装使用及西瓜影音播放器查找和下载视频的方法介绍

uc答题助手入口在哪里?uc答题助手网页版入口及使用方法介绍

EL表达式及其11个使用对象（及jsp中的对象）实例介绍

闪电下载FlashGet(网际快车)功能介绍及使用说明教程

怎样正确使用、安全退出U盘?正确使用U盘的7个重要注意事项及方法介绍

搜狐影音及搜狐影音中的一些小技巧使用介绍

ATX安装步骤及简单使用介绍

jquery append()方法教程与html()方法教程的区别及使用介绍