系統日志是應用程序問(wèn)題診斷及運行維護的重要工具。Logback、Log4j 是常用于 Java 平臺的日志記錄 API. 目前大部分產(chǎn)品只是將系統重要參數、狀態(tài)的變化及異常信息通過(guò)日志輸出。本文將要介紹的 Perf4j 是一款專(zhuān)門(mén)用于 Java 服務(wù)器端代碼計時(shí)、記錄日志和監控結果的開(kāi)源工具包。Perf4j 對常用日志工具包進(jìn)行了擴展，能夠將得到的原始性能數據進(jìn)行統計并發(fā)布到可定制的輸出源，如控制臺、日志文件、JMX 等。Perf4j 提供了多種方式與 Java 代碼集成，開(kāi)發(fā)和系統維人員能夠靈活地將 Perf4j 的 API 嵌入到各種不同架構的應用程序中。
Perf4j 目前依托于開(kāi)源項目協(xié)作平臺 Codehaus 進(jìn)行文檔及代碼管理，下一步該項目計劃遷移到 Github 平臺，以便更多的社區及開(kāi)發(fā)人員可以參與到開(kāi)發(fā)及維護中來(lái)。Perf4j 歡迎使用者提出新的功能需求并且鼓勵將定制或擴展的代碼貢獻到 Perf4j 源碼中。本文中示例代碼使用的 Perf4j 版本是 0.9.16，讀者需在下載類(lèi)包或配置 Maven 時(shí)留意。
閱讀文章之前，您要對 Java 注解、JMX、面向方面編程有一些了解。特別是 JConsole 的使用及 Spring AOP 的配置方式要較為熟悉。
文章首先闡明在何種應用場(chǎng)景下應優(yōu)先考慮使用 Perf4j。然后是具體講解 Pef4j 與應用程序的集成方式。最后會(huì )介紹如何將收集的數據生成便于分析的可視化圖表。
回頁(yè)首
在 Java 平臺上遇到性能問(wèn)題時(shí)，如 CPU 占用過(guò)高、系統響應緩慢，通常的分析方法是使用 JVM 剖析工具在系統瓶頸臨界點(diǎn)前一段時(shí)間抓取 CPU 占用分布，再對 CPU 占用率最高的幾個(gè)方法排查。Perf4j 的優(yōu)勢在于能夠持續跟蹤統計所關(guān)注功能代碼的執行效率，對于前后兩個(gè)版本出現較大差異的方法進(jìn)行深入分析，可以在開(kāi)發(fā)周期中盡早發(fā)現問(wèn)題。Perf4j 還可以用在產(chǎn)品環(huán)境中，從運營(yíng)的早期開(kāi)始，將其統計的數據做為系統的性能和健康指標長(cháng)期監測。
首選 Perf4j 的應用場(chǎng)景：
開(kāi)發(fā)人員必須將本地方法、遠程方法及 Web services 的性能問(wèn)題隔離出來(lái)，以防干擾對 Java 應用程序本身的分析。通過(guò)日志記錄則是最簡(jiǎn)單的方式；采用分布式架構或集群部署的系統相對復雜，不同的網(wǎng)絡(luò )環(huán)境、基礎硬件和操作系統的差異、虛擬主機中資源與配置的差異等造成很難采用統一的工具來(lái)監測代碼級別的性能指標。而日志記錄則可以輕松加入到各種程序中，且是資源與時(shí)間成本最低的方式。Perf4j 提供了 CSV 格式的轉換工具，開(kāi)發(fā)人員可以借助第三方工具方便地將統計結果匯總分析。
回頁(yè)首
下面將分兩種方式具體講述如何利用 Per4j 提供的 API。在實(shí)際的項目中，應根據現有的程序框架及監測目的靈活選擇。另外，針對 WebSphere 應用服務(wù)器的自有日志系統，還必須采取額外的措施來(lái)確保 Perf4j 的正常工作。
Perf4j 中 org.perf4j.StopWatch 是整個(gè) API 中的基礎工具。這是一個(gè)封裝良好的計時(shí)器?？梢园?StopWatch 嵌入到代碼中任何地方。這種方式往往使得復雜的方法得到分解，從而有利于精確定位問(wèn)題的根源。以下通過(guò)清單 1 和清單 2 來(lái)介紹其具體用法。
public static void basicStopWatch() throws InterruptedException{
// 創(chuàng )建 StopWacth 時(shí)開(kāi)始計時(shí)，之后也可以用 stopWatch.start() 重新設定計時(shí)開(kāi)始時(shí)間點(diǎn)
StopWatch stopWatch = new StopWatch("TransactionA");
// 執行需要計時(shí)的代碼
Thread.sleep(2 * 1000L);
String result = stopWatch.stop();
System.out.print(result);
}清單 1 中最后輸出的結果示例：start[1340442785756] time[1995] tag[TransactionA]。在構造函數中設定 tag[TransactionA] 用來(lái)區分不同的業(yè)務(wù)邏輯，可以把它看成是性能分析中的事務(wù)（Transaction）。
如果需要將多段代碼分開(kāi)統計，可采用 LoggingStopWatch 類(lèi)的 lap() 方法定義多個(gè)事務(wù)。
public static void loggingStopWacth() throws InterruptedException{
LoggingStopWatch stopWatch = new LoggingStopWatch();
// 設定閾值，小于此閾值的結果將不會(huì )被記錄下來(lái)
stopWatch.setTimeThreshold(1*1000L);
Thread.sleep(2 * 1000L);
// 停止當前計時(shí)，開(kāi)始新的起始時(shí)間點(diǎn)
stopWatch.lap("TransactionB");
Thread.sleep(500L);
stopWatch.stop("TransactionC");
}清單 2 中使用了 LoggingStopWatch 類(lèi)，其 stop() 方法只是將執行時(shí)間數據通過(guò) System.err.println() 輸出。若與 Log4j 框架集成，則需要使用 LoggingStopWatch 的子類(lèi) Log4JStopWatch, 目前 Perf4j 還支持 Apache Commons Logging、java.util.logginLogback，對應使用 CommonsLogStopWatch、 JavaLogStopWatch、Slf4JStopWatch。
以 Log4j 為例，在 Log4j.xml 中要為 Log4JStopWatch 加入異步輸出源 AsyncCoalescingStatisticsAppender。盡量使專(zhuān)用于 Perf4JAppender 的 fileAppender，從而保證記錄的性能數據輸出到獨立的日志文件中。
<appender name="Perf4jAppender" class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender"> <!-- TimeSlice 用來(lái)設置聚集分組輸出的時(shí)間間隔，默認是 30000 ms, 在產(chǎn)品環(huán)境中可以適當增大以供減少寫(xiě)文件的次數 --> <param name="TimeSlice" value="10000" /> <appender-ref ref="fileAppender" /> </appender> <appender name="fileAppender" class="org.apache.log4j.FileAppender"> <param name="File" value="perfermanceData.log" /> <layout class="org.apache.log4j.PatternLayout"> <param name="ConversionPattern" value="%m%n" /> </layout> </appender> <!-- Perf4j 默認用名稱(chēng)為 org.perf4j.TimingLogger 的 Logger --> <logger name="org.perf4j.TimingLogger" additivity="false"> <level value="INFO" /> <appender-ref ref="Perf4jAppender" /> </logger>
清單 3 中設置了 TimeSlice 為 10 秒， Perf4jAppender 則以 10 秒為采樣間隔，統計后按時(shí)間分組輸出。清單 4 中是一個(gè)采樣單位的數據。
Performance Statistics 2012-07-02 21:45:30 - 2012-07-02 21:45:40 Tag Avg(ms) Min Max Std Dev Count LogicalBlock1 1997.0 1997 1997 0.0 1 LogicalBlock2 499.0 499 499 0.0 1
若要避免 Perf4j 與系統的緊耦合，不在程序中加入額外的第三方代碼，還可以借助面向方面編程（AOP），通過(guò)簡(jiǎn)單的配置在運行中動(dòng)態(tài)地對指定的方法計時(shí)。Perf4j 對常用的 AOP 工具如 AspectJ 及 Spring AOP 均提供了良好支持 . 在此主要介紹下 Per4j 與后者集成的配置方式。
首先確保工程中已有如圖 1 中的 Jar 包：
其次在 Spring 的配置文件（一般是 applicationContext.xml 或 spring-config.xml）中加入 <aop:config> 及申明 org.perf4j.log4j.aop.TimingAspect 做為 <aop:aspect>。具體配置參考清單 5：
<aop:config>
<aop:aspect id="timing" ref="timingAspect">
<aop:pointcut id="timingcut"
expression="execution(* cn.test.perf4j.example..*.*(..)) and @annotation(profiled)"/>
<aop:around pointcut-ref="timingcut" method="doPerfLogging"/>
</aop:aspect>
</aop:config>
<bean id="timingAspect" class="org.perf4j.log4j.aop.TimingAspect"/>
<!-- 用戶(hù)自定義任意的業(yè)務(wù)處理類(lèi) -->
<bean id="processService" class="cn.test.perf4j.example.ProcessService" />其中切入點(diǎn) <aop:pointcut> 的表達式（expression）中包的作用域可以按實(shí)際需求進(jìn)行修；@annotation(profiled) 會(huì )把 @org.perf4j.aop.Profiled 做為參數傳給 TimingAspect，在此則不能刪除此條件。當然還可以采用 <aop:aspectj-autoproxy/> 替換 <aop:pointcut> 復雜的配置，在 org.perf4j.log4j.aop.TimingAspect 的父類(lèi) ProfiledTimingAspect 中已用注解定義過(guò)全局的切入點(diǎn)。<aop:config> 具有更大的靈活性，可以任意設置監測的范圍，建議產(chǎn)品環(huán)境使用。
運行時(shí)如果遇到如下異常：
“The matching wildcard is strict, but no declaration can be found for element 'aop:config'”
說(shuō)明之前沒(méi)有設置過(guò) AOP 的命名空間，在 xsi:schemaLocation 最后加相對應版本的 URI 即可。
<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:context="http://www.springframework.org/schema/context"
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.5.xsd
http://www.springframework.org/schema/context
http://www.springframework.org/schema/context/spring-context-2.5.xsd
http://www.springframework.org/schema/aop
http://www.springframework.org/schema/aop/spring-aop-2.5.xsd">現在如果要記錄包 cn.test.perf4j.example 下某些方法的執行時(shí)間，只需在方法簽名加上注解 @Profiled。org.perf4j.aop.Profiled 也提供了細顆粒度的定制。具體屬性設置方法如下 :
/** 1. 默認以方法名做標記 tag 的名稱(chēng) */
@Profiled
public void doService(){...}
/** 2. 自定義標記 tag 的名稱(chēng)并設定閾值 */
@Profiled(tag=”doTimedService”,timeThreshold =500L )
public void doService(){...}其它支持的屬性還有：
boolean el : tag 和 message 的設置是否支持 Java EL 表達式語(yǔ)法；
String level : 設定日志級別；
boolean logFailuresSeparately : 若為真，正常和異常拋出的執行時(shí)間數據將分開(kāi)統計；
Sring logger : log4.xml 中設置的 logger 名稱(chēng)。如果是默認值，則此屬性可省去。
在產(chǎn)品環(huán)境中，不方便重新編譯代碼，建議使用 ScopedTimingAspect，完全通過(guò)配置文件控制監測的范圍，不用在方法上加 Profiled 注解。具體用法可以參考 AspectJ 的用法。另外如果系統已采用 EJB3，可以把 org.perf4j.log4j.aop.EjbTimingAspect 做為攔截器加入。具體可以參考有關(guān) EJB3@Interceptors 的用法。
WebSphere 應用服務(wù)器默認使用基于 JDK 中 java.util.logging 的日志 API 并且集中管理了整個(gè)系統的日志輸出。Perf4j 必須單獨生成自己的數據文件，以便于分析。如果應用程序要部署到 WebSphere 應用服務(wù)器中，如下方法能夠幫助我們將 Perf4j 記錄的日志獨立出來(lái)。
1. 指定 LogFactory 實(shí)現類(lèi)：
在 <app root>/META-INF/services 目錄中創(chuàng )建名為 org.apache.commons.logging.LogFactory 的文件，在文件中分別設定相對 Log4j 的配置，內容為 org.apache.commons.logging.impl.Log4j；還有一種方式是在 classpath 下創(chuàng )建 commons-logging.properties 文件，文件內容為：
priority=1 org.apache.commons.logging.LogFactory=org.apache.commons.logging.impl.LogFactoryImpl org.apache.commons.logging.Log=org.apache.commons.logging.impl.Log4JLogger
2. 在 Admin 控制臺中，選擇 Applications > Enterprise Applications > ''app name'' ，設定 ClassLoader 的模式為 PARENT_LAST。
3. 將之前配置的 log4j.xml 同樣放在 classpath 下。在 log4j.xml 中只須設定 Perf4jAppender。程序其它調用 java.util.logging 的日志仍由 WebSphere 統一控制。
回頁(yè)首
目前我們已經(jīng)可以得到 Perf4j 生成的原始數據，不過(guò)為了易于分析這些數據，方便直觀(guān)地將統計結果展現出來(lái)才是我們最終需要的。這里介紹的兩種方式均是利用 Perf4j 提供的特定 Appender 來(lái)發(fā)布數據到相應可視化工具。
Java 管理擴展接口（JMX）常用來(lái)監控 JVM 的運行狀態(tài)以及動(dòng)態(tài)管理配置系統。
通過(guò) JmxAttributeStatisticsAppender 能將數據封裝成標準的 JMX 管理構件的 MBean。配置見(jiàn)清單 8。
<appender name="Perf4jAppender"
class="org.perf4j.log4j. AsyncCoalescingStatisticsAppender">
<appender-ref ref="fileAppender" />
<appender-ref ref="perf4jJmxAppender"/>
</appender>
<appender name="perf4jJmxAppender"
class="org.perf4j.log4j.JmxAttributeStatisticsAppender">
<!-- 設定要發(fā)布的事務(wù) -->
<param name="TagNamesToExpose" value="doServiceA,doServiceB"/>
<!-- 設定閾值 此處為 doServiceA 的最小值超過(guò) 200ms 才發(fā)布出去。
若設定范圍可用區間表示，如 (200-500) -->
<param name="NotificationThresholds" value="doServiceAMin(>200)"/>
</appender>JConsole 是 Oracle JDK 自帶的的 JMX 監控工具，當然也有很多第三方 JMX 工具可供選擇。圖 2 是 JConsole 界面的截圖，顯示了 Perf4j MBean 具體內容及圖表。
這種方式需要用到 AsyncCoalescingStatisticsAppender，通過(guò)其記錄的是每個(gè)時(shí)間片各事務(wù)的執行時(shí)間統計信息，在此還要加上 GraphingStatisticsAppender，將指定的監測指標數據單獨抽出，再由 Perf4j 的 GraphingServlet 展現在頁(yè)面上。一般可做為子頁(yè)面加入到系統管理界面中。清單 9 中只是加入了一個(gè)用于生成平均執行時(shí)間圖示的 Appender 做為示例，當然 Perf4j 也允許加入多個(gè) GraphingStatisticsAppender 以同時(shí)顯示不同指標的數據。
<appender name="Perf4jAppender"
class="org.perf4j.log4j. AsyncCoalescingStatisticsAppender">
<appender-ref ref="fileAppender" />
<appender-ref ref="meanExecutionTime"/>
</appender>
<appender name="meanExecutionTime"
class="org.perf4j.log4j.GraphingStatisticsAppender">
<param name="GraphType" value="Mean"/>
<param name="TagNamesToGraph" value="doServiceA,doServiceB"/>
<appender-ref ref="meanTimeFileAppender"/>
</appender>在 GraphType 中可以設定的性能指標有平均執行時(shí)間（Mean）、最長(cháng)執行時(shí)間（Max）、最短執行時(shí)間（Min）、執行時(shí)間標準差（StdDev）、執行次數（Count）和 每秒事務(wù)處理量（TPS）。TagNamesToGraph 是可選項，用來(lái)指定需要輸出的事務(wù)，如果不設定則會(huì )輸出全部事務(wù)。
同時(shí)在 web.xml 中還要加入 GraphingServlet 的映射。如清單 10。
<servlet>
<servlet-name>perf4jMonitor</servlet-name>
<servlet-class>org.perf4j.log4j.servlet.GraphingServlet</servlet-class>
<init-param>
<param-name>graphNames</param-name>
<!-- 此處設置清單 9 中配置的 Appender 名稱(chēng) -->
<param-value>meanExecutionTime,executionTPS</param-value>
</init-param>
</servlet>
<servlet-mapping>
<servlet-name>perf4jMonitor</servlet-name>
<url-pattern>/perf4jMonitor</url-pattern>
</servlet-mapping>至此在系統的運行過(guò)程中，訪(fǎng)問(wèn) /perf4jMonitor 就可以實(shí)時(shí)的觀(guān)測指定事務(wù)的性能數據圖示。
回頁(yè)首
本文介紹了配置與使用 Perf4j 的諸多細節。在實(shí)際項目中，我們還應該設計一個(gè)易擴展的體系結構，使第三方 API 能輕易加入。如果只是用 Perf4j 協(xié)助發(fā)現性能問(wèn)題的源頭，開(kāi)發(fā)人員可采用臨時(shí)代碼中嵌入 StopWatch 類(lèi)的方式。若是計劃長(cháng)期對系統性能跟蹤，應設計一個(gè)完善的日志框架集成方案，能夠輕易地將 Perf4j 無(wú)縫的加入和脫離尤為重要。
盡管 Perf4j 中使用的是異步的輸出源，在大量用戶(hù)并發(fā)的性能測試和產(chǎn)品環(huán)境下，額外的 CPU 內存占用也是不容忽視的。因此務(wù)必確保 Perf4j 只用于對性能跟蹤及瓶頸分析，而不要用于對系統負載能力的評估。
聯(lián)系客服
