【从零单排】Java性能排查实战模拟
当线上发生了性能问题时，需要我们快速定位问题。本文模拟了一次内存泄漏，从零教学一步步手动排查。
模拟事故现场
使用如下代码模拟内存泄漏。起了几个问题线程（在不停地创建很大的StringBuilder)。另外还有一些常规线程。
import java.util.List;
import java.util.Random;
import java.util.Scanner;
import java.util.concurrent.Executors;
import java.util.concurrent.ExecutorService;
import static java.lang.Thread.sleep;
public class app {
public static void main(String[] args) {
Scanner sc = new Scanner(System.in);
ExecutorService executorService = Executors.newFixedThreadPool(100);
System.out.println("Please Enter when VM is ready.");
sc.nextLine();
System.out.println("START");
// 5 threads with issues
for (int i=0; i<5; i++) {
executorService.execute(() -> {
System.out.println(Thread.currentThread().getName());
double input = new Random().nextDouble();
List<String> l;
while (true) {
// create many string builder
for (int j=0; j<100; j++) {
StringBuilder s = new StringBuilder(Double.toString(input++));
// make it big, 100 million
for (int k=0; k<100000000; k++) {
s.append(input+k);
}
}
}
});
}
// 95 threads - good
for (int i=0; i<95; i++) {
executorService.execute(() -> {
System.out.println(Thread.currentThread().getName());
double input = new Random().nextDouble();
List<String> l;
while (true) {
StringBuilder s = new StringBuilder(Double.toString(input++));
try {
sleep(100);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
});
}
}
}
把代码部署到服务器上。接下来，我们需要找一个open的端口给JMX用。
使用命令查看已经占用的端口：lsof -i -P -n | grep LISTEN。（也可以用：netstat -tulpn | grep LISTEN）
挑一个不在上述列表里的，这里就用7788吧。于是就可以跑起来了。
// 编译
javac app.java
// 运行
java -Dcom.sun.management.jmxremote.port=7788 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -verbose:gc -Xloggc:/home/username/LOGS/test_my_gc_log.log app
这里要加上jmxremote的三个参数。第一个指定了端口，后两个设置了无需密码。这是为了local的visualvm可以远程连上server上的JVM。
-Dcom.sun.management.jmxremote.port=7788
-Dcom.sun.management.jmxremote.ssl=false
-Dcom.sun.management.jmxremote.authenticate=false
另外，还使用了gc的参数。第一个表示要打印垃圾回收的log，第二个指定了log的位置。这时为了保留gc日志方便以后分析。
-verbose:gc
-Xloggc:/home/username/LOGS/test_my_gc_log.log
现在，我们把事故现场模拟好了。但是实际发生问题的时候，我们一开始是不知道具体细节的，需要一步步排查。让我们把上面的代码都忘掉，从头开始。
top命令
首先，使用top命令查看服务器上占用CPU，Memory资源最多的进程（Top Process's Resource Usage）。
这里，我们定位到PID为18264的这个java进程，发现它的CPU使用率为773.4%，MEM使用率为11.7%。估计问题出在这儿。
（当然，实际生产环境发生内存泄漏问题，一般MEM会撑爆，这里仅仅作为测试用例，占用了近30个G的内存，没有把内存撑满。）
其次，使用top -H p18264观察该进程下的线程资源使用情况。（18264是Java进程的PID）
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
18413 eufiudwq 20 0 42.4g 21.9g 13220 R 83.7 11.7 1:36.71 java
18414 eufiudwq 20 0 42.4g 21.9g 13220 R 83.7 11.7 1:37.18 java
18415 eufiudwq 20 0 42.4g 21.9g 13220 R 83.3 11.7 1:36.75 java
18416 eufiudwq 20 0 42.4g 21.9g 13220 R 83.3 11.7 1:36.74 java
19060 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.05 java
19061 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.06 java
19062 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.13 java
19063 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.14 java
19065 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.11 java
19066 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.10 java
19067 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.12 java
19068 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.10 java
19069 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.13 java
19070 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.10 java
19071 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.13 java
19072 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.00 java
19074 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:09.99 java
19075 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:09.92 java
19076 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:09.94 java
19077 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.09 java
19078 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.08 java
19079 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.13 java
19080 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.09 java
19081 eufiudwq 20 0 42.4g 21.9g 13220 S 12.0 11.7 0:10.09 java
可以看到，起了很多线程，需要特别关注的是头部的PID为18413，18414，18415，18416这几个，CPU和MEM占用都很大。其它的资源占用相对较小。
jvisualvm工具
下面，我们用jvisualvm远程连接到server端，查看Java进程运行时CPU，堆栈内存，线程使用情况（Overall JVM Status）。
(jvisualvm以及下述的jstack,jstat,jmap都是位于Javajdk<version_number>/bin目录下)
查看Threads页面，发现主要是pool-1-thread-5,pool-1-thread-4,pool-1-thread-3,pool-1-thread-2这几个线程跑了很多时间，且在Running状态，其它的大多都在sleep。
这几个，应该就是对应到上面说的PID为18413，18414，18415，18416的线程。
Thread Dump
这里，我们想要深入到Thread内部，看看具体某一时刻有问题的线程在干啥。
Method 1
在jvisualvm中，使用 -> Thread Dump。再定位到可能有问题的pool-1-thread-3中，得到log如下：
"pool-1-thread-3" - Thread t@33
java.lang.Thread.State: RUNNABLE
at sun.misc.FloatingDecimal$BinaryToASCIIBuffer.access$100(FloatingDecimal.java:259)
at sun.misc.FloatingDecimal.getBinaryToASCIIConverter(FloatingDecimal.java:1785)
at sun.misc.FloatingDecimal.getBinaryToASCIIConverter(FloatingDecimal.java:1738)
at sun.misc.FloatingDecimal.appendTo(FloatingDecimal.java:89)
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:736)
at java.lang.StringBuilder.append(StringBuilder.java:226)
at app.lambda$main$0(app.java:28)
at app$$Lambda$9/1681433494.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Locked ownable synchronizers:
- locked <3d71d552> (a java.util.concurrent.ThreadPoolExecutor$Worker)
发现这一行：at java.lang.StringBuilder.append(StringBuilder.java:226)，猜想可能创建了很多StringBuilder，造成了大量的内存占用。
Method 2
另外一种方法是用jstack，在server上可以直接把thread信息dump到一个文件，然后分析：jstack 18264 > jstack.txt （18264是Java进程的PID）
jstack出来的log，id是16进制，上面top看到的是十进制，需要进行转换。比如18413（10进制）这个，转换之后为47ed（16进制）。找到对应的log如下：
"pool-1-thread-2" #32 prio=5 os_prio=0 tid=0x00007fa38c27a000 nid=0x47ed runnable [0x00007fa3455a8000]
java.lang.Thread.State: RUNNABLE
at sun.misc.FloatingDecimal$BinaryToASCIIBuffer.access$100(FloatingDecimal.java:259)
at sun.misc.FloatingDecimal.getBinaryToASCIIConverter(FloatingDecimal.java:1785)
at sun.misc.FloatingDecimal.getBinaryToASCIIConverter(FloatingDecimal.java:1738)
at sun.misc.FloatingDecimal.appendTo(FloatingDecimal.java:89)
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:736)
at java.lang.StringBuilder.append(StringBuilder.java:226)
at app.lambda$main$0(app.java:28)
at app$$Lambda$9/1681433494.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
结论和方法1是一致的。
jstat - GC status
下面，我们来看看GC情况：jstat -gcutil 18264 2000 10
参数说明：
- 18264是Java进程的PID
- 2000：每间隔2000毫秒收集一次
- 10：收集10次
分析可知，Eden区和Old区占用超过了一半以上，有15次Full GC，一共花了大概9秒。
（服务器上内存并没有占满，我们只拿了30G左右来测试，所以不需要频繁FGC。而正常线上发生内存泄漏问题时，往往伴随着频繁的FGC。）
Usage in Class Level
从上面的分析，我们已经大概知道问题可能出现在StringBuilder。下面从Class level分析，希望能进一步证实我们的推断。
Method 1
在local，使用jvisualvm查看 -> Sampler -> Memory
可以看到，大部分的占用在char[]，其实StringBuilder.append底层是调用char进行拼接的，jdk代码如下：
// AbstractStringBuilder.java
public AbstractStringBuilder append(String str) {
if (str == null)
return appendNull();
int len = str.length();
ensureCapacityInternal(count + len);
str.getChars(0, len, value, count);
count += len;
return this;
}
由此，我们可以确信，是程序中的某一个部分使用StringBuilder时出了问题。
Method 2
在server端，使用jmap -histo 18264查看。（18264是Java进程的PID）
num #instances #bytes class name
----------------------------------------------
1: 17874 21878767104 [C
2: 1366 23338808 [I
3: 1842 207544 java.lang.Class
4: 6524 156576 java.lang.String
5: 5503 132072 java.lang.StringBuilder
6: 1304 114752 java.lang.reflect.Method
7: 346 113480 [B
8: 2294 105424 [Ljava.lang.Object;
9: 125 47000 java.lang.Thread
10: 1195 38240 java.util.HashMap$Node
11: 1547 34736 [Ljava.lang.Class;
12: 521 25008 java.util.HashMap
13: 345 24840 java.lang.reflect.Field
14: 309 24720 java.lang.reflect.Constructor
15: 255 22456 [Ljava.util.HashMap$Node;
16: 557 22280 java.lang.ref.SoftReference
17: 411 13152 java.util.concurrent.ConcurrentHashMap$Node
18: 398 12088 [Ljava.lang.String;
19: 204 11424 java.lang.invoke.MemberName
20: 357 11424 java.util.Hashtable$Entry
21: 472 11328 java.lang.Long
22: 341 10912 sun.misc.FDBigInteger
23: 101 10504 java.io.ObjectStreamClass
24: 127 10320 [Ljava.util.Hashtable$Entry;
25: 237 9480 java.util.LinkedHashMap$Entry
26: 100 8000 [Ljava.lang.ThreadLocal$ThreadLocalMap$Entry;
27: 195 7800 java.io.ObjectStreamField
28: 219 7008 java.util.Vector
29: 96 6912 sun.reflect.DelegatingClassLoader
30: 203 6496 java.lang.invoke.LambdaForm$Name
31: 113 6328 java.lang.Class$ReflectionData
32: 191 6112 java.io.ObjectStreamClass$WeakClassKey
33: 119 5712 java.util.Hashtable
34: 142 5680 java.lang.invoke.MethodType
35: 94 5640 [Ljava.lang.ref.SoftReference;
36: 139 5560 java.security.AccessControlContext
37: 321 5136 java.lang.Object
38: 102 4896 java.util.concurrent.ThreadPoolExecutor$Worker
39: 27 4784 [Ljava.util.concurrent.ConcurrentHashMap$Node;
40: 144 4608 java.lang.invoke.MethodType$ConcurrentWeakInternSet$WeakEntry
41: 287 4592 java.lang.Integer
42: 191 4584 javax.management.ImmutableDescriptor
43: 113 4520 java.security.ProtectionDomain
44: 61 4448 [Ljava.lang.reflect.Method;
45: 110 4400 java.util.TreeMap$Entry
46: 109 4360 java.util.WeakHashMap$Entry
47: 130 4160 com.sun.jmx.mbeanserver.ConvertingMethod
结论和方法1是一致的。
总结
首先，我们使用了top查看服务器上高占用的进程，继而定位到某些问题线程。
其次，我们使用了jvisualvm查看某一个进程的运行情况。
接着，我们使用了jvisualvm的Thread Dump，或者jstack查看问题线程的状态。
然后，我们使用了jstat查看GC情况。
最后，我们使用了jvisualvm的Sampler，或者jmap，查看高占用的类。
性能排查，是一项有挑战的活。有可能在中间的某一步，就发现了问题；也可能所有的步骤都做完了，还是没能发现问题。这就需要我们抓住每次机会，积累经验，细致思考，发散思维。
