通過日誌監控並收集 Java 應用程式效能資料

阿新 • • 發佈：2019-02-12

應用場景

在 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 做為攔截器加入。具體可以參考有關 [email protected] 的用法。

在 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(&gt;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 只用於對效能跟蹤及瓶頸分析，而不要用於對系統負載能力的評估。