http://www.ibm.com/developerworks/cn/websphere/library/techarticles/1406_tuzy_javacore/1406_tuzy_javacore.html
通過 Javacore 診斷線程掛起等性能問題
WebSphere Commerce 性能問題診斷與解決系列
隨着電子商務應用的廣泛應用和用戶體驗度的提升,對一個生產環境的突發問題的快速診斷和解決以及系統恢復變得越來越關鍵。一般情況下,我們會有一定的監控,恢復的流程和手段,包括搜集相應的信息並進行相應的分析。本文中會着重介紹一下如何分析 Javacores(Javadumps)來診斷出線程掛起,死鎖,資源爭搶等資源瓶頸等問題,並以一個 WC 線程死鎖的案例來幫助大家分析理解 Javacore,從而確定相應的解決方案。
0 評論:
Javacore 與 WebSphere Commerce 性能問題
近年來,依據 WebSphere Commerce(以下簡稱為 WC)搭建的電子商務網站系統日益增多。由於系統本身的復雜性,一旦系統出現問題,尤其是性能問題,問題診斷和定位就會非常困難。下圖所示為由 WC 系統為核心搭建的電子商務網站的一般邏輯架構 , 如圖 1 所示:
圖 1. 電子商務網站的一般邏輯架構

在整個系統架構中,核心應用邏輯運行在 WebSphere 應用服務器上。當系統出現性能問題時,雖然實際問題的根源可能分布在各個節點上,但是通過在應用服務器上的線程運行狀態分析,都有助於對整個系統的當前狀態以及可能的問題根源進行快速定位。WebSphere 應用服務器運行在 JVM(Java 虛擬機)之上。所以掌握通過 Javacore 進行 Java 線程分析,對於解決 WC 系統中的性能問題至關重要。
本文介紹如何通過 Javacore 文件分析線程運行狀態,以及輔助分析工具的使用。並通過實例講解如何利用 Java 線程分析解決 WC 系統中的性能問題。本文所介紹的分析方法對於其他基於 JavaEE 構建的企業應用也有借鑒意義。
如何通過 Javacore 了解線程運行狀況
Javacore 是一個當前 JVM 運行狀態的快照。通過對 Javacore 的分析,可以了解在 JVM 中運行的應用程序的當前狀態,比如是否“卡”在某一點上,或在某些代碼上運行時間太長。
Javacore 的基本內容
Javacore,也可以稱為“threaddump”或是“javadump”,它是 Java 提供的一種診斷特性,能夠提供一份可讀的當前運行的 JVM 中線程使用情況的快照。即在某個特定時刻,JVM 中有哪些線程在運行,每個線程執行到哪一個類,哪一個方法。
應用程序如果出現不可恢復的錯誤或是內存泄露,就會自動觸發 Javacore 的生成。而為了性能問題診斷的需要,我們也會主動觸發生成 Javacore。在 AIX、Linux、Solaris 環境中,我們通常使用 kill -3 <PID> 產生該進程的 Javacore。IBM Java6 中產生 Javacore 的詳細方法可以參考文章 [1]。
對於 IBM JVM,AIX 平台上的 Javacore 會被寫到 javacore.<date>.<time>.<PID>.<sequence>.txt 中。對於 Oracle JVM,Javacore 被附加到 native_stdout.txt。Javacore 的內容有兩列,第一列是“類型”,第二列表示“數據”,如清單 1 所示:
清單 1
1TISIGINFO Dump Event "user" (00004000) received 1TIDATETIME Date: 2013/12/22 at 23:05:18 1TIFILENAME Javacore filename: /usr/WebSphere/AppServer/profiles/demo_solr/javacore.20131222.230518.7995516.0004.txt
通常情況下,Javacore 中除了線程信息外,還能提供關於操作系統,應用程序環境,線程,程序調用棧,鎖,監視器和內存使用等相關信息。
為了便於分析,Javacores 的每一段的開頭,都會用“----------”和上一信息塊區分開來。每一信息塊的標題會以“=========”來標識,很容易找到,如清單 2 所示:
清單 2
NULL ------------------------------------------------------------------------ 0SECTION GPINFO subcomponent dump routine NULL ================================ 2XHOSLEVEL OS Level : AIX 7.1 2XHCPUS Processors - 3XHCPUARCH Architecture : ppc64 3XHNUMCPUS How Many : 8 3XHNUMASUP NUMA is either not supported or has been disabled by user NULL 1XHERROR2 Register dump section only produced for SIGSEGV, SIGILL or SIGFPE. NULL
Javacore 文件中,每行都包含一個標簽,這個標簽最多由 15 個字符組成。第一位數字表示信息的詳細級別,級別越高代表信息越詳細。接着的兩個字符是段標題的縮寫,例如:“CI”表示 Command line interpreter,“CL”表示 Class loader,“LK”表示 Locking,“ST”表示 Storage,“TI”表示 Title,“XE”表示 Execution engine 等。余下的字符表示信息的概述。如下清單 3 所示:
清單 3
3XMTHREADINFO "Thread-18" J9VMThread:0x00000000308DA900, j9thread_t:0x0000010016C4F2E0, java/lang/Thread:0x000000004136E3E8, state:P, prio=5
雖然不同版本的 JVM 所產生的 Javacore 的格式會稍有不同,但基本都包含下面幾個內容:
TITLE 信息塊:描述 Javacore 產生的原因,時間以及文件的路徑。常見的 Javacore 產生的原因可以參考文章 [2]。最常見的有下面三種:
user:SIGQUIT 信號
gpf:程序一般保護性錯誤導致系統崩潰
systhrow:JVM 內部拋出的異常
GPINFO 信息塊:GPF(一般保護性錯誤)信息
ENVINFO 信息塊:系統運行時的環境和 JVM 參數
MEMINFO 信息塊:內存使用情況和垃圾回收情況
LOCKS 信息塊:用戶監視器(monitor)和系統監視器(monitor)情況
THREADS 信息塊:所有 java 線程的狀態信息和執行堆棧
CLASSES 信息塊:類加載信息
Javacore 中的線程可分為以下幾種狀態:
- 死鎖(Deadlock)【重點關注】:一般指多個線程調用間,進入相互資源占用,導致一直等待無法釋放的情況。
- 執行中(Runnable)【重點關注】:一般指該線程正在執行狀態中,該線程占用了資源,正在處理某個請求,有可能在對某個文件操作,有可能進行數據類型等轉換等。
- 等待資源(Waiting on condition)【重點關注】:等待資源,如果堆棧信息明確是應用代碼,則證明該線程正在等待資源,一般是大量讀取某資源、且該資源采用了資源鎖的情況下,線程進入等待狀態。又或者,正在等待其他線程的執行等。
- 等待監控器檢查資源(Waiting on monitor)
- 暫停(Suspended)
- 對象等待中(Object.wait())
- 阻塞(Blocked)【重點關注】:指當前線程執行過程中,所需要的資源長時間等待卻一直未能獲取到,被容器的線程管理器標識為阻塞狀態,可以理解為等待資源超時的線程。這種情況在應用的日志中,一般可以看到 CPU 飢渴,或者某線程已執行了較長時間的信息。
- 停止(Parked)
通過對 Javacore 數據的分析經驗,結合對具體應用代碼邏輯的理解,有經驗的工程師可以直接通過文本編輯器查看原始 Javacore 文件來分析當前應用程序的運行狀態。一般初學者則需要通過一些工具進行更直觀的分析。
圖形化分析工具 TMDA
有很多圖形化工具可以用於 Javacore 的分析。筆者常用的工具為:IBM Thread and Monitor Dump Analyzer for Java 工具,簡稱 TMDA。TMDA 提供以下功能:
- 提供一個簡潔的 Javacore 內容的總結,包括一些初步的預警信息,線程柱狀圖,內存使用情況信息等等。
- 方便地分析線程棧和監視器(monitor)的用戶接口
- 方便地進行多個 Javacore 中的線程棧和監視器進行比較的用戶接口
無論是初學者還是性能分析專家都可以使用 TMDA 進行 Javacore 的快速分析。關於 TMDA 的更多介紹可以參考它的社區:參考文獻 [3]
WC 線程執行堆棧分析
不論是否利用 TMDA 工具進行分析,對 Javacore 的分析最終都會落實在具體線程的執行堆棧上。如果對具體應用的代碼不熟悉,那么看着一個個長長的執行堆棧,可能會覺得無從下手。本部分介紹 WC 線程執行堆棧的常見代碼和對應的功能模塊。初學者可以根據這些示例推測某個線程的當前運行狀態。需要注意的是,WC 的不同版本,同樣的功能模塊的具體代碼可能會發生變化,經過用戶定制的代碼就更是千差萬別。本部分提供的只是依據 WC FEP7 版本代碼的一些示例,讀者需要根據自己所處理的系統的實際代碼情況靈活掌握,不可拘泥。
通常一個 Javacore 里面會有上百個線程,這些線程的地位並不一樣。有些線程是系統運行的“入口線程”,而其他一些線程只是由這些線程派生出來的輔助線程。所以 Javacore 分析過程中一定要抓住這些主要線程。
WC 的核心是一個 Web 應用,所以大部分 WC 的 Javacore 以應用服務器的 Web 容器為入口。用來處理前台商店或后台管理端的 JVM 基本類似,但專門運行定時任務的 JVM 會有所區別。下圖 2 所示為以 Web 容器為入口線程的一般調用結構:
圖 2. 調用結構

