使用Perf4J進行效能分析和監控
原文地址：http://www.infoq.com/cn/articles/perf4j/
許多開發人員都很熟悉墨菲法則的一個例子：他們發現在花費了大量時間確保應用程式在開發環境中快速和靈活之後，在釋出到生產環境的時候效能會不可思議的大幅下降。更糟糕的是，應用程式平時執行正常，老闆或者重要客戶操作應用的時候卻反應緩慢。詳細的日誌記錄和分析對於追蹤這些間歇性的效能瓶頸尤為重要。
然而，當今世界充滿了面向服務的架構和分散式的應用，查詢效能瓶頸對應的元件極其困難。考慮一個典型Web 2.0風格應用的伺服器端的常見場景：
- 伺服器接收一個Web請求，分發給負責產生響應的元件。
- 該請求也許需要通過LDAP伺服器進行安全驗證。
- 控制器元件對資料庫執行查詢。
- 控制器元件也會呼叫第三方Web服務。
- 控制器元件將所有獲得的資料進行彙總，組成一系列業務物件用於顯示。
- 業務物件被展現，響應內容傳回使用者瀏覽器。
- 運行於瀏覽器的AJAX程式碼產生其他的請求，與伺服器端互動。
對於“為何我的網頁反應遲鈍？”這樣問題的回答需要研究多個元件和執行路徑，同時需要生產環境中所有應用元件的詳細效能資料。
Perf4J是一款開源工具包，用於新增Java伺服器端計時程式碼、記錄日誌和監控結果。對於熟悉諸如log4j日誌框架的開發人員來說，可以這樣類比：
Perf4J is to System.currentTimeMillis() as log4j is to 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的目標是通過易於整合（和擴充套件）的開源軟體包提供這些功能。Per4J是由Homeaway.com開發的，其基礎設施的分散式特性和網站的高可用性及效能需求需要深入的效能分析。Perf4J的特點包括：
- 簡潔的 stop watch計時機制。
- 提供命令列工具，從原始的日誌檔案中生成彙總的統計資料和效能圖表。
- 定製的log4j appender，可以在執行時應用中生成資料和圖表，計劃在以後的版本中支援
java.util.logging和logback。 - 能夠以JMX屬性的形式釋出效能資料，在資料超過指定閾值時傳送通知。
- 提供
@Profiled註解和一套自定義機制，允許在與AOP框架（如AspectJ或者Spring AOP）整合時巧妙的計時。
下面的例子展現瞭如何輕鬆利用這些功能。可以通過Perf4J開發人員指南來了解整合Perf4J的詳細資訊。
利用StopWatch類開發計時程式碼
org.perf4j.LoggingStopWatch類用於在程式碼中新增計時語句並列印到標準輸出或者日誌檔案中：
StopWatch stopWatch = new LoggingStopWatch();
//... execute code here to be timed
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]
使用LogParser建立統計資料和圖表
雖然預設的stop watch輸出相比直接呼叫System.currentTimeMillis()來說沒有很大的改進，但真正的好處在於能夠解析這些輸出以生成統計資料和圖表。LogParser通過tag和時間片把stop watch輸出分組，生成詳細的統計資訊和可選的時間序列圖（使用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 appender提供。這樣開發人員就能在部署階段通過非常熟悉的日誌框架來零零散散的新增分析和監控功能（未來的Perf4J將提供定製logback appender和java.util.logging處理器）。其中一個重要的功能是允許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/"> <!-- 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也支援生成效能圖表的畫圖appender，使用前端的Perf4J畫圖Servlet。定製的csv佈局可以輕鬆的匯入Excel或者其他電子表格應用。
使用@Profiled註解簡化效能日誌
在程式碼中增加效能記錄語句（通常的日誌語句）的一個缺點是降低了程式碼的“信噪比”，難以在特定程式碼塊中遵循嚴格的業務邏輯。為了改善這一不足，Perf4J提供了@Profiled註解，可以新增在需要記錄執行時間的方法上，允許方法本身不新增StopWatch程式碼：
@Profiled(tag = "dynamicTag_{$0}")
public void profiledExample(String tagSuffix) {
... business logic only here
}
一旦添加了@Profiled註解，Perf4J的計時切面會通過一個面向切面的程式設計框架如AspectJ或者Spring AOP啟用。這個切面在方法呼叫周圍加入建立和停止StopWatch例項的位元組碼。計時切面甚至可以有選擇的使用AspectJ的載入時編織（load-time weaving）功能。因此，通過使用載入時編織你可以保證那些沒有啟用效能監控的方法絕沒有額外的負擔。
一個簡單的示例：基於Web的質數生成器
本示例將帶你感受如何建立一個使用Perf4J庫大多數功能的真實應用。你可以下載perf4jPrimes.war檔案，然後Servlet容器中執行它。在war包中也包含該應用的原始碼。
一切從簡，本例子只包含兩個主要的程式碼檔案：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輸出：
- 原始的標準輸出日誌。
- 通過
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
當代理啟用時，你可以在“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協議下完全開源，程式碼都充分文件化，你可以隨意擴充套件。
現在就下載Perf4J吧，告訴我們你的想法！
感謝張龍對本文的審校。