HomeAway_logo這是一個許多開發者都熟悉的墨菲定律的具體的例子：在花費了大量的時間來確保應用程式在當前環境中是快速而且可伸縮之後，一發布到生產環境，性能就令人費解的直線暴降。甚至更糟糕的是，只有老闆或重要客戶在抱怨他們的業務運營總是象蝸牛爬一樣，其實這個東西平時運行的挺快。當涉及到跟蹤這些間歇性的性能瓶頸的時候，詳細的日誌和分析就變得至關重要。
然而，在廣泛採用面相服務的架構(SOA)和分散式套用的當今世界，給負責回響的組件監測性能瓶頸變得極其困難。仔細考慮一下在相對常見的典型web2.0的套用下，伺服器上都發生了什麼：
·收到的一個web請求，被分發到負責回響的組件並生成回響。
·這個請求可能需要到一個LDAP伺服器上進行許可權認證。
·控制組件在資料庫上進行幾次查詢。
·控制組件還調用了第三方Web service。
·控制組件把所有的檢索數據聚合成了一套業務對象用於顯示。
·業務對象被渲染並返回給用戶瀏覽器。
·瀏覽器運行AJAX代碼導致了有附加請求送回給伺服器。
要回答“為什麼我的網頁這么慢”，需要調查多種組件和執行路徑，以及生產環境中所有套用組件輸出的詳細性能數據。
Perf4J就是這樣一個開源的工具，通過在Java服務端加入代碼，給狀態計時，並記錄日誌、分析和監控結果。對於熟悉日誌框架(如log4j或者java.util.logging)的開發者同學，可以這樣比喻和描述Perf4J：
Perf4J對於System.currentTimeMillis() 就像log4j 對於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的目標是用開源包的方式提供這些功能，並且容易集成、容易擴展。我們在Homeaway.com開發出Perf4J，我們的網站是廣泛的分散式結構，它必須是高可用性高性能的，需要深入的性能分析。
一些Perf4J的特點
·用於計時的簡單的stop watch機制。
·從原始日誌檔案生成聚合統計和性能圖表的命令行工具
·可定製的log4j appenders(輸出源)，可以在正在運行的套用中生成統計信息（隨後還會支持java.util.logging和logback）
·可以用JMX屬性的方式展現性能統計，並且當統計超出閥值時發出通知。
·在整合AOP框架(AspectJ或者Spring AOP)時，可以使用@Profiled注釋和一套定製的切面很不起眼的加入計時語句。
下面給出的例子明示了你如何很容易的利用這些特性。
更多關於如何把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流。大多數情況下，儘管，你可能想繼承LoggingStopWatch，生成一個子類，這個子類集成了某種流行的java日誌框架或者日誌外殼，變成Log4JStopWatch、CommonsLogStopWatch或者Slf4JStopWatch。下面是一些stopwatch輸出的例子：
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]
用Log Parser創建統計和圖表
因為默認stop watch不比直接調用System.currentTimeMillis()輸出增長快很多，所以這樣就能夠分析這些輸出來生成聚合統計和圖表，真是不錯啊。LogParser按照標籤和時間片聚合stop watch輸出，生成詳細的統計信息，可以選擇使用Google Chart API生成時序圖。下面是一些使用默認文本格式的輸出例子(還支持csv格式)：
Performance Statistics 20:32:00 - 20:32:30
TagAvg(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.failure747.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伺服器生成平均執行時間和每秒事務數的圖表：
Perf4J而且，因為LogParser默認從標準輸入讀取，所以你可以從正在運行的伺服器把日誌檔案用管道方式發給LogParser，讓輸出變成實時的：
tail -f performance.log | java -jar perf4j-0.9.8.1.jar
直接集成Log4J
藉助一套定製的log4j appenders，出現了很多Perf4J的擴展功能。這將允許開發者在開發的時候藉助許多java開發都熟悉的日誌框架添加分析和監控的小功能(未來Perf4J將支持定製的logback appenders和java.util.logging接口)。這么一個有價值的功能允許Perf4J通過JMX MBean來顯示性能數據，當性能下降到低於可接受的值的時候傳送JMX通知。由於JMX成了管理和監控java套用的標準接口，正說明了Perf4J MBean可以使用各式各樣的第三方監控程式提供的功能。例如，在Homeaway，我們的IT部門在Nagios和Cacti上進行系統監控的標準化；這些工具支持把MBean當作一個數據域來查詢。
下面的範例檔案log4j.xml顯示了如何為JMX開啟Perf4J appenders：
<?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 appender，Perf4J也提供生成性能圖表的圖形化appender，它可以通過Perf4J的graphing 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的裝載時織入功能在特定的類運行時選擇性的生效。因此，採用裝載時織入的方式，絲毫不會因為那些沒有開啟profile的方法引起額外的系統開銷。
一個簡單的例子
一個基於web的Prime Number Generator(素數生成器)
這個例子帶你一步步的創建一個實例，它用到了Perf4J庫的大部分特性。你可以下載perf4jPrimes.war，自己在servlet容器中運行這個程式。注意這個war檔案也包含用來創建應用程式的原始碼。
簡單起見，這個例子只包含兩個主代碼檔案：primes.jsp，用來顯示生成的素數和接受用戶指定的參數，PrimeNumberGenerator類包含真正的生成代碼(大部分情況下授權給了java.math.BigInteger類)。有3個地方用Perf4J來計時代碼塊：
·在primes.jsp的代碼中創建一個Log4JStopWatch來給整個頁面生成計時。
·PrimeNumberGenerator.generatePrime()方法中有一個@Profiled註解。
·PrimeNumberGenerator.randomFromRandomDotOrg()方法中也有一個@Profiled註解。
如果你查看WEB-INF/classes/log4j.xml，就會發現Perf4J可以使用這些功能：
所有單獨的stop watch日誌將被寫到標準輸出(注意：你的servlet容器可以將標準輸出通過管道輸出到硬碟上的檔案)。如果願意，你可以用LogParser直接處理這些輸出。
已經創建了一個AsyncCoalescingStatisticsAppender來聚合stop watch日誌，並把他們傳送到下游的一組GraphingStatisticsAppenders和一個JmxAttributeStatisticsAppender。
已經創建了兩個GraphingStatisticsAppenders，一個用來輸出平均執行時間，一個用來輸出每秒事務數。
一旦你在web伺服器上啟動了web套用，你可以訪問素數生成頁面：http://servername//primes.jsp，rootContextLocation取決於你的web伺服器的配置(而且，為了便於訪問，你可以查看PrimeNumberGenerator的源碼：http://servername//PrimeNumberGenerator.java)。在primes.jsp頁面上，你將看到若干不同的參數控制生成素數的方式。你可以修改這些參數，並點擊"Generate Prime Number"按鈕來看這些參數如何影響以及它花了多少時間去生成這些數。在生成了一坨數字以後，你應該可以看見Perf4J在三個地方輸出：
原始日誌輸出被傳送到標準輸出。
圖表servlet：http://servername//perf4jGraphs。訪問它，你應該可以看到平均執行時間和每秒事務數圖表。
還有JMX監控。你可以使用Java的SDK自帶的Jconsole應用程式來查看Perf4J MBean的值。你需要用-D com.sun.management.jmxremote命令行方式，啟動你的webserver。然後，如果你在正在運行的伺服器上啟動jconsole，你應該可以在MBeans這一欄看到"org.perf4j.StatisticsExposingMBean.Perf4J"的數據值。
因為這時你還沒有開啟任何TimingAspects(計時切面)來支持@Profiled注釋，你看到的僅有的stop watch輸出是關於"fullPageGeneration"標籤的。你可以用AspectJ裝載時織入來開啟計時切面。你需要這樣用AspectJ的織入代理命令行參數啟動你的webserver：
-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的最大好處，來最小化任何非預期的影響：
當決策要profile註解什麼方法或代碼塊的時候，請專注於最重要的大魚。在企業級套用中，當遇到性能瓶頸的時候，有很多“慣犯”：資料庫調用、遠程方法調用、磁碟I/O，以及在巨大數據集上的重量級計算操作。因此，你在決定如何進行profile註解的時候，應該聚焦在這些類型的操作上。而且，因為這些典型操作花費數十到數百毫秒，Perf4J在這些操作上額外增加的開支比他們執行時間低好幾個量級，在實用上可以忽略。事實上，這就是為什麼Perf4J在給代碼塊計時上故意使用System.currentTimeMillis(而沒有用System.nanoTime)的原因之一：在可能有問題的企業級套用的代碼塊上計時，根本不用納秒級。
設計Perf4J是為了對獨立的執行緒或進程進行性能分析。當使用AsyncCoalescingStatisticsAppender時，正在執行的執行緒將一個日誌事件推送到記憶體里的佇列，這個佇列消耗了一個獨立的線程來發送日誌訊息到下游的appender。因此，雖然那些下游appender做了大量密集的工作，比如創建圖示或者更新MBean屬性或者保存到資料庫，在代碼塊上的影響確實爆低的並且和下游appender做的一坨工作都無關。類似的，當把計時日誌寫入到一個檔案，以便稍候解析和分析(比如使用Unix的tail命令來查看)時，對被計時的進程的影響只和它寫日誌花去的時間相關，和日誌分析無關。
不要忘記性能回歸測試的好處。除實時的檢測測性能瓶頸之外，Perf4J對創建性能回歸測試非常有用，它可以確定代碼的改變是否對性能有很大的影響(積極或消極)。用代碼的最初版本創建一個基線，你可以很快的確定新版本對性能有什麼樣的影響。
利用@Profiled註解和AspectJ的裝載時織入來判斷部署的時候需要對哪些方法計時。如果你用@Profiled註解，你可以很容易的在方法調用周圍添加計時註解，然後可以在你使用AspectJ的aop.xml配置檔案時，決定實際上要對什麼方法計時。但在結束時總有一次都沒被執行的方法，它們將不能被計時。雖然這些被計時的方法比直接在代碼里使用StopWatch開銷略高一點(AspectJ其實是在被計時的方法外創建一個閉環)，這點額外的開銷在方法至少執行幾毫秒時應該仍然微不足道。
不要忘記你的那部分在JVM之外執行的套用。例如，非常多web2.0套用是以Javascript方式在客戶的瀏覽器端執行的。雖然能用Perf4J來測量AJAX遠程調用的伺服器上的應答的方法，如果Javascript自己執行的很慢，你還是需要額外的客戶端調試工具。
未來Perf4J的方向
Perf4J正積極開發以及頻繁增加新功能。例如，未來Perf4J版本將允許你用一個獨立的配置檔案來指定要profile的方法，因此，甚至允許當你未訪問原始碼就可以對方法執行計時。所有功能都根據用戶反饋和需要排優先權，所以如果你想決定Perf4J的未來，今天就試試它。更強的是Perf4J完全開源(用的是Apache2的license)，代碼的注釋非常完全，你可以對它隨意擴展。
現在就下載Perf4J，讓我們知道你覺得怎么樣！
