Java異常處理手冊V1.0

目錄

  • Linux診斷
  • jvm診斷

Linux診斷

  • cpu
  • 內(nèi)存
  • 網(wǎng)絡(luò)(連接,狀態(tài))
  • 磁盤IO
  • 句柄數(shù)

使用top命令

使用top命令主要查看load average,cpu使用率iowait等指標(biāo)

top - 14:14:11 up  2:44,  1 user,  load average: 0.00, 0.00, 0.00
Tasks: 212 total,   1 running, 211 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.2%us,  0.1%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  16333500k total,   931016k used, 15402484k free,    54272k buffers
Swap:        0k total,        0k used,        0k free,   528656k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                 
 1574 root      20   0 2443m  65m  10m S  1.7  0.4   0:56.86 java                                                                     
 3895 root      20   0 1040m  24m 4504 S  0.7  0.2   2:06.46 python                                                                   
 1449 root      20   0  122m  12m 8280 S  0.3  0.1   0:27.45 AliYunDun                                                                
15831 root      20   0 15136 1324  948 R  0.3  0.0   0:00.01 top                                                                      
    1 root      20   0 19352 1636 1308 S  0.0  0.0   0:00.98 init                                                                     
    2 root      20   0     0    0    0 S  0.0  0.0   0:00.00 kthreadd                                                                 
    3 root      RT   0     0    0    0 S  0.0  0.0   0:00.00 migration/0                                                              
    4 root      20   0     0    0    0 S  0.0  0.0   0:00.01 ksoftirqd/0                                                              
    5 root      RT   0     0    0    0 S  0.0  0.0   0:00.00 stopper/0            

網(wǎng)絡(luò)監(jiān)測

網(wǎng)絡(luò)監(jiān)測,第一步先監(jiān)測網(wǎng)絡(luò)是否通暢,使用ping監(jiān)測網(wǎng)絡(luò)是否可達
第二步監(jiān)測端口是否通暢,可以使用telnet 端口

netstat -na
顯示當(dāng)前所有活動的網(wǎng)絡(luò)連接

顯示出所有處于監(jiān)聽狀態(tài)的應(yīng)用程序及進程號和端口號:
netstat -aultnp

Close_Wait的問題

對于 服務(wù)器的連接狀態(tài)而言,一般有四種比較常見的: Established、 Time_Wait、Close_Wait、Closed。 服務(wù)器大量出現(xiàn)close_wait通常是因為沒有發(fā)送close Fin包給客戶端,客戶端收到fin包,則會向ack ,則服務(wù)端會最終關(guān)閉。
通過客戶端與服務(wù)端的交互都知道,在客戶端與服務(wù)端之間交互時,服務(wù)端出現(xiàn)CLOSE_WAIT,根本問題一定是服務(wù)端的代碼有問題。
Close wait是一種被動關(guān)閉狀態(tài)。而不是LAST_ACK狀態(tài),則說明服務(wù)端的程序因為請求某些資源的原因造成沒有釋放程序。曾經(jīng)因為程序的一個bug造成大量的接受端程序處于close_wait的狀態(tài),所以對于程序來說如果出現(xiàn)大量的close_wait,那么通常需要檢測程序的異常。

磁盤IO

查看系統(tǒng)的io_wait
如果 %util 接近 100%,說明產(chǎn)生的I/O請求太多,I/O系統(tǒng)已經(jīng)滿負(fù)荷,該磁盤可能存在瓶頸。idle小于70% IO壓力就較大了,一般讀取速度有較多的wait。

