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