許多開發人員都很熟悉墨菲法則的一個例子：他們發現在花費了大量時間確保應用程序在開發環境中 快速和靈活之後，在發布到生產環境的時候性能會不可思議的大幅下降。更糟糕的是，應用程序平時運行 正常，老板或者重要客戶操作應用的時候卻反應緩慢。詳細的日志記錄和分析對於追蹤這些間歇性的性能 瓶頸尤為重要。
然而，當今世界充滿了面向服務的架構和分布式的應用，查找性能瓶頸對應的組件極其困難。考慮一 個典型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] 使用LogParser創建統計數據和圖表
start[1233364398264] time[556] tag[example1] message[custom message text]
start [1233364398820] time[698] tag[example1] message[custom message text]
雖然默認的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">
< BR> <!-- 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
你可以在這裡下載jar包： http://mirrors.ibiblio.org/pub/mirrors/maven2/org/aspectj/aspectjweaver/1.6.1/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吧（http://perf4j.codehaus.org/downloads.html），告訴我們你的想法！
