歡迎您光臨本站 註冊首頁

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

←手機掃碼閱讀     火星人 @ 2014-03-12 , reply:0
  

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

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

好了,讓我們出發。

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

Jmap(藉助JPM的一點幫助)

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

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

圖1:jps命令的終端輸出

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

jmap –histo:live 45417

上述命令輸出如下:

(點擊圖片可以放大)

圖2:命令jmap -histo:live的輸出結果顯示了堆中現有對象的個數

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

本例中,我請同事有意給程序增加了一處明顯的內存泄露。請特別注意位於第8行的類,CelleData。將它與下圖顯示的4分鐘后截屏進行比較:

(點擊圖片可以放大)

圖3:jmap的輸出表明CelleData類的對象數目增加了

請注意CelleData類現在已經變為系統中第二多的類,短短4分鐘內已經增加了631,701個額外實例。等待約一小時后,我們觀察到如下結果:

(點擊圖片可以放大)

圖4:程序執行1小時后jmap的輸出結果,顯示超過2千5百萬個CelleData類實例

現在有超過2千5百萬個CelleData類實例,佔用了超過1GB內存!我們可以確認這是一個內存泄露。

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

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

VisualVM

另一個包含於JVM中的工具是VisualVM,它的開發者將它描述為“一種集成了多個JDK命令行工具的可視化工具,它能為您提供輕量級的運行分析能力”。這樣看來,VisualVM是另一種你最有可能用到的事後分析工具,一般是錯誤已出現或性能問題已經用傳統方法(客戶抱怨大多屬於此類)發現。

繼續之前的示常式序和它嚴重的內存泄露問題,在程序執行30分鐘后,VisualVM幫我們繪製了如下圖表:

圖5:程序初始運行的VisualVM 內存圖

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

藉助jmap,我們定位了這種內存消耗攀升的原因。修復后,我們讓程序重新運行於VisualVM的嚴格監測之下,觀察到下面的情況:

圖6:修復內存泄露問題后的VisualVM內存圖

如你所見,程序的內存曲線(啟動參數仍然為–Xmx3g)有了明顯改善。

除了內存圖像工具,VisualVM還提供了一個採樣器和一個輕量級的剖析器(Profiler)。

VisualVM採樣器能周期採樣程序CPU和內存的使用情況。得到的統計數據類似jmap的反饋,此外,你還可以通過採樣得到方法調用對CPU的佔用情況。它讓你能快速了解周期採樣過程中的方法執行次數:

(點擊圖片可以放大)

圖7:VisualVM方法執行時間表

VisualVM剖析器無需對程序周期採樣就可以提供類似採樣器的反饋信息,它還可以收集程序在整個正常執行過程中的統計數據(通過操縱程序源代碼的位元組碼)。從剖析器得到的這種統計數據比從採樣器而來的更精確和實時。

(點擊圖片可以放大)

圖8: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項目網站。

由於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,就此應運而生。

(點擊圖片可以放大)

圖9:激活方法分析時必需的BTrace腳本

EurekaJ

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

EurekaJ提供了兩個主要應用:

  1. 一個基於java的管理器程序,可以接收傳入的統計數據並一致地以可視化視圖展現出來
  2. 一個解析BTrace輸出的代理程序,將其轉化為JSON格式並輸入到EurekaJ管理程序的REST介面

EurekaJ接受兩種類型的輸入數據格式。EurekaJ代理期望BTrace腳本的輸出被格式化為逗號分隔的文件(這點在BTrace中可很容易做到),而EurekaJ管理程序期望它的輸入符合它的JSON REST介面格式。這意味著你能通過代理程序或直接經由REST介面來傳遞度量數據。

藉助EurekaJ管理程序,我們可以在一張圖上分組顯示多個統計數據、可以定義閾值和給接收者發出警報。我們還可以方便的查看收集到的實時數據或歷史數據。

所有收集到的數據排序成一種邏輯樹結構,其結構由BTrace腳本作者指定。我建議BTrace腳本的作者對相關統計數據分組,這樣,當它們顯示在EurekaJ中時會更容易理解和觀察。例如,我個人喜歡對統計數據進行如下的邏輯分組:

圖10:EurekaJ演示程序的統計分組示例

圖例

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

(點擊圖片可以放大)

圖11:顯示平均系統負載的EurekaJ圖表

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

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

(點擊圖片可以放大)

圖12:同時顯示多個圖表

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

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

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

(點擊圖片可以放大)

圖13:EurekaJ堆圖顯示內存溢出錯誤的一種可能情形

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

(點擊圖片可以放大)

圖14:前面圖表放大后的效果

EurekaJ使我們可以設置程序的堆內存警告,個人建議最好如此。若程序持續佔用堆內存超過95%-98%(取決於堆的大小),幾乎可以肯定,程序存在內存問題,要麼用–Xmx參數為程序分配更多的堆,要麼優化程序使其使用更少內存。同時,EurekaJ未來版本計劃增加統計數據不足的警報。

最後的圖表示例展示了一個包含4個不同程序內存使用的圖表組。這種類型的圖表組可方便用來比較一個程序不同部分的、或甚至不同程序之間、伺服器之間的數據。下圖的這4個程序有不同的內存需求和內存佔用模式。

如下圖示,不同程序有不同的內存曲線。這些曲線非常依賴一些實際情況,比如使用的架構、緩存數量、用戶數、程序負載等。我希望通過下圖說明你需要掌握程序在正常和高負載下執行情況的重要性,因為這將直接關係到如何定義報警閾值。

(點擊圖片可以放大)

圖15:EurekaJ圖組會將圖像彼此疊加在一起

注意性能干擾 – 讓非熱點區不受影響!

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

  • 基於“採樣”的度量通常可被認為“無影響”。採樣CPU負載、進程CPU負載、內存使用和每5-10秒的線程計數,其帶來的額外一兩個毫秒的影響可被忽略。在我看來,你應該經常收集這類統計數據,它們對你來說不會有什麼損耗。
  • 對長時間運行的任務的測量也可被認為“無影響”。通常,它僅會對每個被測量方法帶來1700-2500納秒的影響。如果你正測量這些對象的執行時間:SQL查詢、網路流量、硬碟讀寫或一個預期範圍在40毫秒(磁碟存取)到1秒(Servlet處理)之間的Servlet處理過程,那麼對這些對象每個增加額外的2500納秒左右的時間也是可接受的。
  • 絕對不要對循環內執行的方法進行測量

尋找程序熱點區的一個通用規則是不要影響非熱點區域。例如,考慮下面的類:


[火星人 ] 藉助開源工具高效完成Java應用的運行分析已經有404次圍觀

http://coctec.com/docs/program/show-post-71448.html