從 Web 容器入口開始,一般會進入 Servlet 執行。如果有緩存而且命中的話,則會進入 DynaCache 的相關代碼。如果無緩存或緩存不命中,如果是 JSP 頁面,則會執行 JSP 的相關代碼,否則會執行相應的邏輯。代碼邏輯處理過程中,經常會訪問到數據庫(通過 DSL 或 EJB)或 Solr 搜索(通過 BOD 或 REST),還有可能訪問到外部系統集成接口(通過 HTTP 同步調用或消息隊列)。如果數據庫服務器 / 搜索服務器 / 系統集成服務器分布在其他節點上,那么這些調用最終都會轉化為網絡訪問。
以下為一個正在處理 JSP 頁面中的數據庫請求的執行堆棧示例,如圖 3、4、5:
圖 3. 堆棧實例(1)

圖 4. 堆棧實例(2)

圖 5. 堆棧實例(3)

自下而上的關鍵代碼:
- Web 容器處理請求
Package 名 / 類名 . 方法名:com.ibm.ws.webcontainer/WebContainer.handleRequest
- RuntimeFilter
Package 名 / 類名 . 方法名:com.ibm.commerce.webcontroller/RuntimeServletFilter.doFilterAction
- Servlet 處理
Package 名 / 類名 . 方法名:com.ibm.commerce.struts/ECActionServlet.doGet
或者
Package 名 / 類名 . 方法名:com.ibm.commerce.struts/ECActionServlet.doPost
- JSP 處理
Package 名 / 類名 . 方法名:com.ibm._jsp/_(JSP 文件名 )._jspService
- Command 執行(圖例為 BOD command)
Package 名 / 類名 . 方法名:com.ibm.commerce.*/Abstract(*)CmdImpl.performExecute
- DSL
Package 名 / 類名 . 方法名:com.ibm.commerce.foundation.server.services.dataaccess/AbstractDataServiceFacade.*
- JDBC
查詢
Package 名 / 類名 . 方法名:com.ibm.ws.rsadapter.jdbc/WSJdbcPreparedStatement.executeQuery
或 Package 名 / 類名 . 方法名:com.ibm.ws.rsadapter.cci/WSResourceAdapterBase.executeQuery
更新
Package 名 / 類名 . 方法名:com.ibm.ws.rsadapter.jdbc/WSJdbcPreparedStatement.executeUpdate
或 Package 名 / 類名 . 方法名:com.ibm.ws.rsadapter.cci/WSResourceAdapterBase.executeUpdate
- 數據庫驅動代碼
DB2
Package 名:com.ibm.db2.*
Oracle
Package 名 / 類名 . 方法名:oracle.jdbc.driver/OraclePreparedStatement.executeInternal
- 外部網絡訪問
(網絡讀)Package 名 / 類名 . 方法名:java.net/SocketInputStream.socketRead0
(網絡寫)Package 名 / 類名 . 方法名:java.net/SocketOutputStream.socketWrite0
其他常見的執行堆棧舉例:
- 空閑(Idle)
這樣的堆棧表示當前線程處於空閑狀態(對於 Web 容器而言,即當前線程沒有接收到 Web 請求)。其調用棧為:
Package 名 / 類名 . 方法名:java.lang/Object/wait
…
Package 名 / 類名 . 方法名:com.ibm.ws.util/ThreadPool$Worker. run
或者
Package 名 / 類名 . 方法名:com.ibm.io.async/AsyncLibrary. aio_getioev*
…
Package 名 / 類名 . 方法名:com.ibm.ws.util/ThreadPool$Worker. run
圖 6 示例截圖
- 事務(Transaction)處理
提交(Commit)
Package 名 / 類名 . 方法名:com.ibm.commerce.server/TransactionManager.commit
回滾(Rollback)
Package 名 / 類名 . 方法名:com.ibm.commerce.server/TransactionManager.rollback
- 緩存(DynaCache)讀取
Package 名 / 類名 . 方法名:com.ibm.ws.cache/Cache.getEntry(或 getCacheEntry)
基於 WXS 的緩存則為
Package 名 / 類名 . 方法名:com.ibm.ws.objectgrid.dynacache/RemoteCoreCacheImpl.get
- MultiClick 處理
Package 名 / 類名 . 方法名:com.ibm.commerce.webcontroller.doubleclick/MultiClickRequestHandler. waitForResponse
- 消息處理(MQ)
Package 名 / 類名 . 方法名:com.ibm.mq.jmqi.remote.internal/RemoteRcvThread.run
- 搜索(Solr)處理
Package 名 / 類名 . 方法名:org.apache.solr.client.solrj/SolrServer.query
- REST 處理
Package 名 / 類名 . 方法名:com.ibm.commerce.foundation.internal.client.util/RESTHandler.execute
前面作者已經強調,不同版本的 WC 代碼或者經過定制的代碼會有不同。讀者必須在實際系統開發運維過程中積累經驗,形成自己的代碼樣例“庫”。這樣才能在長長的執行堆棧中迅速抓住關鍵信息。
案例分析
本部分通過兩個具體實例講解如何通過 Javacore 分析來分析解決 WC 系統中的性能問題。當系統出現性能問題的時候,通常系統的工作狀態會發生某些異常。我們的任務就是通過 Javacore 分析來找出系統關鍵線程的運行狀態變化。這里一般都需要獲取多次 Javacore 並進行比較,發現哪些是“變”的部分,哪些是“不變”的部分。所以,誰和誰比,比什么,是分析問題的關鍵。
邏輯死鎖問題
Javacore 分析經常用於解決邏輯死鎖問題。使用 TMDA 工具,可以在圖形界面中快速找出不同線程之間的等待關系,如圖 7 所示:
圖 7. TMDA 工具圖形界面

