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

玩過性能優化的朋友都清楚，性能優化的關鍵並不在於怎麼進行優化，而在於怎麼找到當前系統的性能瓶頸。
性能優化分爲好幾個層次，好比系統層次、算法層次、代碼層次…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 的那個進程：

進程 ID 爲 10495 的那個進程一直在佔用很高的 CPU。

6.1.2. 性能線程的獲取

如今咱們來找到這個進程中佔用 CPU 較高的那些線程：
$ ps p 10495 -L -o pcpu,pid,tid,time,tname,cmd > ~/10495ps.txt
屢次拉這個快照，咱們找到了 tid 爲 1049九、10500、1050一、10502 等線程一直在佔用着很高的 CPU：

拉 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 +。