一、摘要
于硬件问题、系统资源紧缺或者程序本身的BUG,Java服务在线上不可避免地会出现一些“系统性”故障,比如:服务性能明显下降、部分(或所有)接口超
时或卡死等。其中部分故障隐藏颇深,对运维和开发造成长期困扰。笔者根据自己的学习和实践,总结出一套行之有效的“逐步排除”的方法,来快速定位Java
服务线上“系统性”故障。
二、导言
语言是广泛使用的语言,它具有跨平台的特性和易学易用的特点,很多服务端应用都采用Java语言开发。由于软件系统本身以及运行环境的复杂性,Java的
应用不可避免地会出现一些故障。尽管故障的表象通常比较明显(服务反应明显变慢、输出发生错误、发生崩溃等),但故障定位却并不一定容易。为什么呢?有如
下原因:
三、本方法适用的范围
四、有哪些异常现象
个程序由于BUG或者配置不当,可能会占用过多的系统资源,导致系统资源匮乏。这时,系统中其它程序就会出现计算缓慢、超时、操作失败等“系统性”故障。
常见的系统资源异常现象有:CPU占用过高、物理内存富余量极少、磁盘I/O占用过高、发生换入换出过多、网络链接数过多。可以通过top、iostat、vmstat、netstat工具获取到相应情况。
-
Java堆满
Java堆是“Java虚拟机”从操作系统申请到的一大块内存,用于存放Java程序运行中创建的对象。当Java堆满或者较满的情况下,会触发
“Java虚拟机”的“垃圾收集”操作,将所有“不可达对象”(即程序逻辑不能引用到的对象)清理掉。有时,由于程序逻辑或者Java堆参数设置的问题,
会导致“可达对象”(即程序逻辑可以引用到的对象)占满了Java堆。这时,Java虚拟机就会无休止地做“垃圾回收”操作,使得整个Java程序会进入
卡死状态。我们可以使用jstat工具查看Java堆的占用率。 -
日志中的异常
目标服务可能会在日志中记录一些异常信息,例如超时、操作失败等信息,其中可能含有系统故障的关键信息。 -
疑难杂症
死锁、死循环、数据结构异常(过大或者被破坏)、集中等待外部服务回应等现象。这些异常现象通常采用jstack工具可以获取到非常有用的线索。
五、故障定位的步骤
于不能排除的方面,要根据该信息对应的“危险程度”来判断是应该“进一步深入”还是“暂时跳过”。例如“目标服务Java堆占用100%”这是一条危险程
度较高的信息,建议立即“进一步深入”。而对于“在CPU核数为8的机器上,其它程序偶然占用CPU达200%”这种危险程度不是很高的信息,则建议“暂
时跳过”。当然,有些具体情况还需要故障排查人员根据自己的经验做出判断。
第一步:排除其它程序占用过量系统资源的情况
一行数值表示的是从系统启动到运行命令时的均值,我们忽略掉。从第二行开始,每一行的si/so表示该秒内si/so的block数。如果多行数值都为
零,则可以排除物理内存不足的问题。如果数值较大(例如大于1000
blocks/sec,block的大小一般是1KB)则说明存在较明显的内存不足问题。我们可以运行【top】输入shift+m,将进程按照物理内存
占用(“RES”列)从大到小进行排序,然后对排前面的进程逐一排查(见下面TIP)。
假如定位到是某个外部程序占用过量系统资源,则依据进程的功能和配置情况判断是否合乎预期。假如符合预期,则考虑将服务迁移到其他机器、修改程序运行的磁
盘、修改程序配置等方式解决。假如不符合预期,则可能是运行者对该程序不太了解或者是该程序发生了BUG。外部程序通常可能是Java程序也可能不是
Java程序,如果是Java程序,可以把它当作目标服务一样进行排查;而非Java程序具体排查方法超出了本文范围,列出三个工具供参考选用:
- 系统提供的调用栈的转储工具【pstack】,可以了解到程序中各个线程当前正在干什么,从而了解到什么逻辑占用了CPU、什么逻辑占用了磁盘等
- 系统提供的调用跟踪工具【strace】,可以侦测到程序中每个系统API调用的参数、返回值、调用时间等。从而确认程序与系统API交互是否正常等。
- 系统提供的调试器【gdb】,可以设置条件断点侦测某个系统函数调用的时候调用栈是什么样的。从而了解到什么逻辑不断在分配内存、什么逻辑不断在创建新连接等
第二步:排除目标服务占用了过量系统资源的情况
- 如果CPU使用分散到多个线程,而且每个线程占用都不算高(例如都<30%),则排除CPU占用过高的问题
-
如果CPU使用集中到一个或几个线程,而且很高(例如都>95%),则用【jstack pid >
jstack.log】获取目标服务中线程调用栈的情况。top中看到的占用CPU较高的线程的PID转换成16进制(字母用小写),然后在
jstack.log中找到对应线程,检查其逻辑:- 假如对应线程是纯计算型任务(例如GC、正则匹配、数值计算等),则排除CPU占用过高的问题。当然如果这种线程占用CPU总量如果过多(例如占满了所有核),则需要对线程数量做控制(限制线程数 < CPU核数)。
- 假如对应线程不是纯计算型任务(例如只是向其他服务请求一些数据,然后简单组合一下返回给用户等),而该线程CPU占用过高(>95%),则可能发生了异常。例如:死循环、数据结构过大等问题,确定具体原因的方法见下文“第三步:目标进程内部观察”。
第三步:目标服务内部观察
通过【jmap -dump:file=dump.map
pid】取得目标服务的Java堆转储,然后找一台空闲内存较大的机器在VNC中运行mat工具。mat工具中打开dump.map后,可以方便地分析内
存中什么对象引用了大量的对象(从逻辑意义上来说,就是该对象占用了多大比例的内存)。具体使用可以ca
- 检查jstack.log中是否有deadlock报出,如果没有则排除deadlock情况。
Found one Java-level deadlock:=============================“Thread-0″:waiting to lock monitor 0x1884337c (object 0x046ac698, a java.lang.Object),which is held by “main”“main”:waiting to lock monitor 0x188426e4 (object 0x046ac6a0, a java.lang.Object),which is held by “Thread-0″Java stack information for the threads listed above:===================================================“Thread-0″:at LockProblem$T2.run(LockProblem.java:14)– waiting to lock <0x046ac698> (a java.lang.Object)– locked <0x046ac6a0> (a java.lang.Object)“main”:at LockProblem.main(LockProblem.java:25)– waiting to lock <0x046ac6a0> (a java.lang.Object)– locked <0x046ac698> (a java.lang.Object)Found 1 deadlock.
- 用【POST http://www.xinitek.com/ajax/summaryJStack < jstack.log > jstack.log.summary】对jstack.log做合并处理,然后继续分析故障所在。
情况 | 嫌疑点 | 猜测原因 |
线程数量过多 | 某种线程数量过多 |
运行环境中“限制线程数量”的机制失效
|
多个线程在等待一把锁,但拿到锁的线程在做某个操作
|
拿到这把锁的线程在做网络connect操作
|
被connect的服务异常 |
|
拿到锁的线程在做数据结构遍历操作
|
该数据结构过大或被破坏
|
某个耗时的操作被反复调用
|
某个应当被缓存的对象多次被创建
|
对象池的配置错误 |
等待外部服务的响应
|
很多线程都在等待外部服务的响应
|
该外部服务故障
|
|
很多线程都在等待FutureTask完成,而FutureTask在等待外部服务的响应
|
该外部服务故障
|
用于查看Java级别内存情况。jmap是JDK自带工具,可以将Java程序的Java堆转储到数据文件中;MAT是eclipse.org上提供的一
个工具,可以检查jmap转储数据文件中的数据。结合这两个工具,我们可以非常容易地看到Java程序内存中所有对象及其属性。
1000 threads at“Timer-0″ prio=6 tid=0x189e3800 nid=0x34e0 in Object.wait() [0x18c2f000]java.lang.Thread.State: TIMED_WAITING (on object monitor)at java.lang.Object.wait(Native Method)at java.util.TimerThread.mainLoop(Timer.java:552)– locked [***] (a java.util.TaskQueue)at java.util.TimerThread.run(Timer.java:505)
38 threads at“Thread-44″ prio=6 tid=0×18981800 nid=0x3a08 waiting for monitor entry [0x1a85f000]java.lang.Thread.State: BLOCKED (on object monitor)at SlowAction$Users.run(SlowAction.java:15)– waiting to lock [***] (a java.lang.Object)
1 threads at“Thread-3″ prio=6 tid=0x1894f400 nid=0×3954 runnable [0x18d1f000]java.lang.Thread.State: RUNNABLEat java.util.LinkedList.indexOf(LinkedList.java:603)at java.util.LinkedList.contains(LinkedList.java:315)at SlowAction$Users.run(SlowAction.java:18)– locked [***] (a java.lang.Object)
daemon prio=10 tid=0x000000004dc43800 nid=0x65f5 waiting for monitor
entry [0x00000000507ff000]
“Thread-0″ prio=6 tid=0x189cdc00 nid=0×2904 runnable [0x18d5f000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:150)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
…
at RequestingService$RPCThread.run(RequestingService.java:24)
“pool-1-thread-1″ prio=6 tid=0x188fc000 nid=0×2834 runnable [0x1d71f000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:150)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
…
at IndirectWait.request(IndirectWait.java:23)
at IndirectWait$MyThread$1.call(IndirectWait.java:46)
at IndirectWait$MyThread$1.call(IndirectWait.java:1)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
at java.lang.Thread.run(Thread.java:722)
六、给运维人员的简单步骤
七、参考资料
- BTrace官网
- MAT官网
- 使用jmap和MAT观察Java程序内存数据
- 使用Eclipse远程调试Java应用程序
- Linux下输入【man strace/top/iostat/vmstat/netstat/jstack】
文章链接:http://techblog.youdao.com/?p=961
原创文章,作者:追马,如若转载,请注明出处:http://www.178linux.com/570