如果在同一個 JVM 內部出現了線程之間循環等待的狀況,就會進入線程之間的死鎖(Deadlock)狀態。對於未定制的 WC 系統而言,直接出現這樣的死鎖問題的可能性比較小。較常見的是在整個系統的不同節點之間出現的邏輯死鎖問題,這種問題一般不能直接在 Javacore 中識別出來。本節通過一個 WC 內部測試過程中遇到的案例介紹如何分析解決這種邏輯死鎖問題。
這是一個隨機瀏覽產品目錄的測試場景。在這個場景中,WC 應用服務器接收請求,並調用搜索服務器上的索引進行處理。簡化后的系統架構圖(省略了 Web 服務器)如圖 8 所示:
圖 8. 簡化的系統架構圖

這里,搜索服務器在處理過程中會有一次回調到應用服務器,通過應用服務器獲取某些搜索所需的數據。
我們對這個測試場景進行了用戶數遞增的壓力測試,正常情況下,我們期望看到的結果是隨着用戶數的增加,系統的吞吐量逐漸上升,最后達到一個平穩狀態(達到 CPU 瓶頸)。但是實際測試過程中看到的現象卻是,當並發用戶數增加到某個數值的時候,系統吞吐率突然下降,最終降低到 0,如圖 9、10。
圖 9. 並發用戶數

