perf 性能分析_Perf4J的性能分析和监控

perf 性能分析

这是许多开发人员都熟悉的墨菲定律的一个特殊示例：在花费大量时间确保应用程序在临时环境中快速且可扩展之后，性能在发布到生产环境时莫名其妙地下降。 更糟糕的是，通常情况下运行速度很快，除了老板或重要客户抱怨他们的业务似乎总是步履维艰之外。 在跟踪这些间歇性性能瓶颈时，详细的日志记录和分析至关重要。

但是，在当今面向服务的体系结构和广泛分布的应用程序世界中，检测导致性能瓶颈的组件可能非常困难。 考虑一下在典型的Web 2.0样式的应用程序的相对常见的情况下服务器上发生的情况：

1. 传入的Web请求被分派到负责生成响应的组件。
2. 该请求可能需要针对LDAP服务器进行身份验证。
3. 控制器组件对数据库进行查询。
4. 控制器组件还调用第三方Web服务。
5. 控制器组件将所有检索到的数据聚合到一组业务对象中以进行显示。
6. 呈现业务对象，并将响应发送到用户的浏览器。
7. 在浏览器中运行的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的目标是在易于集成（且易于扩展）的开源软件包中提供这些功能。 Perf4J是在Homeaway.com上开发的，该网站的基础设施分布广泛，我们网站的高可用性和性能要求也需要深入的性能分析。 Perf4J的一些亮点包括：

• 一个简单的秒表机制，用于简洁的计时语句。
• 用于从原始日志文件生成聚合统计信息和性能图的命令行工具。
• 自定义log4j附加程序，用于在运行的应用程序中生成统计信息和图形，并为后续发行版计划了java.util.logging和logback支持。
• 可以将性能统计信息公开为JMX属性，并在统计信息超过指定阈值时发送通知。
• @Profiled批注和一组自定义方面，当与AOP框架（如AspectJ或Spring AOP）结合使用时，可以使用不引人注意的时序声明。

下面给出的示例着重说明了如何不费吹灰之力就可以利用其中的某些功能。 有关如何将Perf4J集成到代码库中的更多详细信息，您将需要阅读《 Perf4J开发人员指南》 。

使用秒表计时代码块

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。 这是一些秒表输出示例：

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]

使用日志解析器创建统计信息和图形

尽管默认秒表输出与直接调用System.currentTimeMillis（）相比并没有太大的改进，但真正的好处是能够解析此输出以生成汇总的统计信息和图形。 LogParser组按标记和时间片停止监视输出，使用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附加程序获得。 这使开发人员可以在部署时通过许多Java开发人员熟悉的日志记录框架来逐步添加分析和监视功能（并且Perf4J的将来版本将提供自定义的logback附加程序和java.util.logging处理程序）。 一种如此有价值的功能使Perf4J可以将性能数据公开为JMX MBean上的属性，并在性能下降到可接受的阈值以下时发送JMX通知。 由于JMX已成为管理和监视Java应用程序的标准接口，因此公开Perf4J MBean可以打开第三方监视应用程序提供的广泛功能。 例如，在Homeaway，我们的IT部门已经对Nagios和Cacti进行了系统监控的标准化； 这两个工具都支持将MBean作为数据源进行查询。

下面的示例log4j.xml文件显示了如何为JMX启用Perf4J附加程序：

<?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还提供图形附加程序，这些附加程序生成性能图，可以使用Perf4J图形Servlet通过Web前端公开这些性能图。 自定义的csv布局可轻松导入Excel或其他电子表格程序。

使用@Profiled注释进行性能记录

在代码中添加性能日志记录语句（通常是日志记录语句）的缺点之一是，它会降低代码的“信噪比”，从而使遵循特定代码块的关键业务逻辑更加困难。 为了帮助减轻这种情况，Perf4J提供了@Profiled批注，可以将其添加到应记录其执行时间的方法中，从而使方法主体可以保留StopWatch代码：

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

添加@Profiled批注后，可以使用面向方面的编程框架（如AspectJ或Spring AOP）启用Perf4J自定义计时方面。 这方面的方法调用包含用于创建和停止StopWatch实例的字节码。 使用AspectJ的加载时编织功能，甚至可以在运行时在特定类上选择性地启用计时方面。 因此，通过使用加载时编织，对于那些未启用概要分析的方法，您绝对不会产生任何开销。

