Java并发编程线上问题定位

 有时候，有很多问题只有在线上或者预发环境才能发现，而线上又不能调试代码，所以线上问题定位就只能看日志、系统状态和dump线程。

1）在Linux命令行下使用TOP命令查看每个进程的情况，显示如下。

top - 22:27:25 up 463 days, 12:46, 1 user, load average: 11.80, 12.19, 11.79
Tasks: 113 total, 5 running, 108 sleeping, 0 stopped, 0 zombie
Cpu(s): 62.0%us, 2.8%sy, 0.0%ni, 34.3%id, 0.0%wa, 0.0%hi, 0.7%si, 0.2%st
Mem: 7680000k total, 7665504k used, 14496k free, 97268k buffers
Swap: 2096472k total, 14904k used, 2081568k free, 3033060k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
31177 admin 18 0 5351m 4.0g 49m S 301.4 54.0 935:02.08 java
31738 admin 15 0 36432 12m 1052 S 8.7 0.2 11:21.05 nginx-proxy

 我们的程序是Java应用，所以只需要关注COMMAND是Java的性能数据，COMMAND表示启动当前进程的命令，在Java进程这一行里可以看到CPU利用率是300%，不用担心，这个是当前机器所有核加在一起的CPU利用率。

 
2）再使用top的交互命令数字1查看每个CPU的性能数据。

top - 22:24:50 up 463 days, 12:43, 1 user, load average: 12.55, 12.27, 11.73
Tasks: 110 total, 3 running, 107 sleeping, 0 stopped, 0 zombie
Cpu0 : 72.4%us, 3.6%sy, 0.0%ni, 22.7%id, 0.0%wa, 0.0%hi, 0.7%si, 0.7%st
Cpu1 : 58.7%us, 4.3%sy, 0.0%ni, 34.3%id, 0.0%wa, 0.0%hi, 2.3%si, 0.3%st
Cpu2 : 53.3%us, 2.6%sy, 0.0%ni, 34.1%id, 0.0%wa, 0.0%hi, 9.6%si, 0.3%st
Cpu3 : 52.7%us, 2.7%sy, 0.0%ni, 25.2%id, 0.0%wa, 0.0%hi, 19.5%si, 0.0%st
Cpu4 : 59.5%us, 2.7%sy, 0.0%ni, 31.2%id, 0.0%wa, 0.0%hi, 6.6%si, 0.0%st
Mem: 7680000k total, 7663152k used, 16848k free, 98068k buffers
Swap: 2096472k total, 14904k used, 2081568k free, 3032636k cached

 命令行显示了CPU4，说明这是一个5核的虚拟机，平均每个CPU利用率在60%以上。如果这里显示CPU利用率100%，则很有可能程序里写了一个死循环。这些参数的含义，可以对比表11-1来查看。

CPU参数含义

3）使用top的交互命令H查看每个线程的性能信息。

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
31558 admin 15 0 5351m 4.0g 49m S 12.2 54.0 10:08.31 java
31561 admin 15 0 5351m 4.0g 49m R 12.2 54.0 9:45.43 java
31626 admin 15 0 5351m 4.0g 49m S 11.9 54.0 13:50.21 java
31559 admin 15 0 5351m 4.0g 49m S 10.9 54.0 5:34.67 java
31612 admin 15 0 5351m 4.0g 49m S 10.6 54.0 8:42.77 java
31555 admin 15 0 5351m 4.0g 49m S 10.3 54.0 13:00.55 java
31630 admin 15 0 5351m 4.0g 49m R 10.3 54.0 4:00.75 java
31646 admin 15 0 5351m 4.0g 49m S 10.3 54.0 3:19.92 java
31653 admin 15 0 5351m 4.0g 49m S 10.3 54.0 8:52.90 java
31607 admin 15 0 5351m 4.0g 49m S 9.9 54.0 14:37.82 java

在这里可能会出现3种情况：

• 第一种情况，某个线程CPU利用率一直100%，则说明是这个线程有可能有死循环，那么请记住这个PID。
• 第二种情况，某个线程一直在TOP 10的位置，这说明这个线程可能有性能问题。
• 第三种情况，CPU利用率高的几个线程在不停变化，说明并不是由某一个线程导致CPU偏高。

 如果是第一种情况，也有可能是GC造成，可以用jstat命令看一下GC情况，看看是不是因为持久代或年老代满了，产生Full GC，导致CPU利用率持续飙高，命令和回显如下。

sudo /opt/java/bin/jstat -gcutil 31177 1000 5
  S0 S1 E O P YGC YGCT FGC FGCT GCT
0.00 1.27 61.30 55.57 59.98 16040 143.775 30 77.692 221.467
0.00 1.27 95.77 55.57 59.98 16040 143.775 30 77.692 221.467
1.37 0.00 33.21 55.57 59.98 16041 143.781 30 77.692 221.474
1.37 0.00 74.96 55.57 59.98 16041 143.781 30 77.692 221.474
0.00 1.59 22.14 55.57 59.98 16042 143.789 30 77.692 221.481

 还可以把线程dump下来，看看究竟是哪个线程、执行什么代码造成的CPU利用率高。执行以下命令，把线程dump到文件dump17里。执行如下命令。

sudo -u admin /opt/taobao/java/bin/jstack 31177 > /home/tengfei.fangtf/dump17

dump出来内容的类似下面内容。

"http-0.0.0.0-7001-97" daemon prio=10 tid=0x000000004f6a8000 nid=0x555e in Object.
wait() [0x0000000052423000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on (a org.apache.tomcat.util.net.AprEndpoint$Worker)
at java.lang.Object.wait(Object.java:485)
at org.apache.tomcat.util.net.AprEndpoint$Worker.await(AprEndpoint.java:1464)
- locked (a org.apache.tomcat.util.net.AprEndpoint$Worker)
at org.apache.tomcat.util.net.AprEndpoint$Worker.run(AprEndpoint.java:1489)
at java.lang.Thread.run(Thread.java:662)

 dump出来的线程ID（nid）是十六进制的，而我们用TOP命令看到的线程ID是十进制的，所以要用printf命令转换一下进制。然后用十六进制的ID去dump里找到对应的线程。

printf "%x\n" 31558

输出：7b46。