圖 10. 吞吐率

此時,我們監控兩個節點上的 CPU 使用狀況。發現吞吐量降低為 0 的同時,CPU 使用率也幾乎降低為 0。因此,初步可以判斷系統出現了邏輯死鎖問題。反之,如果某個節點上的 CPU 使用率(或其他資源使用率)很高,則有可能是邏輯死循環或其他代碼實現問題。
要想進一步分析就需要通過 Javacore 分析獲取當前 JVM 的運行狀態信息。這里我們需要分別在應用服務器和搜索服務器端獲取 Javacore(采樣的時間點要同步)。采樣點可以做三次,在吞吐率下降前采樣一次,下降后采樣兩次(中間間隔 30 秒以上)。然后對這三次 Javacore 進行對比分析。
在 TMDA 中打開采樣到的 Javacore 文件。TMDA 提供的“Compare Threads”功能可以用來比較這些 Javacore 文件:
圖 11. TMDA 比較菜單

先來看 WC 應用服務器端的 Javacore 文件。前文已經解釋過 Web 容器通常是整個應用的入口,所以我們重點關注 Web 容器相關線程的狀態。TMDA 比較的結果如圖 12 所示:
圖 12. TMDA 比較結果

用黃底色表示(TMDA 的不同版本顯示效果可能略有區別)的線程表示在兩次采樣中的狀態相同(執行堆棧相同)。這里可以很清楚地看到在第二次和第三次采樣點上,所有 Web 容器的線程執行狀態都相同,系統已經進入了假死(HANG)狀態(注意這兩次采樣發生在系統吞吐率降為 0 之后)。
這里需要注意,在第一個采樣點(系統吞吐率下降之前),還有很多線程處於“阻塞”(Blocked)狀態。而在第二、第三個采樣點上,除了個別線程處於阻塞狀態外,多數線程都處於“執行中”(Runnable)狀態。由此可見,不能完全依賴 Javacore 中標明的線程狀態來判斷當前系統的狀態,關鍵還是要看執行堆棧中實際在執行的代碼。處於“執行中”狀態的線程可能實際在等待,而處於“等待資源”(Waiting on condition)狀態的線程可能實際是“執行中”狀態。
我們進一步分析第二、第三個采樣點上,Web 容器各線程的執行堆棧。我們發現,雖然下層處理的頁面(JSP)各有不同,但是頂層處於運行中的代碼都一樣:
圖 13. 執行堆棧

