線上效能問題初步排查方法
阿新 • • 發佈：2018-12-23
本文首發於併發網，作者：方騰飛
引言
有時候有很多問題只有在線上或者預發環境才能發現，而線上又不能Debug，所以線上問題定位就只能看日誌，系統狀態和Dump執行緒，本文只是簡單的介紹一些常用的工具，幫助定位線上問題。
問題定位
1: 首先使用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％，則很有可能程式裡寫了一個死迴圈。這些引數的含義，可以對比下表：
|
us |
使用者空間佔用CPU百分比 |
|
1.0% sy |
核心空間佔用CPU百分比 |
|
0.0% ni |
使用者程序空間內改變過優先順序的程序佔用CPU百分比 |
|
98.7% id |
空閒CPU百分比 |
|
0.0% wa |
等待輸入輸出的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
在這裡可能會出現三種情況：
- 第一種情況，某個執行緒一直CPU利用率100％，則說明是這個執行緒有可能有死迴圈，那麼請記住這個PID。
- 第二種情況，某個執行緒一直在TOP十的位置，這說明這個執行緒可能有效能問題。
- 第三種情況，CPU利用率TOP幾的執行緒在不停變化，說明並不是由某一個執行緒導致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/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是10進位制的，所以我們要printf命令轉換一下進位制。然後用16進位制的ID去dump裡找到對應的執行緒。
printf "%x\n" 31558 輸出：7b46
優化實戰
1：檢視下TCP連線狀態，建立了800多個連線，需要儘量降低ESTABLISHED。
[[email protected] ~]$ netstat -nat | awk '{print $6}' | sort | uniq -c | sort -n 1 established) 1 Foreign 3 CLOSE_WAIT 7 CLOSING 14 FIN_WAIT2 25 LISTEN 39 LAST_ACK 609 FIN_WAIT1 882 ESTABLISHED 10222 TIME_WAIT
2：用jstack dump看看這些執行緒都在做什麼。
sudo -u admin /opt/ifeve/java/bin/jstack 31177 > /home/tengfei.fangtf/dump17
3：統計下所有執行緒分別處於什麼狀態，發現大量執行緒處於WAITING(onobjectmonitor)狀態
[[email protected] ~]$ grep java.lang.Thread.State dump17 | awk '{print $2$3$4$5}' | sort | uniq -c 39 RUNNABLE 21 TIMED_WAITING(onobjectmonitor) 6 TIMED_WAITING(parking) 51 TIMED_WAITING(sleeping) 305 WAITING(onobjectmonitor) 3 WAITING(parking)
4：檢視處於WAITING(onobjectmonitor)的執行緒資訊，主要是jboss的工作執行緒在await。
"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 <0x00000007969b2280> (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 <0x00000007969b2280> (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)
5：找到jboss的執行緒配置資訊，將maxThreads降低到100
<maxThreads="250" maxHttpHeaderSize="8192" emptySessionPath="false" minSpareThreads="40" maxSpareThreads="75" maxPostSize="512000" protocol="HTTP/1.1" enableLookups="false" redirectPort="8443" acceptCount="200" bufferSize="16384" connectionTimeout="15000" disableUploadTimeout="false" useBodyEncodingForURI="true">
6：重啟jboss，再dump執行緒資訊，然後統計，WAITING(onobjectmonitor)的執行緒減少了170。
[[email protected] ~]$ grep java.lang.Thread.State dump17 | awk '{print $2$3$4$5}' | sort | uniq -c 44 RUNNABLE 22 TIMED_WAITING(onobjectmonitor) 9 TIMED_WAITING(parking) 36 TIMED_WAITING(sleeping) 130 WAITING(onobjectmonitor) 1 WAITING(parking)
其他命令
- 檢視CPU資訊 cat /proc/cpuinfo
- 檢視記憶體資訊 cat /proc/meminfo
- 檢視Java執行緒數 ps -eLf | grep java -c
- 檢視linux系統裡開啟檔案描述符的最大值 ulimit -u
- 找到日誌裡TOP10的異常：grep ‘Exception’ /home/admin/logs/XX.log |awk -F’:|,’ ‘{print $2}’|sort |uniq -c |sort -nr|head -10，找到之後可以再用-A 2 -B 2，看定位出日誌的前面2行和後面兩行。