[root@ali-flink-05 ~]# iostat -x 1
Linux 2.6.32-696.16.1.el6.x86_64 (ali-flink-05)     03/30/2018  _x86_64_    (8 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.36    0.00    0.11    0.02    0.00   99.51

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
vda               0.64    13.72    1.70    1.53    62.63   122.00    57.27     0.04   12.47    0.91   25.33   0.96   0.31

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.25    0.00    0.12    0.00    0.00   99.63

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
vda               0.00     0.00    1.00    0.00    16.00     0.00    16.00     0.00    4.00    4.00    0.00   4.00   0.40

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.00    0.00    0.00    0.00    0.00  100.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
vda               0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00    0.00    0.00   0.00   0.00

iotop命令
iotop可以查看io排名靠前的程序

Total DISK READ: 0.00 B/s | Total DISK WRITE: 0.00 B/s
  TID  PRIO  USER     DISK READ  DISK WRITE  SWAPIN     IO>    COMMAND                                                                
 1963 be/4 root        0.00 B/s    3.94 K/s  0.00 %  0.00 % java -Djava.compiler=none -XX:-UseGC~liyun.tianji.cloudmonitor.Application
    1 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % init
    2 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [kthreadd]
    3 rt/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [migration/0]
    4 be/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [ksoftirqd/0]
    5 rt/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [stopper/0]
    6 rt/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [watchdog/0]
    7 rt/4 root        0.00 B/s    0.00 B/s  0.00 %  0.00 % [migration/1]

Jvm診斷

常見的jvm異常,通常包括以下:

  • OutOfMemoryError,內(nèi)存不足
  • 內(nèi)存泄露
  • 線程死鎖
  • 鎖爭用(Lock Contention)
  • Java進程消耗CPU過高

常用的工具

  • jps
  • jstack
  • jmap
  • jstat
  • jprof

jps

jps主要用來輸出JVM中運行的進程狀態(tài)信息。語法格式如下:

jps [options] [hostid]

命令行參數(shù)選項說明如下:
-q 不輸出類名、Jar名和傳入main方法的參數(shù)
-m 輸出傳入main方法的參數(shù)
-l 輸出main類或Jar的全限名
-v 輸出傳入JVM的參數(shù)

比如下面的命令

# jps -m -l
2458 org.artifactory.standalone.main.Main /usr/local/artifactory-2.2.5/etc/jetty.xml
29920 com.sun.tools.hat.Main -port 9998 /tmp/dump.dat
3149 org.apache.catalina.startup.Bootstrap start
30972 sun.tools.jps.Jps -m -l
8247 org.apache.catalina.startup.Bootstrap start
25687 com.sun.tools.hat.Main -port 9999 dump.dat
21711 mrf-center.jar

jstack

jstack主要用來查看某個Java進程內(nèi)的線程堆棧信息。語法格式如下:

jstack [option] pid
jstack [option] executable core
jstack [option] [server-id@]remote-hostname-or-ip

jstack可以定位到線程堆棧,根據(jù)堆棧信息我們可以定位到具體代碼,所以它在JVM性能調(diào)優(yōu)中使用得非常多。下面通過一個實例找出某個Java進程中最耗費CPU的Java線程并定位堆棧信息,用到的命令有ps、top、printf、jstack、grep。

第一步

先找出Java進程ID,我部署在服務(wù)器上的Java應(yīng)用名稱為mrf-center:

root@ubuntu:/# ps -ef | grep yarn | grep -v grep
yarn     15562  3.5 31.9 4309936 2578800 ?     Sl   13:02   5:45 /usr/local/java/bin/java -Xms2250m -Xmx2250m -XX:PermSize=64m 
-XX:MaxPermSize=128m -XX:SurvivorRatio=6 -XX:CMSInitiatingOccupancyFraction=70 -XX:+UseCMSInitiatingOccupancyOnly 
-Dlog.file=/data/yarn/log/application_1519876221508_0118/container_e12_1519876221508_0118_01_000002/taskmanager.log -Dlogback.configurationFile=file:./logback.xml 
-Dlog4j.configuration=file:./log4j.properties org.apache.flink.yarn.YarnTaskManager --configDir .
第二步

得到進程ID為15562,第二步找出該進程內(nèi)最耗費CPU的線程,可以使用ps -Lfp pid或者ps -mp pid -o THREAD, tid, time或者top -Hp pid,我這里用第三個,輸出如下:

[yarn@ali-flink-03 ~]$ top -Hp 15562
top - 15:45:31 up 128 days, 23 min,  1 user,  load average: 0.02, 0.05, 0.05
Tasks:  94 total,   0 running,  94 sleeping,   0 stopped,   0 zombie
Cpu(s):  2.7%us,  1.2%sy,  0.0%ni, 96.2%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   8061108k total,  7904292k used,   156816k free,   173856k buffers
Swap:        0k total,        0k used,        0k free,  1430360k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                        
15576 yarn      20   0 4208m 2.5g  33m S  0.3 32.0   0:03.23 java                                                                            
15583 yarn      20   0 4208m 2.5g  33m S  0.3 32.0   0:14.62 java                                                                            
15562 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:00.00 java                                                                            
15563 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:02.04 java                                                                            
15564 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:10.41 java                                                                            
15565 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:10.55 java                                                                            
15566 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:10.35 java                                                                            
15567 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:10.32 java                                                                            
15568 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:02.53 java                                                                            
15569 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:00.03 java                                                                            
15570 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:00.03 java                                                                            
15571 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:00.00 java                                                                            
15572 yarn      20   0 4208m 2.5g  33m S  0.0 32.0   0:30.33 java 

TIME列就是各個Java線程耗費的CPU時間,CPU時間最長的是線程ID為15576的線程,用。
轉(zhuǎn)化成16進制

printf "%x" 17504

得到了十六進制 4460

jstack 15562  | grep 4460
"PollIntervalRetrySchedulerThread" prio=10 tid=0x00007f950043e000 nid=0x54ee in Object.wait() [0x00007f94c6eda000]

可以看到CPU消耗在P的ollIntervalRetrySchedulerThread這個類Object.wait(),找了下代碼,定位到下面的代碼:

// Idle wait
getLog().info("Thread [" + getName() + "] is idle waiting...");
schedulerThreadState = PollTaskSchedulerThreadState.IdleWaiting;
long now = System.currentTimeMillis();
long waitTime = now + getIdleWaitTime();
long timeUntilContinue = waitTime - now;
synchronized(sigLock) {
    try {
        if(!halted.get()) {
            sigLock.wait(timeUntilContinue);
        }
    } 
    catch (InterruptedException ignore) {
    }
}

它是輪詢?nèi)蝿?wù)的空閑等待代碼,上面的sigLock.wait(timeUntilContinue)就對應(yīng)了前面的Object.wait()。

