速讀原著-藉助開源工具高效完成 Java 應用的運行分析

• 2020 年 2 月 14 日
• 筆記

藉助開源工具高效完成 Java 應用的運行分析

不止一次，我們都萌發過想對運行中程式的底層狀況一探究竟的念頭。產生這種需求的原因可能是運行緩慢的服務、Java 虛擬機（JVM）崩潰、掛起、死鎖、頻繁的 JVM 暫停、突然或持續的高 CPU 使用率、甚至於可怕的記憶體溢出(OOME)。好消息是現在已有許多工具能幫你得到Java 虛擬機運行過程中的不同參數，這些資訊有助於你了解其內部狀況，從而診斷上述的各種情況。

在這篇文章中，我將介紹一些優秀的開源工具。其中一些是 JVM 自帶的，另一些則是第三方工具。我將從最簡單的工具開始介紹，逐漸過渡到一些比較複雜的工具。本文的目的是幫助你找到合適的調試診斷工具，這樣當程式出現執行異常、緩慢或根本不能執行時，手頭隨時有可用的工具。 好了，讓我們出發。

如果程式出現不正常的高記憶體負載、頻繁無響應或記憶體溢出，通常最好的分析切入點是查看記憶體對象。幸好JVM 內置了工具「jmap」，讓它天生就能完成這種任務。

Jmap（藉助JPM 的一點幫助）

Oracle 將 jmap 描述為一種「輸出進程、核心文件、遠程調試伺服器的共享對象記憶體映射和堆記憶體細節」的程式。本文將使用 jmap 列印一張記憶體統計圖。

為了運行 jmap，你需要知道被調試程式的 PID（進程標識符）。得到 PID 的簡單辦法是使用 JVM 提供的 jps，它能列出機器上每一個JVM 進程及其PID。jps 輸出結果如下圖：

為了列印記憶體統計圖，我們需要打開 jmap 控制台程式，並輸入程式的 PID 和「-histo:live」選項。如果不添加這個選項，jmap 將完整導出該程式的堆記憶體,這不是我們想要的結果。所以，如果想得到上圖中「eureka.Proxy」 程式的記憶體統計圖， 我們應該用如下命令來運行 jmap： jmap – histo:live 45417

上述命令輸出如下：

結果中每行顯示了當前堆中每種類類型的資訊，包含被分配的實例個數及其消耗的位元組數。

本例中，我請同事有意給程式增加了一處明顯的記憶體泄露。請特別注意位於第 8 行的類， CelleData。將它與下圖顯示的 4 分鐘後截屏進行比較：

現在有超過 2 千 5 百萬個CelleData 類實例，佔用了超過 1GB 記憶體！我們可以確認這是一個記憶體泄露。

這類數據資訊的好處是，不僅非常有用而且對於很大的 JVM 堆也能快速回饋結果。我曾經試過檢測一個運行頻繁並且佔用 17GB 堆記憶體的程式，使用 jmap 能夠在 1 分鐘內生成程式的性能統計圖。

需要注意的是，jmap 不是運行分析工具，在生成統計圖時JVM 可能會暫停，因此當生成統計圖時需要確認這種暫停對程式是可接受的。以我的經驗，通常在調試一個嚴重 bug 時需要生成這種統計圖，這種情況下，這些 1 分鐘的暫停對程式來說是可接受的。這裡，我們引出了下一個話題 - 半自動的運行分析工具VisualVM。

VisualVM

另一個包含於 JVM 中的工具是 VisualVM，它的開發者將它描述為「一種集成了多個 JDK 命令行工具的可視化工具，它能為您提供輕量級的運行分析能力」。這樣看來，VisualVM 是另一種你最有可能用到的事後分析工具，一般是錯誤已出現或性能問題已經用傳統方法（客戶抱怨大多屬於此類）發現。 繼續之前的示常式序和它嚴重的記憶體泄露問題，在程式執行 30 分鐘後，VisualVM 幫我們繪製了如下圖表：

從這個圖表，我們可以清晰地看到截止到 7:00pm，運行僅僅 10 分鐘後，程式已經消耗掉超過1GB 的堆空間。又過了 23 分鐘，JVM 已經到了它啟動參數–Xmx3g 最大值，導致程式響應緩慢， 系統響應緩慢（持續的垃圾回收）和數量驚人的記憶體溢出錯誤。

