玩過性能優化的朋友都清楚，性能優化的關鍵並不在於怎麽進行優化，而在於怎麽找到當前系統的性能瓶頸。
性能優化分為好幾個層次，比如系統層次、算法層次、代碼層次…JVM 的性能優化被認為是底層優化，門檻較高，精通這種技能的人比較少。筆者呆過幾家技術力量不算弱的公司，每個公司內部真正能夠進行 JVM 性能調優的人寥寥無幾、甚至沒有。如是乎，能夠有效通過 JVM 調優提升系統性能的人往往被人們冠以”大牛”、”大師”之類的稱呼。
其實 JVM 本身給我們提供了很多強大而有效的監控進程、分析定位瓶頸的工具，比如 JConsole、JMap、JStack、JStat 等等。使用這些命令，再結合 Linux 自身提供的一些強大的進程、線程命令，能夠快速定位系統瓶頸。本文以一次使用這些工具準確定位到某系統瓶頸的實戰經驗為例，希望能為大家掌握 JVM 調優這項技能起到一些借鑒作用。

Linux：RedHat 6.1
Weblogic：11g
JRokit：R28.2.4
JDK：1.6.0_45
Weblogic 跑在 JRokit 上面，JDK 是我們對 JRokit 進行監控分析的工具。

1. LoadRunner 壓測結果

該系統其實早已跑在生產上好多年，雖然沒有做過壓力測試，但穩定性還是可以的。公司進行架構調整，有一些新系統將對接該系統。公司領導擔心對接後該系統的並發性能問題，於是開始對該系統進行並發壓力測試。
50 個用戶並發壓十幾個小時，TRT 在 20 左右，TPS 在 2.5 左右。領導對這個結果不滿意，要求進行優化。但這是個老系統，開發在之前明顯已經對其代碼做過很多優化，如今面對這種狀況也束手無策。

2. Oracle 的 awr 報告分析

有句老話，優化來優化去，系統的性能瓶頸還是會在數據庫上面。在這裏我們首先想到的也是數據庫的問題。
並發壓測的時候 Spotlight 查看數據庫服務器各項性能指標，很清閑。

分析 awr 報告，結果顯示也是很清閑。

並發壓測的時候去相關數據表執行一些 sql 的速度很快也證明著問題不在 Oracle 這邊。

3. Weblogic 服務器的性能指標

使用 Spotlight 查看並發壓測時的 Weblogic 所在的 Linux 服務器，除了 CPU 之外其它各項指標顯示，Linux 也很清閑。
雖然 CPU 利用率始終在 200% 左右徘徊，但這對於 16 核的系統來講也算是正常的吧？

4. JStack 報告分析

事情到了這裏，大家已經想到了線程死鎖、等待的問題了。
沒錯，JStack 隆重登場。JStack 能夠看到當前 Java 進程中每個線程的當前狀態、調用棧、鎖住或等待去鎖定的資源，而且很強悍的是它還能直接報告是否有線程死鎖，可謂解決線程問題的不二之選。
$ /opt/jdk1.6.0_45/bin/jstack -l 10495 > ~/10495jstack.txt
JRokit 堆棧的拉取，可以直接用 JDK 的 JStack，10495 是 Weblogic 服務的進程 ID。註意一定要用該進程的啟動用戶去拉，否則會報 Unable to open socket file: target process not responding or HotSpot VM not loaded 錯誤。
JStack 拉取的文件信息基本分為以下幾個部分：

該拉取快照的服務器時間
JVM 版本
以線程 ID(即 tid)升序依次列出當前進程中每個線程的調用棧
死鎖(如果有的話)
阻塞鎖鏈
打開的鎖鏈
監視器解鎖情況跟蹤
每個線程在等待什麽資源，這個資源目前在被哪個線程 hold，盡在眼前。JStack 最好在壓測時多次獲取，找到的普遍存在的現象即為線程瓶頸所在。

4.1. TLA 空間的調整

多次拉取 JStack，發現很多線程處於這個狀態：
at jrockit/vm/Allocator.getNewTla(JJ)V(Native Method)
at jrockit/vm/Allocator.allocObjectOrArray(Allocator.java:354)[optimized]
at java/util/HashMap.resize(HashMap.java:564)[inlined]
at java/util/LinkedHashMap.addEntry(LinkedHashMap.java:414)[optimized]
at java/util/HashMap.put(HashMap.java:477)[optimized]
由此懷疑出現上述堆棧的原因可能是 TLA 空間不足引起。TLA 是 thread local area 的縮寫，是每個線程私有的空間，所以在多線程環境下 TLA 帶來的性能提升是顯而易見的。如果大部分線程的需要分配的對象都較大，可以考慮提高 TLA 空間，因為這樣更大的對象可以在 TLA 中進行分配，這樣就不用擔心和其它線程的同步問題了。但這個也不可以調的太大，否則也會帶來一些問題，比如會帶來更多內存碎片、更加頻繁的垃圾搜集。
TLA 默認最小大小 2 KB，默認首選大小 16 KB – 256 KB (取決於新生代分區大小)。這裏我們調整 TLA 空間大小為最小 32 KB，首選 1024 KB，JVM 啟動參數中加入：
-XXtlaSize:min=32k,preferred=1024k