基本上所有的 Web 容器線程都在等待 REST 請求的網絡返回。根據前面描述的簡化后的系統結構圖,可以推斷所有線程都在等候搜索服務器的處理結果。這是作者根據對系統結構的理解進行的判斷,如果讀者在實際問題分析過程中無法確定,可以使用 netstat 進行網絡監控,根據 HTTP 鏈接的建立情況進一步確認。
下一步,我們再比較搜索服務器端的三個時間點上的 Javacores 文件。結果是類似的,同樣第二個和第三個采樣點上 Web 容器的所有線程都進入了假死(HANG)狀態:
圖 14. 三個采樣點比較結果

我們再來看看搜索服務器端處於“執行中”的線程都在干什么。基本上所有執行堆棧的頂端都在執行如下代碼:
圖 15. 執行堆棧代碼

經過代碼分析,我們發現這是搜索服務器端在通過 REST 回調 WC 應用服務器,獲取 BCS(BusinessConextService)相關的數據。
這樣的調用關系為什么會導致邏輯上的死鎖呢?關鍵在於對 Web 容器的線程池資源的競爭上。每個 WC 端接收到的請求在處理過程中需要占用 Web 容器的線程池的一個線程資源,而這個處理邏輯在處理過程中請求了搜索服務器端,又通過搜索服務器端回調到 WC 端,這就需要占用 Web 容器的線程池的另一個線程資源。
這個邏輯關系可以簡化為圖 16:
圖 16. 簡化邏輯關系圖

