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

曾燕輝發表於2018-07-02
JVM

轉載自：https://blog.csdn.net/defonds/article/details/52598018

玩過效能優化的朋友都清楚，效能優化的關鍵並不在於怎麼進行優化，而在於怎麼找到當前系統的效能瓶頸。
效能優化分為好幾個層次，比如系統層次、演算法層次、程式碼層次...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=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，發現這兩個互相矛盾的現象：
一方面 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 +。

參考資料


相關文章