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