一个简单的例子：基于Web的素数生成器

本示例将引导您完成创建真实应用程序的步骤，以演示Perf4J库的大多数功能。 您可以通过下载perf4jPrimes.war文件并将其运行在servlet容器中来自己运行该应用程序 。 请注意，war文件还包含用于创建应用程序的源代码。

为简单起见，该示例仅包含两个主要代码文件：用于显示生成的素数并接受用户指定的参数的primes.jsp文件，以及包含实际生成代码的PrimePrimeGenerator类（大部分情况下， ，委托给java.math.BigInteger类）。 Perf4J在三个地方用来对代码块计时：

1. 将使用代码创建Log4JStopWatch，以在primes.jsp文件中计时整个页面的生成时间。
2. PrimeNumberGenerator.generatePrime（）方法具有Profiled注释。
3. PrimeNumberGenerator.randomFromRandomDotOrg（）方法还具有一个Profiled注释。

如果查看WEB-INF / classes / log4j.xml文件，可以看到已启用以下Perf4J功能：

1. 所有单独的秒表日志都将写入标准输出（请注意，您的Servlet容器可能会将标准输出传递到磁盘上的文件中）。 如果需要，您可以直接针对此输出使用LogParser。
2. 已创建一个AsyncCoalescingStatisticsAppender来聚合秒表日志，并将其发送到下游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。 通过单击此servlet，您应该能够看到平均执行时间和每秒事务数。
3. JMX监视也已启用。 您可以使用Java SDK随附的jconsole应用程序来查看Perf4J MBean值。 您将需要使用-Dcom.sun.management.jmxremote Java命令行选项启动Web服务器。 然后，如果在运行服务器的同一台计算机上启动jconsole，则应该能够在“ MBeans”选项卡下看到“ org.perf4j.StatisticsExposedMBean.Perf4J”数据值。

由于此时您尚未启用任何TimingAspects支持@Profiled批注，因此您唯一看到的秒表输出将是“ fullPageGeneration”标记的。 要启用TimingAspects，可以使用AspectJ加载时编织。 为此，您需要使用AspectJ编织代理命令行参数启动网络服务器，如下所示：

-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”标记名称的秒表输出。

陷阱和最佳实践

对于性能，稳定性或语义正确性的许多应用程序监视尝试都无法最佳地实现其预期的收益。 要么收集的信息太多，以至于很难遍历大量数据，要么在最需要的点收集了足够多的关键信息。 尽管所有监视都需要一定数量的开销，但是性能监视应该对其产生的额外开销特别敏感。 下面的提示应帮助您充分利用Perf4J，同时最大程度地减少意外影响：

1. 在决定分析哪些方法和代码块时，请首先关注大鱼。 在企业应用程序中，当遇到性能瓶颈时，会产生“通常的怀疑”：数据库调用，远程方法调用，磁盘I / O和对大数据集起作用的繁重的计算操作。 因此，在确定要概要分析的内容时，应重点关注这些类型的操作。 而且，由于这些操作通常需要数十到数百毫秒，因此Perf4J添加到这些操作的开销比本地执行时间小几个数量级，并且出于实际目的可以忽略。 实际上，这就是Perf4J故意在后台使用System.currentTimeMillis（而不是System.nanoTime）来对代码块进行计时的原因之一：在可能需要对企业应用程序中的代码块类型进行计时时，不需要纳秒粒度引起问题。
2. Perf4J旨在将性能分析卸载到单独的线程或进程中。 使用AsyncCoalescingStatisticsAppender时，执行线程将日志事件推送到内存队列中，该队列由单独的线程耗尽，该线程将日志消息发送到下游附加程序。 因此，即使这些下游附加程序做了很多密集的工作，例如创建图形或更新MBean属性或保存到数据库，对定时代码块的影响也很小，并且与这些下游附加程序所完成的工作量无关。 同样，在将定时日志写入打算稍后进行分析和分析的文件时（例如，使用如上所述的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 ，让我们知道您的想法！

翻译自: https://www.infoq.com/articles/perf4j/?topicPageSponsorship=c1246725-b0a7-43a6-9ef9-68102c8d48e1

perf 性能分析