JVM 性能调优实战之：一次系统性能瓶颈的寻找过程
栏目：框架设计时间：2016-10-17 15:42:30
玩过性能优化的朋友都清楚，性能优化的关键其实不在于怎样进行优化，而在于怎样找到当前系统的性能瓶颈。
性能优化分为好几个层次，比如系统层次、算法层次、代码层次...JVM 的性能优化被认为是底层优化，门坎较高，精通这类技能的人比较少。笔者呆过几家技术气力不算弱的公司，每一个公司内部真正能够进行 JVM 性能调优的人寥寥无几、乃至没有。如是乎，能够有效通过 JVM 调优提升系统性能的人常常被人们冠以"大牛"、"大师"之类的称呼。
其实 JVM 本身给我们提供了很多强大而有效的监控进程、分析定位瓶颈的工具，比如 JConsole、JMap、JStack、JStat 等等。使用这些命令，再结合 Linux 本身提供的1些强大的进程、线程命令，能够快速定位系统瓶颈。本文以1次使用这些工具准肯定位到某系统瓶颈的实战经验为例，希望能为大家掌握 JVM 调优这项技能起到1些鉴戒作用。
本文背景：
50 个用户并发压10几个小时，TRT 在 20 左右，TPS 在 2.5 左右。领导对这个结果不满意，要求进行优化。但这是个老系统，开发在之前明显已对其代码做过很多优化，如今面对这类状态也束手无策。
并发压测的时候 Spotlight 查看数据库服务器各项性能指标，很清闲。
虽然 CPU 利用率始终在 200% 左右徘徊，但这对 16 核的系统来说也算是正常的吧？
没错，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 拉取的文件信息基本分为以下几个部份：
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
现在怀疑是服务堆内存太小，查看1下果然。服务器物理内存 32 GB，Weblogic 进程只分到了 6 GB。怎样查看？最少有4种办法：
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=
这个页面还能看到进程已运行时间，启动以来产生的 GC 次数，可以折算出 GC 的频率，为本次性能瓶颈 - GC 过于频繁提供有力的左证。
-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 过于频繁提供有力的左证。
$ /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
上述是当前已用碓大小和新生代分区大小。多拉几次便可估算出各自分配的大小。
因而我们调剂它们的大小，结合 4.1 TLA 调剂的结论，JVM 启动参数增加以下：
-Xms10240m -Xmx10240m -Xns:1024m -XXtlaSize:min=32k,preferred=1024k
再次压测，TRT 降到了 2.5，TPS 上升到 20。
进程 ID 为 10495 的那个进程1直在占用很高的 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
为什么会如此频繁 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 +。
性能优化分为好几个层次，比如系统层次、算法层次、代码层次...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
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)升序顺次列出当前进程中每一个线程的调用栈
- 死锁(如果有的话)
- 阻塞锁链
- 打开的锁链
- 监视器解锁情况跟踪
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 javadefonds 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
------分隔线----------------------------
------分隔线----------------------------