在應用服務器的 Web 容器線程池資源上,通過搜索服務器的回調形成了一個閉環。這類似於標准的“哲學家就餐問題”,如果所有的請求都占用了第一個線程資源,而請求第二個線程資源,那么所有的線程都會阻塞在這個狀態上,形成死鎖。要解決這個線程死鎖問題,必須消除這個資源占用上的閉環。可以采取的方案包括消除從 Search 端的 REST 回調,建立一個獨立的線程池專門負責處理 Search 端的回調,等等。
尋找性能瓶頸
除了分析邏輯死鎖問題外,Javacore 分析也可以用於尋找性能瓶頸。一般來說,尋找代碼邏輯中的性能瓶頸,需要對代碼的執行路徑進行 Profiling(執行統計分析)。Profiling 工具一般有兩種。能夠提供完整執行堆棧的工具一般都是侵入式的,運行開銷很高,並不適於在高負載的生產環境中使用。基於采樣(sampling)的工具運行開銷很小,但通常都不提供完整的執行堆棧。這里其實可以把 Javacore 分析當作輔助的 Profiling 工具來用。每個 Javacore 都提供了在某一時刻正在運行的代碼的執行堆棧,這可以看作一個采樣點。如果多做幾次采樣點,那么根據這些 Javacore 數據就可以進行一個執行路徑的粗略 Profiling(不過總體采樣點數量比真正的 Profiling 工具少很多)。
我們仍以一個 WC 產品測試過程中遇到的問題為例介紹這種分析方法。
我們在某個產品開發的版本測試過程中發現,搜索結果頁面(SearchResultDisplay)的性能比前一個版本下降了很多。為了找出性能下降的原因,我們對該頁面進行了單場景壓力測試。當系統性能進入穩定狀態后,我們在 WC 應用服務器端做了 Javacore 數據采樣。
同樣,我們的入口線程仍是 Web 容器的線程。這里要解決的是性能下降問題(系統 CPU 占用率很高),而不是邏輯死鎖問題。所以我們關注的重點是同一次采樣內部線程之間的橫向比較,而不是多次采樣之間的橫向比較,所以只需要用到 TMDA 的線程分析功能,而不需要使用線程比較功能。
如果關注於執行堆棧的頂部代碼,我們發現 Web 容器各線程的執行狀況比較分散,似乎沒有什么規律。但是如果從執行堆棧的底部往上看,就會發現某些規律。這里我們發現在 Web 容器的 25 個線程(等於線程池的大小)中,有一半以上的執行堆棧在執行如下圖 17 代碼:
圖 17. 執行代碼

由於這是單場景壓力測試,基本上所有的 Web 容器線程都在執行相同的 JSP:SearchBasedCategoryPage。如果這個 JSP 里面沒有明顯的性能瓶頸,那么 Web 容器的 25 個線程應該隨機運行在這個 JSP 的不同代碼邏輯之中。我們實際觀察到的現象則是有一半以上的線程都在執行如下代碼:
com/ibm/commerce/infrastructure/facade/client/AbstractInfrastructureFacadeClient.getOnlineStore
為了排除代碼執行隨機性的影響,我們又在隨后的系統執行過程中多做了幾次采樣,仍然得到了類似的結果。
這就表示該代碼有可能是整個 JSP 邏輯中的性能瓶頸(當然還不能完全確定)。另一方面,通過與前一個版本的 Javacore 進行對比分析,發現前一版本的 Javacore 中並沒有出現該代碼。這說明該代碼是當前版本新引入的代碼。通過進一步的代碼分析發現,這是在當前版本中新加入的一段處理客戶定制邏輯的新代碼。我們屏蔽了該端代碼后,重新進行了性能測試,發現性能基本上可以恢復到前一版本的水平。因此最終可以確定是這段代碼導致了當前版本的性能下降問題。
如何解決這類性能問題呢?首先應該是評估原始的實現邏輯,是否需要在每一個頁面請求的處理過程中執行這段邏輯。如果不需要,則可以直接屏蔽該代碼段。如果這一段邏輯必須在每一個頁面請求中執行,則可以考慮引入適當的緩存機制,降低重復執行時的開銷。
這種分析方法也可以用於在客戶生產系統中快速定位整個系統的性能瓶頸。生產系統執行的頁面請求是多種多樣的,通常情況下,在生產系統上做 Javacore 應該找不到什么規律。反之,如果多次采樣可以發現系統在高負載運行狀態下,Web 容器線程的執行堆棧存在某些規律,比如:大部分線程都在執行目錄頁面(CategoryDisplay)顯示。而頁面訪問統計的結果顯示,目錄頁面的訪問頻率並不比其他頁面高很多。這種情況下就很有可能在 CategoryDisplay 頁面有性能瓶頸。下一步就可以進行單場景的壓力測試來進一步尋找 CategoryDisplay 頁面邏輯中的性能瓶頸。
如果能將 Javacore 分析的結果,與其他基於采樣的 Profiling 工具的分析結果相結合,則更容易快速找到代碼中的性能瓶頸。