藉助 jmap，我們定位了這種記憶體消耗攀升的原因。修復後，我們讓程式重新運行於 VisualVM 的嚴格監測之下，觀察到下面的情況：

如你所見，程式的記憶體曲線（啟動參數仍然為–Xmx3g）有了明顯改善。 除了記憶體影像工具，VisualVM 還提供了一個取樣器和一個輕量級的剖析器（Profiler）。

VisualVM 取樣器能周期取樣程式 CPU 和記憶體的使用情況。得到的統計數據類似 jmap 的回饋， 此外，你還可以通過取樣得到方法調用對 CPU 的佔用情況。它讓你能快速了解周期取樣過程中的方法執行次數：

VisualVM 剖析器無需對程式周期取樣就可以提供類似取樣器的回饋資訊，它還可以收集程式在整個正常執行過程中的統計數據（通過操縱程式源程式碼的位元組碼）。從剖析器得到的這種統計數據比從取樣器而來的更精確和實時。

但是，你必須考慮的另一方面是該剖析器屬於一種「暴力」分析工具。它的檢測方法本質上是重新定義程式執行中的大多數類和方法，結果必然會明顯減緩程式執行速度。例如，上述程式運行部分的常規分析，大約要 35 秒。開啟 VisualVM 的記憶體剖析器後，導致程式完成相同分析要31 分鐘。

我們需要清楚的是 VisualVM 並非功能齊全的剖析器。它無法在你的產品 JVM 上持續運行，不會保存分析數據，無法指定閾值，也不會在超過閾值時發出警報。要想更多的了解功能齊全的剖析器的目標。下面，讓我們看看BTrace，這個功能齊全的開源 java 代理程式。

BTrace 想像一下，如果能收集 JVM 當前的任何資訊，那麼你感興趣的資訊有哪些？我猜想問題列表會將因人而異，因情形而異。就個人來說，我通常感興趣的是以下的問題：

• 程式對堆、非堆、永久保存區（Permanent Generation），以及JVM 包含的不同記憶體池（新生對象區、長期對象區、存活空間等）的記憶體使用情況；
• 當前程式的執行緒數量，以及哪種類型執行緒正在被使用（單獨計數）；
• JVM 的CUP 負載；
• 系統平均負載/系統 CPU 使用總和；
• 對程式中的某些類和方法，我需要了解它們被調用次數，各自平均執行時間和整體平均時間；
• 對 SQL 調用的調用計數及執行次數；
• 對硬碟和網路操作的調用計數及執行次數。

