Java应用性能问题诊断技巧

作者：张彦东
参考：https://developer.aliyun.com/ebook/450?spm=a2c6h.20345107.ebook-index.28.6eb21f54J7SUYc

应用性能问题的诊断主要从以下三方面入手：内存、CPU、网络。

（一）内存

1.内存

·现象

1）OutOfMemoryError: Java heap space；

2）频繁FULL GC；

·原因

1）内存泄露；

2）堆大小配置不合理；

·解决方法

1）jvisualvm；

2）jstat；

3）jmap；

4）mat。

java.lang.OutOfMemoryError: Java heap space
 at java.util.Arrays.copyOfRange(Arrays.java:3664) ~[na:1.8.0_271]
 at java.lang.StringBuffer.toString(StringBuffer.java:669) ~[na:1.8.0_271]
 at com.aliyun.javards.controller.MyController.genString(MyController.java:74) ~[classes!/:0.0.1-SNAPSHOT]
 at com.aliyun.javards.controller.MyController.leakMem(MyController.java:63) ~[classes!/:0.0.1-SNAPSHOT]
 at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_271]

如上图所示，这段日志是当出现内存耗尽的时候，结果会报出来一些错误，应用会出现频繁的FULL GC。

2.内存-JMX

诊断结内存的问题的方法：

可以打开JMX通过启动参数以-D开头这4个参数进行远程连接，连接之后可以看到最大堆的大小以及实际已经使用的情况。

3.内存-Jmap

同时通过JMX对堆进行一个Dump，文件会在Jvm运行所在主机的对应的目录上。

第二种是 jmap -heap 2780进程号，可以看到Jmap的堆的最大大小是512兆，同时看到老年代的使用情况是78%。通过命令把Jmap的堆内存Dump到文件中做后续分析。通过命令提示正在进行Dump，完成后会有一个Heap Dump File Created日志。

用MAT打开堆的Dump文件，然后用内存泄露分析模式，通过结果可以看到 Controller里面有大量的对象，MAT的下载地址https:/www.eclipse.org/mat/。

4.内存-结合代码确认问题

确认最终的问题，打开MAT打开堆的Dump文件之后，通过内存泄露的分析，可以找到MyController下的list对象，里面存在大量字符串，每个字符串的大小约为2M，大概有100个，占用了268兆，可以看到具体的字符串的内容。

结合代码，看到在代码中第63行申请了一个1M长度，2M字节大小的内存，并且把内存放到一个全局的静态变量中进行应用，所以GC无法回收，因为是一个强引用无法回收，否则将导致内存泄漏。

通过Jmap把堆Dump出来，再通过MAT工具对内存进行分析，找到占用内存的对象，再通过对象里的一些引用关系，就能够找到代码里面创建对象，找到出现问题的代码，完成内存泄露的定位。

（二）CPU

CPU问题定位：

·现象

1）应用响应缓慢；

2）Java进程CPU占用高；

·原因

1）存在大量消耗CPU的逻辑；

2）循环；

3）复杂计算；

·解决方法

1）Top；

2）Jvisualvm ；

3）Async-profiler；

1.CPU-JMX或Jstack

如上图所示案例，一个一核的主机，CPU使用率接近100%，主机的负载达到了6点多，Java进程的CPU使用率可以到99%，通过选择JMX或者Jstack。

JMX连上去之后去检查每个线程是否在执行，这里通过JMX可以看到线程池1里的线程号1~6在长期的运行，因此这可能就是问题线程。

同时可以通过Jstack查看Jvm里面每个现场的堆栈，但是通过Jstack有一个缺点就是当应用里面线程非常多的时候，Jstack的结果会非常大，难以分析。

2.CPU-Async-Profiler

下载对应平台已编译好的代码，解压后找到对应的Java进程，通过这一串命令，对Java进程做一个系统剖析，剖析完之后会生成一个火焰图，通过火焰图能够准确地看到应用的热点代码。

tar -xf async-profiler-1.8.3-linux-x64.tar.gz
cd async-profiler-1.8.3-linux-x64
./profiler.sh -e itimer -d 10 -f /share/cpu-flame-graph.svg --title "CPU profile"
3141

这里对上列参数做一个说明：

增加了-e itimer后，会不依赖perf_events，只剖析JVM一般就够了；

-d 10 表示剖析持续10秒，可以根据实际情况调整；

最后的3141是Java进程的pid。

通过生成的火焰图之后，用浏览器打开可以看到里面有6个线程长期霸占CPU。火焰图从上往下看，下面的方法是处于栈底的，上面的方法是属于栈顶的，栈顶的方法就是正在执行的方法，而栈顶上面的最宽的方法就是占用CPU最多的方法，所以可以看到这里有6个线程，里面有6个栈，每个栈上都正在执行方法在消耗CPU。

结合上图代码，通过堆栈来对应到源码。可以看到，通过JMX可以找到可疑的线程，通过Async-profiler可以生成火焰图，直接定位到存在性能问题的线程以及它的堆栈，通过堆栈就用源码找到真正有问题的代码。

（三）网络

1.常用命令

网络问题包含以下常用命令：

1）查看当前主机IP：ip a

