Java异常处理手册V1.0

目录

  • Linux诊断
  • jvm诊断

Linux诊断

  • cpu
  • 内存
  • 网络(连接,状态)
  • 磁盘IO
  • 句柄数

使用top命令

使用top命令主要查看load average,cpu使用率iowait等指标

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            

网络监测

网络监测,第一步先监测网络是否通畅,使用ping监测网络是否可达
第二步监测端口是否通畅,可以使用telnet 端口

netstat -na
显示当前所有活动的网络连接

显示出所有处于监听状态的应用程序及进程号和端口号:
netstat -aultnp

Close_Wait的问题

对于 服务器的连接状态而言,一般有四种比较常见的: Established、 Time_Wait、Close_Wait、Closed。 服务器大量出现close_wait通常是因为没有发送close Fin包给客户端,客户端收到fin包,则会向ack ,则服务端会最终关闭。
通过客户端与服务端的交互都知道,在客户端与服务端之间交互时,服务端出现CLOSE_WAIT,根本问题一定是服务端的代码有问题。
Close wait是一种被动关闭状态。而不是LAST_ACK状态,则说明服务端的程序因为请求某些资源的原因造成没有释放程序。曾经因为程序的一个bug造成大量的接受端程序处于close_wait的状态,所以对于程序来说如果出现大量的close_wait,那么通常需要检测程序的异常。

磁盘IO

查看系统的io_wait
如果 %util 接近 100%,说明产生的I/O请求太多,I/O系统已经满负荷,该磁盘可能存在瓶颈。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,内存不足
  • 内存泄露
  • 线程死锁
  • 锁争用(Lock Contention)
  • Java进程消耗CPU过高

常用的工具

  • jps
  • jstack
  • jmap
  • jstat
  • jprof

jps

jps主要用来输出JVM中运行的进程状态信息。语法格式如下:

jps [options] [hostid]

命令行参数选项说明如下:
-q 不输出类名、Jar名和传入main方法的参数
-m 输出传入main方法的参数
-l 输出main类或Jar的全限名
-v 输出传入JVM的参数

比如下面的命令

# 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进程内的线程堆栈信息。语法格式如下:

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

jstack可以定位到线程堆栈,根据堆栈信息我们可以定位到具体代码,所以它在JVM性能调优中使用得非常多。下面通过一个实例找出某个Java进程中最耗费CPU的Java线程并定位堆栈信息,用到的命令有ps、top、printf、jstack、grep。

第一步

先找出Java进程ID,我部署在服务器上的Java应用名称为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,第二步找出该进程内最耗费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的线程,用。
转化成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) {
    }
}

它是轮询任务的空闲等待代码,上面的sigLock.wait(timeUntilContinue)就对应了前面的Object.wait()。

jmap

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

jmap用来查看堆内存使用状况,一般结合jhat使用。

jmap语法格式如下

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

使用jmap -heap pid查看进程堆内存使用情况,包括使用的GC算法、堆配置参数和各代中堆内存使用情况。比如下面的例子:

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查看堆内存中的对象数目、大小统计直方图,如果带上live则只统计活对象,如下:

 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实例创建了 406482 个,非常多。

class name是对象类型,说明如下:

B  byte
C  char
D  double
F  float
I  int
J  long
Z  boolean
[  数组,如[I表示int[]
[L+类名 其他对象

还有一个很常用的情况是:用jmap把进程内存使用情况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这种参数指定最大堆内存,即jhat -J-Xmx512m -port 9998 /tmp/dump.dat。然后就可以在浏览器中输入主机地址:9998查看了。

jstat

语法如下

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

vmid是Java虚拟机ID,在Linux/Unix系统上一般就是进程ID。interval是采样时间间隔。count是采样数目。比如下面输出的是GC信息,采样时间间隔为250ms,采样数为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:第一个幸存区的大小
  • S1C:第二个幸存区的大小
  • S0U:第一个幸存区的使用大小
  • S1U:第二个幸存区的使用大小
  • EC:伊甸园区的大小
  • EU:伊甸园区的使用大小
  • OC:老年代大小
  • OU:老年代使用大小
  • MC:方法区大小
  • MU:方法区使用大小
  • CCSC:压缩类空间大小
  • CCSU:压缩类空间使用大小
  • YGC:年轻代垃圾回收次数
  • YGCT:年轻代垃圾回收消耗时间
  • FGC:老年代垃圾回收次数
  • FGCT:老年代垃圾回收消耗时间
  • GCT:垃圾回收消耗总时间

hprof

Heap/CPU Profiling Tool

hprof能够展现CPU使用率,统计堆内存使用情况。

语法格式如下:

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

比如统计cpu的使用

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

上面每隔20毫秒采样CPU消耗信息,堆栈深度为3,生成的profile文件名称是java.hprof.txt,在当前目录。
CPU Usage Times Profiling(cpu=times)的例子,它相对于CPU Usage Sampling Profile能够获得更加细粒度的CPU消耗信息,能够细到每个方法调用的开始和结束,它的实现使用了字节码注入技术(BCI):

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

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

javac -J-agentlib:hprof=heap=dump Hello.java
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 194,319评论 5 459
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 81,801评论 2 371
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 141,567评论 0 319
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 52,156评论 1 263
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 61,019评论 4 355
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 46,090评论 1 272
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 36,500评论 3 381
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 35,192评论 0 253
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 39,474评论 1 290
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 34,566评论 2 309
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 36,338评论 1 326
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 32,212评论 3 312
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 37,572评论 3 298
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 28,890评论 0 17
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 30,169评论 1 250
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 41,478评论 2 341
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 40,661评论 2 335

推荐阅读更多精彩内容

  • (一)Java部分 1、列举出JAVA中6个比较常用的包【天威诚信面试题】 【参考答案】 java.lang;ja...
    独云阅读 7,028评论 0 62
  • Java 应用性能优化是一个老生常谈的话题,典型的性能问题如页面响应慢、接口超时,服务器负载高、并发数低,数据库频...
    Rick617阅读 7,297评论 1 9
  • 参考自 http://techblog.youdao.com/?p=961 在分析具体故障,先介绍一下几种常用的工...
    抓兔子的猫阅读 5,920评论 1 27
  • 我有时在想,我真正想要的是什么? 而每次只有同一个答案,我想要过上好日子考上理想的大学,找到一个依靠,安安稳稳的生...
    孙佳颖阅读 285评论 0 2
  • 电影一开始就对陈末的颓废和神经质感到无聊,甚至怀疑他这两年竟然还在电台工作。邓超一演起无厘头来就感觉在看跑男。但是...
    7秒钟的鱼阅读 121评论 0 0