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

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

• Linux：RedHat 6.1
• Weblogic：11g
• JRokit：R28.2.4
• JDK：1.6.0_45

Weblogic 跑在 JRokit 上面，JDK 是我們對 JRokit 進行監控分析的工具。

1. LoadRunner 壓測結果

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

2. Oracle 的 awr 報告分析

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

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

并發壓測的時候去相干數據表履行1些 sql 的速度很快也證明著問題不在 Oracle 這邊。

3. Weblogic 服務器的性能指標

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

4. JStack 報告分析

事情到了這里，大家已想到了線程死鎖、等待的問題了。
沒錯，JStack 隆重登場。JStack 能夠看到當前 Java 進程中每一個線程確當前狀態、調用棧、鎖住或等待去鎖定的資源，而且很強悍的是它還能直接報告是不是有線程死鎖，可謂解決線程問題的不2之選。
$ /opt/jdk1.6.0_45/bin/jstack -l 10495 > ~/10495jstack.txt
JRokit 堆棧的拉取，可以直接用 JDK 的 JStack，10495 是 Weblogic 服務的進程 ID。注意1定要用該進程的啟動用戶去拉，否則會報 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 中進行分配，這樣就不用擔心和其它線程的同步問題了。但這個也不可以調的太大，否則也會帶來1些問題，比如會帶來更多內存碎片、更加頻繁的垃圾搜集。
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。別灰心，改1個地方就吹糠見米，成功仿佛來得太快了點。
現在懷疑是服務堆內存太小，查看1下果然。服務器物理內存 32 GB，Weblogic 進程只分到了 6 GB。怎樣查看？最少有4種辦法：

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 文件，這個文件1般會生成在啟動的 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⑶40.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⑶40.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⑶40.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⑶41.126: OC 10485760KB->10413562KB (10485760KB), 0.231 s, sum of pauses 206.458 ms, longest pause 206.458 ms.
第1行表示該進程啟動后的第 340.828⑶40.845 期間進行了1次 young gc，該次 GC 延續了 17.294 ms，將全部已用掉的堆內存由 10444109 KB 下降到 10417908 KB。
第3行一樣是1次 young gc，但該次 GC 后已用堆內存反而上升到了 10485760 KB，也就是到達最大堆內存，因而該次 young gc 結束的同時觸發 full gc。
第4行是1次 old gc (即 full gc)，將已用堆內存由 10485760 KB 降到了 10413562 KB，耗時 206.458 ms。
這些日志一樣能夠指出當前壓力下的 GC 的頻率，為本次性能瓶頸 - GC 過于頻繁提供有力的左證。

5.4. JStat 報告

跟 JStack 的拉取1樣，可以直接用 JDK 的 JStat 去拉取 JRokit 的 GC 信息：
$ /opt/jdk1.6.0_45/bin/jstat -J-Djstat.showUnsupported=true -snap 10495 > ~/10495jstat.txt
注意這個信息是1個快照，這是跟 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 的那個進程1直在占用很高的 CPU。

6.1.2. 性能線程的獲得

現在我們來找到這個進程中占用 CPU 較高的那些線程：
$ ps p 10495 -L -o pcpu,pid,tid,time,tname,cmd > ~/10495ps.txt
屢次拉這個快照，我們找到了 tid 為 10499、10500、10501、10502 等線程占用 CPU 很高：

拉 JStack 快照看看都是1些甚么線程：
$ /opt/jdk1.6.0_45/bin/jstack -l 10495 > ~/10495jstack.txt
相干部份結果以下：
"(GC Worker Thread 1)" id=? idx=0x10 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=0x14 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=0x18 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，發現這兩個相互矛盾的現象：
1方面 GC Worker 線程在拼命 GC，但是 GC 前后效果不明顯，已用堆內存始終降不下來；
另外一方面大量 ExecuteThread 業務處理線程處于 alloc_enqueue_allocation_and_wait_for_gc 的 native_blocked 阻塞狀態。
另外，停止壓測以后，查看已用堆內存大小，也就幾百兆，不到分配堆內存的 1/10。
這說明了甚么呢？這說明了我們利用里沒有內存泄漏、靜態對象不是太多、有大量的業務線程在頻繁創建1些生命周期很長的臨時對象。
很明顯還是代碼里有問題。那末這些對象來自哪里？如何在海量業務代碼里邊準肯定位這些性能代碼？也就是說如何利用 JVM 調優驅動代碼層面的調優？請參考博客《JVM 性能調優實戰之：使用阿里開源工具 TProfiler 在海量業務代碼中精肯定位性能代碼》，使用 TProfiler 我們成功找到了代碼里邊致使 JVM 頻繁 GC 的首惡，并終究解決掉了這個性能瓶頸，將 TRT 降到了 0.5，TPS 提升至 100 +。

參考資料

• Optimizing Memory Allocation Performance
• Understanding Verbose Output