5. JStat 結合 GC 日誌報告分析

第 4 步參數生效之後繼續壓測，TLA 頻繁申請是降下來了，但 TRT 仍舊是 20，TPS 依舊 2.5。別灰心，改一個地方就立竿見影，勝利似乎來得太快了點。
現在懷疑是服務堆內存太小，查看一下果然。服務器物理內存 32 GB，Weblogic 進程只分到了 6 GB。怎麽查看？至少有四種辦法：

5.1. ps 命令

$ ps -ef | grep java
defonds 29874 29819 2 Sep03 ? 09:03:17 /opt/jrockit-jdk1.6.0_33/bin/java -jrockit -Xms6000m -Xmx6000m -Dweblogic.Name=AdminServer -Djava.security.policy=

5.2. Weblogic 控制臺

登錄 Weblogic 管理控制臺 -> 環境 -> 服務器，選擇該服務器實例 -> 監視 -> 性能 -> 當前堆大小。
這個頁面還能看到進程已運行時間，啟動以來發生的 GC 次數，可以折算出 GC 的頻率，為本次性能瓶頸 – GC 過於頻繁提供有力的佐證。

5.3. GC 日誌報告

開啟 JRokit GC 日誌報告只需在 Java 進程啟動參數裏加入
-Xverbose:memory -Xverboselog:verboseText.txt
GC 日誌將會被輸出到 verboseText.txt 文件，這個文件一般會生成在啟動的 Weblogic 域目錄下。如果找不著也可以用 find 命令去搜：
$ find /appserver/ -name verboseText.txt
/appserver/Oracle/Middleware/user_projects/domains/defonds_domain/verboseText.txt
GC log 拿到後，第 3 行中的 maximal heap size 即為該進程分配到的最大堆大小：
[INFO ][memory ] Heap size: 10485760KB, maximal heap size: 10485760KB, nursery size: 5242880KB.
下面還有進程啟動以後較為詳細的每次 GC 的信息：
[INFO ][memory ] [YC#2547] 340.828-340.845: YC 10444109KB->10417908KB (10485760KB), 0.018 s, sum of pauses 17.294 ms, longest pause 17.294 ms.
[INFO ][memory ] [YC#2548] 340.852-340.871: YC 10450332KB->10434521KB (10485760KB), 0.019 s, sum of pauses 18.779 ms, longest pause 18.779 ms.
[INFO ][memory ] [YC#2549] 340.878-340.895: YC 10476739KB->10485760KB (10485760KB), 0.017 s, sum of pauses 16.520 ms, longest pause 16.520 ms.
[INFO ][memory ] [OC#614] 340.895-341.126: OC 10485760KB->10413562KB (10485760KB), 0.231 s, sum of pauses 206.458 ms, longest pause 206.458 ms.
第一行表示該進程啟動後的第 340.828 秒 – 340.845 秒期間進行了一次 young gc，該次 GC 持續了 17.294 ms，將整個已用掉的堆內存由 10444109 KB 降低到 10417908 KB。
第三行同樣是一次 young gc，但該次 GC 後已用堆內存反而上升到了 10485760 KB，也就是達到最大堆內存，於是該次 young gc 結束的同時觸發 full gc。
第四行是一次 old gc (即 full gc)，將已用堆內存由 10485760 KB 降到了 10413562 KB，耗時 206.458 ms。
這些日誌同樣能夠指出當前壓力下的 GC 的頻率，為本次性能瓶頸 – GC 過於頻繁提供有力的佐證。

5.4. JStat 報告

跟 JStack 的拉取一樣，可以直接用 JDK 的 JStat 去拉取 JRokit 的 GC 信息：
$ /opt/jdk1.6.0_45/bin/jstat -J-Djstat.showUnsupported=true -snap 10495 > ~/10495jstat.txt
註意這個信息是一個快照，這是跟 GC 日誌報告不同的地方。
jrockit.gc.latest.heapSize=10737418240
jrockit.gc.latest.nurserySize=23100384
上述是當前已用碓大小和新生代分區大小。多拉幾次即可估算出各自分配的大小。

5.5. 內存分配

根據 5.1 – 5.4 我們得出當前服務器分配堆內存太小的結論，根據 5.3 GC 日誌報告和 5.4. JStat 報告可以得出新生代分區太小的結論。
於是我們調整它們的大小，結合 4.1 TLA 調整的結論，JVM 啟動參數增加以下：
-Xms10240m -Xmx10240m -Xns:1024m -XXtlaSize:min=32k,preferred=1024k
再次壓測，TRT 降到了 2.5，TPS 上升到 20。

6. 性能瓶頸的定位

很明顯，上述 JVM 調整沒有從根本上解決性能問題，我們還沒有真正定位到系統性能瓶頸。

6.1. 性能線程的定位

6.1.1. 性能進程的獲取

使用 TOP 命令拿到最耗 CPU 的那個進程：
性能進程號的獲取.png
進程 ID 為 10495 的那個進程一直在占用很高的 CPU。

6.1.2. 性能線程的獲取

現在我們來找到這個進程中占用 CPU 較高的那些線程：
$ ps p 10495 -L -o pcpu,pid,tid,time,tname,cmd > ~/10495ps.txt
多次拉這個快照，我們找到了 tid 為 10499、10500、10501、10502 等線程一直在占用著很高的 CPU：
tid為10499、10500、10501、10502等線程占用CPU很高.png
拉 JStack 快照看看都是一些什麽線程：
$ /opt/jdk1.6.0_45/bin/jstack -l 10495 > ~/10495jstack.txt
相關部分結果如下：
“(GC Worker Thread 1)” id=? idx=0×10 tid=10499 prio=5 alive, daemon
at pthread_cond_wait@@GLIBC_2.3.2+202(:0)@0x3708c0b44a
at eventTimedWaitNoTransitionImpl+71(event.c:90)@0x7fac47be8528
at eventTimedWaitNoTransition+66(event.c:72)@0x7fac47be8593
at mmGCWorkerThread+137(gcthreads.c:809)@0x7fac47c0774a
at thread_stub+170(lifecycle.c:808)@0x7fac47cc15bb
at start_thread+208(:0)@0x3708c077e1
Locked ownable synchronizers:

• None

“(GC Worker Thread 2)” id=? idx=0×14 tid=10500 prio=5 alive, daemon
at pthread_cond_wait@@GLIBC_2.3.2+202(:0)@0x3708c0b44a
at eventTimedWaitNoTransitionImpl+71(event.c:90)@0x7fac47be8528
at eventTimedWaitNoTransition+66(event.c:72)@0x7fac47be8593
at mmGCWorkerThread+137(gcthreads.c:809)@0x7fac47c0774a
at thread_stub+170(lifecycle.c:808)@0x7fac47cc15bb
at start_thread+208(:0)@0x3708c077e1
Locked ownable synchronizers:

• None

“(GC Worker Thread 3)” id=? idx=0×18 tid=10501 prio=5 alive, daemon
at pthread_cond_wait@@GLIBC_2.3.2+202(:0)@0x3708c0b44a
at eventTimedWaitNoTransitionImpl+71(event.c:90)@0x7fac47be8528
at eventTimedWaitNoTransition+66(event.c:72)@0x7fac47be8593
at mmGCWorkerThread+137(gcthreads.c:809)@0x7fac47c0774a
at thread_stub+170(lifecycle.c:808)@0x7fac47cc15bb
at start_thread+208(:0)@0x3708c077e1
Locked ownable synchronizers:

• None

“(GC Worker Thread 4)” id=? idx=0x1c tid=10502 prio=5 alive, daemon
at pthread_cond_wait@@GLIBC_2.3.2+202(:0)@0x3708c0b44a
at eventTimedWaitNoTransitionImpl+71(event.c:90)@0x7fac47be8528
at eventTimedWaitNoTransition+66(event.c:72)@0x7fac47be8593
at mmGCWorkerThread+137(gcthreads.c:809)@0x7fac47c0774a
at thread_stub+170(lifecycle.c:808)@0x7fac47cc15bb
at start_thread+208(:0)@0x3708c077e1
Locked ownable synchronizers:

• None

6.2. 找到性能瓶頸

事情到了這裏，已經不難得出當前系統瓶頸就是頻繁 GC。
為何會如此頻繁 GC 呢？繼續看 JStack，發現這兩個互相矛盾的現象：
一方面 GC Worker 線程在拼命 GC，但是 GC 前後效果不明顯，已用堆內存始終降不下來；
另一方面大量 ExecuteThread 業務處理線程處於 alloc_enqueue_allocation_and_wait_for_gc 的 native_blocked 阻塞狀態。
此外，停止壓測以後，查看已用堆內存大小，也就幾百兆，不到分配堆內存的 1/10。

總結：

這說明了什麽呢？這說明了我們應用裏沒有內存泄漏、靜態對象不是太多、有大量的業務線程在頻繁創建一些生命周期很長的臨時對象。
很明顯還是代碼裏有問題。那麽這些對象來自哪裏？如何在海量業務代碼裏邊準確定位這些性能代碼？也就是說如何利用 JVM 調優驅動代碼層面的調優？請參考博客《JVM 性能調優實戰之：使用阿裏開源工具 TProfiler 在海量業務代碼中精確定位性能代碼》，使用 TProfiler 我們成功找到了代碼裏邊導致 JVM 頻繁 GC 的元兇，並最終解決掉了這個性能瓶頸，將 TRT 降到了 0.5，TPS 提升至 100 +。

JVM 性能調優實戰之：一次系統性能瓶頸的尋找過程