閱讀787 返回首頁    go windows

線上性能問題初步排查方法

引言

有時候有很多問題隻有在線上或者預發環境才能發現，而線上又不能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

在這裏可能會出現三種情況：

  1. 第一種情況，某個線程一直CPU利用率100％，則說明是這個線程有可能有死循環，那麼請記住這個PID。
  2. 第二種情況，某個線程一直在TOP十的位置，這說明這個線程可能有性能問題。
  3. 第三種情況，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。

 
[tengfei.fangtf@ifeve ~]$ 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)狀態

[tengfei.fangtf@ifeve ~]$ 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。

[tengfei.fangtf@ifeve ~]$ 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行和後麵兩行。
  • 轉載自 並發編程網 - ifeve.com

最後更新：2017-05-23 14:35:44

  上一篇：go  AKKA文檔（java版）—角色（一）
  下一篇：go  Java中的Atomic包使用指南