2）查看当前主机名：hostname

3）检查目标IP是否可达：ping

4）检查目标端口是否可达：telnet

5）查看网卡：ifconfig

6）查看路由表：route –n

7）查看从当前主机发往目标主机中间会经过哪些路由：traceroute –i

8）查看当前主机的网卡流量：iptraf-ng

9）查看以IP为单位的网络流量排名：iftop –n

10）查看当前主机上监听的端口：netstat –tpnl

11）查看当前主机上的TCP连接：netstat –tpn

2.TCP状态机

TCP状态机是TCP连接的核心部分，只有深入理解TCP状态机，才能灵活运用TCP的命令与工具，以及理解输出的结果与意义。

3.TCP状态说明

CLOSED：表示当前连接已经关闭。

LISTEN：表示当前正监听中，随时准备接受连接请求。

SYN_SENT：表示已经发送出建立TCP连接的数据包，等待对方回应。

SYN_RECVD：表示接受到了建立TCP连接的数据包，准备给对方发送SYN + ACK。

ESTABLISHED：表示已经建立TCP连接。

FIN WAIT-1：表示主动关闭连接的一方已经发出了FIN包。

CLOSE WAIT：表示被动关闭的一方收到了FIN包。

FIN WAIT-2：表示主动关闭的一方收到了FIN的ACK包，等待对方发出的 FIN包。

LAST ACK：表示被动关闭的一方发出了FIN包，开始等待对方发出ACK。

TIMED WAIT：表示主动关闭的一方已经发出了ACK，此时主动关闭的一方要等待2倍Maximum segment lifetime，在此期间，任何因为网络延迟或者拥堵而未及时到达的包将会被丢弃，以防止下一个连接收到了上一个连接的包。

4.实战的场景

a.配置问题引起的应用阻塞

现象是一段Python（其它语言相同）程序会阻塞，应用僵死。

诊断：

netstat-tpn|grep python
tcp 0 1
10.0.3.15:41570 192.168.1.1:80 SYN_SENT 15349/python
2.7

可以看到Python程序在等待主机192.168.1.1的ACK，而这个主机根本就不存在因此无法访问。再结合目标端口是80，定位到是程序HTTP请求的目标主机错误。

b．某个数据库的连接数暴涨，想查到连接来源

netstat -tpn|grep 3310|grep -i estab|awk '{print $4}'|cut -d ':'
-f 1|awk '{a[0]=a[0]=a[0] + 1} END {for (i in a) print i " " a[i]}'
10.0.3.15 999

可以看到，来自10.0.3.15的连接数达到了999个，结合代码就可找到问题。

c．线上应用没有打印SQL到日志中，DB也没有开审计日志，如何能看到SQL信息？

命令：tcpdump -i any port 3310 -tttt -nn -A -s0
2020-09-18 17:58:21.284833 IP 11.193.115.110.56454 > 11.193.115.110.3310: Flags
[P.], seq 1313:1606, ack 1238, win 6360, options [nop,nop,TS val 400339442 ecr
400339440], length 293
....E..Y..@.@.....sn..sn........u..............
........!.... select cu.id from test_table cu where cu.ins_name = 'yunji-ddr12' and
cu.is_deleted = 0 and ((cu.ins_type in (0, 2, 20) and cu.is_tmp = 0) or (cu.ins_type = 1
and cu.parent_id > 0)) and cu.status in (0,, 35, 36)

可以在应用服务器执行tcpdump，-i any表示监听任意网卡，port 3310表示去dump 3310端口，-tttt表示在每个包前面增

加一个时间戳，-nn表示不对端口和IP进行反向域名解析，-A表示以应用层的方式输出日志，-s0表示Buffer的控制。

通过这个命令，从网络上可以清晰的看到真实的SQL语句，这对于排查问题非常有帮助。

d．传说中的TCP3次握手和4次挥手，到底是什么样

命令：tcpdump -i any port 3310 -tttt -nn -X -s0

如上图所示，用户还可以通过Tcpdump来查看3次握手和4次挥手的网络数据。上图最上方三个包就是我们说的三次握手，它能够去建立TCP连接，建立成后MySQL会向客户端发送提示输入密码的文字，同时客户端会向MySQL客户端发送一个响应，表示收到数据包。

如果这个时候关闭连接就会产生4次挥手，分别是用户客户端向MySQL端发送一个关闭连接包文，MySQL会马上响应一个ACK，同时发出一个关闭连接包文，用户客户端也向MySQL响应一个ACK，这就是传说中TCP的3次握手和4次挥手。

如上图所示，用户还可以通过Tcpdump来查看3次握手和4次挥手的网络数据。上图最上方三个包就是我们说的三次握手，它能够去建立TCP连接，建立成后MySQL会向客户端发送提示输入密码的文字，同时客户端会向MySQL客户端发送一个响应，表示收到数据包。

如果这个时候关闭连接就会产生4次挥手，分别是用户客户端向MySQL端发送一个关闭连接包文，MySQL会马上响应一个ACK，同时发出一个关闭连接包文，用户客户端也向MySQL响应一个ACK，这就是传说中TCP的3次握手和4次挥手。