利用 BTrace 可以採集到所有以上資訊，你可以使用 BTrace 腳本定義需要採集的數據。方便的是，BTrace 腳本就是普通 Java 類，包含一些特殊註解來定義 BTrace 在什麼地方及如何跟蹤你的程式。BTrace 腳本會被BTrace 編譯器-btracec 編譯成標準的.class 文件。 BTrace 腳本包含許多部分，正如下圖所示。如果需要了解下圖腳本的詳細內容，請點擊該鏈接或訪問 BTrace 項目網站(http://kenai.com/projects/btrace)。 由於BTrace 僅僅是一個代理，記錄結果後，它的任務就算完成了。除了文本輸出，BTrace 並不具備動態展現被收集資訊的功能。預設情況下，BTrace 腳本輸出結果將在 btrace.class 文件所在位置生成一個名為BTrace 腳本名.class.btrace 的 text 文件。 我們可以通過給 BTrace 設置一個額外參數，讓它按某時間間隔循環記錄日誌。切記，它最多能在 100 個日誌文件間循環，當達到*.class.btrace.99，它將覆蓋*.class.btrace.00 文件。若讓循環間隔在一個合理數字（如，每 7.5 秒）內，你就有充足時間來處理這些輸出。只要在 Java 代理的輸入參數中加上fileRollMilliseconds=7500，就可以實現日誌循環。 BTrace 一大缺點是它比較原始，難以定義它的輸出格式。你也許非常希望有一種更好的方式來處理 BTrace 的輸出和數據，比如可以用一種一致的圖形用戶介面來展示。你可能還需要比較不同時間點的數據和超出閾值能發送警告。一個新的開源工具 EurekaJ，就此應運而生。

EurekaJ 我最初開發 EurekaJ 是在 2008 年。那時，我正在尋找一種具有我需要功能的開源剖析器，但沒有找到。於是，我開始開發自己的工具。開發過程中，我涉獵了大量不同的技術並參考了許多架構模型，直到 EurekaJ 第一個版本發布。你可以從項目網站上了解更多的 EurekaJ 歷史，查看源程式碼或下載並試著安裝自己的版本。 EurekaJ 提供了兩個主要應用：

1. 一個基於 Java 的管理器程式，可以接收傳入的統計數據並一致地以可視化視圖展現出來一個解析BTrace 輸出的代理程式，將其轉化為JSON 格式並輸入到EurekaJ 管理程式的REST 介面。
2. EurekaJ 接受兩種類型的輸入數據格式。EurekaJ 代理期望 BTrace 腳本的輸出被格式化為逗號分隔的文件（這點在 BTrace 中可很容易做到），而 EurekaJ 管理程式期望它的輸入符合它的JSON REST 介面格式。這意味著你能通過代理程式或直接經由REST 介面來傳遞度量數據。

藉助 EurekaJ 管理程式，我們可以在一張圖上分組顯示多個統計數據、可以定義閾值和給接收者發出警報。我們還可以方便的查看收集到的實時數據或歷史數據。 所有收集到的數據排序成一種邏輯樹結構，其結構由 BTrace 腳本作者指定。我建議 BTrace 腳本的作者對相關統計數據分組，這樣，當它們顯示在EurekaJ中時會更容易理解和觀察。例如， 我個人喜歡對統計數據進行如下的邏輯分組：

圖例

一種需要採集的重要資訊是程式運行時的平均系統負載。要是你正面對一個運行緩慢的程式， 那麼缺陷可能並不在程式自身，而是隱藏到應用駐留的主機某處。我曾經在調試運行緩慢的應用時偶爾發現，真正的根源是病毒掃描程式。如果不進行測量分析，這種事情會很難被發現。考慮到這一點，我們需要能夠在一張圖中顯示系統平均負載和進程載入後產生的負載。下圖顯示了一個運行EurekaJ 演示程式的Amazon EC2 虛擬伺服器的 2 小時平均負載（該應用登錄的用戶名和密碼都是『user』）。

圖中，黃色和紅色的線條表示警戒閾值。一旦圖形超過黃線的次數超過預設的最小警戒次數時， 則測量結果到達「警告」狀態。類似，若突破紅線，測量結果就到達「危險」或「錯誤」狀態。每當 發生狀態轉換，EurekaJ 都會發送一封郵件給之前註冊的收件人。

在上面的情形中，好像有周期性的事件每 20 分鐘發生一次，從平均負載圖上顯示的波峰可以看到這一點。首先你要確定的是這個波峰確實由你的程式產生，而非其他原因。我們也可以通過測量進程的 CPU 負載來確認這點。在 EurekaJ 樹菜單中，選擇兩個測量點後，兩個圖表結果會一起快速成像顯示出來，其中一個位於另一個下面。

在上面的例子中，我們清楚地看到進程CUP 佔用和系統負載存在必然的聯繫。

許多應用需要在程式無響應或不可用時及時發出警告。下圖是一個 Confluence（Atlassian 的企業級 Wiki 軟體）的例子。這個例子中，程式記憶體佔用快速上升，直到產生程式記憶體溢出。這時，Confluence 無法處理接收到的請求，同時日誌文件記錄了各種奇怪的錯誤。

你可能希望當程式運行導致記憶體溢出時，程式能立刻拋出一個 OOME（記憶體溢出錯誤），然而， 事實上 JVM 不會拋出 OOME 直到它發覺垃圾回收過於緩慢。結果，程式沒有完全崩潰，又過了 2 小時，Java 仍然沒有拋出 OutOfMemoryError，甚至兩小時後程式依然在「運行」（意味著JVM 進程仍然在運行）。顯然，這時任何進程監測工具都不能發現程式已經「停止」。

注意最後幾個小時的執行情況，圖表揭示了下面的度量指標。

EurekaJ 使我們可以設置程式的堆記憶體警告，個人建議最好如此。若程式持續佔用堆記憶體超過95%-98%（取決於堆的大小），幾乎可以肯定，程式存在記憶體問題，要麼用–Xmx 參數為程式分配更多的堆，要麼優化程式使其使用更少記憶體。同時，EurekaJ 未來版本計劃增加統計數據不足的警報。 最後的圖表示例展示了一個包含 4 個不同程式記憶體使用的圖表組。這種類型的圖表組可方便用 來比較一個程式不同部分的、或甚至不同程式之間、伺服器之間的數據。下圖的這 4 個程式有不同的記憶體需求和記憶體佔用模式。 如下圖示，不同程式有不同的記憶體曲線。這些曲線非常依賴一些實際情況，比如使用的架構、快取數量、用戶數、程式負載等。我希望通過下圖說明你需要掌握程式在正常和高負載下執行情況的重要性，因為這將直接關係到如何定義報警閾值。

你使用的每一種測量方法似乎都會引起系統性能干擾。一些數據的測量可以被認為「無干擾」 （或「忽略不計」），然而另外一些數據的測量可稱得上代價昂貴。非常重要的一點是，要知道 你需要 BTrace 測量什麼。因此，你要將這種分析工具對程式的性能干擾減少到最小。關於這點， 請參考下面的 3 條原則：

• 基於「取樣」的度量通常可被認為「無影響」。取樣CPU 負載、進程CPU 負載、記憶體使用和每5-10 秒的執行緒計數，其帶來的額外一兩個毫秒的影響可被忽略。在我看來，你應該經常收集這類統計數據，它們對你來說不會有什麼損耗。
• 對長時間運行的任務的測量也可被認為「無影響」。通常，它僅會對每個被測量方法帶來1700-2500 納秒的影響。如果你正測量這些對象的執行時間：SQL查詢、網路流量、硬碟讀寫或一個預期範圍在 40 毫秒（磁碟存取）到 1 秒（Servlet 處理）之間的Servlet 處理過程， 那麼對這些對象每個增加額外的 2500 納秒左右的時間也是可接受的。
• 絕對不要對循環內執行的方法進行測量。 尋找程式熱點區的一個通用規則是不要影響非熱點區域。例如，考慮下面的類：

第 5 行的 SQL 執行時間可能使 readStatFromDatabase 方法可能成為一個熱點。當查詢返回相當 多的數據行時，它無疑會成為一個熱點，這對 13 行（程式和資料庫伺服器之間的網路流量）和 14-16 行（結果集中每行所需處理）會造成負面影響。如果從資料庫返回結果時間過長，該方法 也會成為一個熱點（在 13 行）。

方法 buildNewStat 就其本身來說似乎絕不會成為一個熱點。即使被多次執行，每次調用都會在幾納秒內完成。另一方面，若給每次調用增加了 2500 納秒的測量採集干擾，則無論 SQL 何時被執行，都勢必會讓該方法看起來像個熱點。因此，我們要避免測量它。

建立完整的運行分析

使用EurekaJ 建立一個完整的運行分析，需要以下幾個主要部分：

• 準備需要監測/操縱的程式；
• BTrace - java 代理；
• 告知BTrace 如何測量的 BTrace 腳本；
• 存儲BTrace 輸出的文件系統；
• 將 BTrace 輸出傳輸到EurekaJ 管理器的 EurekaJ 代理；
• 安裝好的EurekaJ 管理器（本地安裝或可通過互聯網訪問的遠程安裝）。

關於這些產品的完整安裝手冊，請訪問EurekaJ 項目網站(http://eurekaj.haagen.name/)。

總結

這篇文章給我們介紹了一些用於程式運行分析的開源工具，它們不僅能幫我們完成對運行中JVM 的深度分析，而且可以幫助我們對開發、測試和程式部署進行多方位的持續監測。希望你已經開始了解不斷收集度量資訊的好處和超過閾值後及時報警能力的重要性。 非常感謝！