java性能实战_【从零单排】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 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 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/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，查看高占用的类。

性能排查，是一项有挑战的活。有可能在中间的某一步，就发现了问题；也可能所有的步骤都做完了，还是没能发现问题。这就需要我们抓住每次机会，积累经验，细致思考，发散思维。

Reference