jmap

jmap(Memory Map)和jhat(Java Heap Analysis Tool)

jmap用來查看堆內(nèi)存使用狀況,一般結(jié)合jhat使用。

jmap語法格式如下

jmap [option] pid
jmap [option] executable core
jmap [option] [server-id@]remote-hostname-or-ip

使用jmap -heap pid查看進程堆內(nèi)存使用情況,包括使用的GC算法、堆配置參數(shù)和各代中堆內(nèi)存使用情況。比如下面的例子:

Attaching to process ID 24390, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.45-b02

using thread-local object allocation.
Parallel GC with 8 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 2359296000 (2250.0MB)
   NewSize                  = 786432000 (750.0MB)
   MaxNewSize               = 786432000 (750.0MB)
   OldSize                  = 1572864000 (1500.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 6
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 590348288 (563.0MB)
   used     = 376838120 (359.3808364868164MB)
   free     = 213510168 (203.6191635131836MB)
   63.833185876876804% used
From Space:
   capacity = 98041856 (93.5MB)
   used     = 98033456 (93.49198913574219MB)
   free     = 8400 (0.0080108642578125MB)
   99.9914322307403% used
To Space:
   capacity = 98041856 (93.5MB)
   used     = 0 (0.0MB)
   free     = 98041856 (93.5MB)
   0.0% used
PS Old Generation
   capacity = 1572864000 (1500.0MB)
   used     = 839742784 (800.8411254882812MB)
   free     = 733121216 (699.1588745117188MB)
   53.389408365885416% used

20114 interned Strings occupying 2137544 bytes.

使用jmap -histo[:live] pid查看堆內(nèi)存中的對象數(shù)目、大小統(tǒng)計直方圖,如果帶上live則只統(tǒng)計活對象,如下:

 num     #instances         #bytes  class name
----------------------------------------------
   1:          9772      225835072  [B
   2:        406482       42274128  com.chinaway.event.model.gps.Location
   3:        747945       41907800  [C
   4:        747239       17933736  java.lang.String
   5:        410531        9852744  java.util.Date
   6:        289690        9270080  java.util.HashMap$Node
   7:         91096        8934888  [Ljava.util.HashMap$Node;
   8:        101468        4870464  java.util.HashMap
   9:            42        4764744  [D
  10:         15416        4075024  [Ljava.lang.Object;
  11:         70656        1695744  io.netty.buffer.PoolThreadCache$MemoryRegionCache$Entry
  12:         11647        1299864  java.lang.Class
  13:         75796        1212736  java.util.HashSet
  14:         11988         959040  com.chinaway.event.service.pojo.MoveEventConfig
  15:         21815         698080  java.util.concurrent.ConcurrentHashMap$Node
  16:         28006         672144  com.chinaway.event.service.pojo.LastItem
  17:          7220         620992  [I
  18:         24883         597192  com.chinaway.event.service.pojo.SpeedEventConfig$SpeedConfig
  19:            17         557328  [Lscala.concurrent.forkjoin.ForkJoinTask;
  20:         34600         553600  org.apache.flink.api.java.tuple.Tuple1
  21:         12172         486880  com.chinaway.event.service.pojo.DoorEventConfig
  22:         12172         389504  com.chinaway.event.service.pojo.SpeedEventConfig
  23:          1450         359600  com.chinaway.event.model.event.MoveEvent
  24:          6845         328560  org.apache.flink.core.memory.HeapMemorySegment

從上可以分析出com.chinaway.event.model.gps.Location實例創(chuàng)建了 406482 個,非常多。

class name是對象類型,說明如下:

B  byte
C  char
D  double
F  float
I  int
J  long
Z  boolean
[  數(shù)組,如[I表示int[]
[L+類名 其他對象

還有一個很常用的情況是:用jmap把進程內(nèi)存使用情況dump到文件中,再用jhat分析查看。jmap進行dump命令格式如下:

jmap -dump:format=b,file=dumpFileName pid

比如對上面的進程進行dump

root@ubuntu:/# jmap -dump:format=b,file=/tmp/dump.dat 21711     
Dumping heap to /tmp/dump.dat ...
Heap dump file created

dump出來的文件可以用MAT、VisualVM等工具查看,這里用jhat查看:

root@ubuntu:/# jhat -port 9998 /tmp/dump.dat
Reading from /tmp/dump.dat...
Dump file created Tue Jan 28 17:46:14 CST 2014
Snapshot read, resolving...
Resolving 132207 objects...
Chasing references, expect 26 dots..........................
Eliminating duplicate references..........................
Snapshot resolved.
Started HTTP server on port 9998
Server is ready.

注意如果Dump文件太大,可能需要加上-J-Xmx512m這種參數(shù)指定最大堆內(nèi)存,即jhat -J-Xmx512m -port 9998 /tmp/dump.dat。然后就可以在瀏覽器中輸入主機地址:9998查看了。

jstat

語法如下

jstat [ generalOption | outputOptions vmid [interval[s|ms] [count]] ]

vmid是Java虛擬機ID,在Linux/Unix系統(tǒng)上一般就是進程ID。interval是采樣時間間隔。count是采樣數(shù)目。比如下面輸出的是GC信息,采樣時間間隔為250ms,采樣數(shù)為4:

yarn@ali-flink-03 ~]$ jstat -gc 7096 1000 4
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
512.0  512.0  288.0   0.0   493056.0 259950.8  988672.0   734556.3  62976.0 62030.2 7936.0 7718.8  21478  105.210   4      0.177  105.387
512.0  512.0  288.0   0.0   493056.0 279361.6  988672.0   734556.3  62976.0 62030.2 7936.0 7718.8  21478  105.210   4      0.177  105.387
512.0  512.0  288.0   0.0   493056.0 297160.0  988672.0   734556.3  62976.0 62030.2 7936.0 7718.8  21478  105.210   4      0.177  105.387
512.0  512.0  288.0   0.0   493056.0 316667.6  988672.0   734556.3  62976.0 62030.2 7936.0 7718.8  21478  105.210   4      0.177  105.387

jdk 1.8的輸出有些變化,最新的說明如下

  • S0C:第一個幸存區(qū)的大小
  • S1C:第二個幸存區(qū)的大小
  • S0U:第一個幸存區(qū)的使用大小
  • S1U:第二個幸存區(qū)的使用大小
  • EC:伊甸園區(qū)的大小
  • EU:伊甸園區(qū)的使用大小
  • OC:老年代大小
  • OU:老年代使用大小
  • MC:方法區(qū)大小
  • MU:方法區(qū)使用大小
  • CCSC:壓縮類空間大小
  • CCSU:壓縮類空間使用大小
  • YGC:年輕代垃圾回收次數(shù)
  • YGCT:年輕代垃圾回收消耗時間
  • FGC:老年代垃圾回收次數(shù)
  • FGCT:老年代垃圾回收消耗時間
  • GCT:垃圾回收消耗總時間

hprof

Heap/CPU Profiling Tool

hprof能夠展現(xiàn)CPU使用率,統(tǒng)計堆內(nèi)存使用情況。

語法格式如下:

java -agentlib:hprof[=options] ToBeProfiledClass
java -Xrunprof[:options] ToBeProfiledClass
javac -J-agentlib:hprof[=options] ToBeProfiledClass

比如統(tǒng)計cpu的使用

java -agentlib:hprof=cpu=samples,interval=20,depth=3 Hello

上面每隔20毫秒采樣CPU消耗信息,堆棧深度為3,生成的profile文件名稱是java.hprof.txt,在當(dāng)前目錄。
CPU Usage Times Profiling(cpu=times)的例子,它相對于CPU Usage Sampling Profile能夠獲得更加細(xì)粒度的CPU消耗信息,能夠細(xì)到每個方法調(diào)用的開始和結(jié)束,它的實現(xiàn)使用了字節(jié)碼注入技術(shù)(BCI):

javac -J-agentlib:hprof=cpu=times Hello.java

Heap Dump(heap=dump)的例子,它比上面的Heap Allocation Profiling能生成更詳細(xì)的Heap Dump信息:

javac -J-agentlib:hprof=heap=dump Hello.java
?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成,瀏覽時請結(jié)合常識與多方信息審慎甄別。
平臺聲明:文章內(nèi)容(如有圖片或視頻亦包括在內(nèi))由作者上傳并發(fā)布,文章內(nèi)容僅代表作者本人觀點,簡書系信息發(fā)布平臺,僅提供信息存儲服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

  • (一)Java部分 1、列舉出JAVA中6個比較常用的包【天威誠信面試題】 【參考答案】 java.lang;ja...
    獨云閱讀 7,249評論 0 62
  • Java 應(yīng)用性能優(yōu)化是一個老生常談的話題,典型的性能問題如頁面響應(yīng)慢、接口超時,服務(wù)器負(fù)載高、并發(fā)數(shù)低,數(shù)據(jù)庫頻...
    Rick617閱讀 7,605評論 1 9
  • 參考自 http://techblog.youdao.com/?p=961 在分析具體故障,先介紹一下幾種常用的工...
    抓兔子的貓閱讀 6,571評論 1 27
  • 我有時在想,我真正想要的是什么? 而每次只有同一個答案,我想要過上好日子考上理想的大學(xué),找到一個依靠,安安穩(wěn)穩(wěn)的生...
    孫佳穎閱讀 308評論 0 2
  • 電影一開始就對陳末的頹廢和神經(jīng)質(zhì)感到無聊,甚至懷疑他這兩年竟然還在電臺工作。鄧超一演起無厘頭來就感覺在看跑男。但是...
    7秒鐘的魚閱讀 161評論 0 0

友情鏈接更多精彩內(nèi)容