第三步：目标服务内部观察
图示：目标服务内部观察
1. Java堆占用情况
用【jstat -gcutil pid】查看目标服务的OLD区占用比例，假如占用比例低于85%则排除Java堆占用比例过高的问题。
假如占用比例较高（例如超过98%），则服务存在Java堆占满的问题。这时候可以用jmap+mat进行分析定位内存中占用比例的情况（见下文TIP），从而较快地定位到Java堆满的原因。
TIP：用jmap+mat进行分析定位内存中占用比例的情况
先通过【jmap -dump:file=dump.map pid】取得目标服务的Java堆转储，然后找一台空闲内存较大的机器在VNC中运行mat工具。mat工具中打开dump.map后，可以方便地分析内存中什么对象引用了大量的对象（从逻辑意义上来说，就是该对象占用了多大比例的内存）。具体使用可以ca
2. 异常日志观察
通过类似【tail -10000 stdout.log.2014-08-15 | grep -B2 -A10 -i exception】这样的方式，可以查到日志中最近记录的异常。
3. 疑难杂症
用【jstack pid > jstack.log】获取目标服务中“锁情况”和“各线程调用栈”信息，并分析
检查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.
如果发现deadlock则则根据jstack.log中的提示定位到对应代码逻辑。
用【POST http://www.xinitek.com/ajax/summaryJStack < jstack.log > jstack.log.summary】对jstack.log做合并处理，然后继续分析故障所在。
通过jstack.log.summary中的情况，我们可以较迅速地定位到一些嫌疑点，并可以猜测其故障引起的原因（后文有jstack.log.summary情况举例供参考）
| 情况 | 嫌疑点 | 猜测原因 |
| 线程数量过多 | 某种线程数量过多 | 运行环境中“限制线程数量”的机制失效 |
多个线程在等待一把锁，但拿到锁的线程在做某个操作 |
拿到这把锁的线程在做网络connect操作 |
被connect的服务异常 |
拿到锁的线程在做数据结构遍历操作 |
该数据结构过大或被破坏 |
|
某个耗时的操作被反复调用 |
某个应当被缓存的对象多次被创建 |
对象池的配置错误 |
等待外部服务的响应 |
很多线程都在等待外部服务的响应 |
该外部服务故障 |
很多线程都在等待FutureTask完成，而FutureTask在等待外部服务的响应 |
该外部服务故障 |
猜测了原因后，可以通过日志检查、监控检查、用测试程序尝试复现等方式确认猜测是否正确。如果需要更细致的证据来确认，可以通过BTrace、strace、jmap+MAT等工具进行分析，最终确认问题所在。
下面简单介绍下这几个工具：
BTrace：用于监测Java级别的方法调用情况。可以对运行中的Java虚拟机插入调试代码，从而确认方法每次调用的参数、返回值、花费时间等。第三方免费工具。
strace：用于监视系统调用情况。可以得到每次系统调用的参数、返回值、耗费时间等。Linux自带工具。
jmap+MAT：用于查看Java级别内存情况。jmap是JDK自带工具，可以将Java程序的Java堆转储到数据文件中；MAT是eclipse.org上提供的一个工具，可以检查jmap转储数据文件中的数据。结合这两个工具，我们可以非常容易地看到Java程序内存中所有对象及其属性。
TIP：jstack.log.summary情况举例
1. 某种线程数量过多
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)
2. 多个线程在等待一把锁，但拿到锁的线程在做数据结构遍历操作
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: RUNNABLE
at 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)
3. 某个应当被缓存的对象多次被创建（数据库连接）
99 threads at “resin-tcp-connection-*:3231-321″ daemon prio=10 tid=0x000000004dc43800 nid=0x65f5 waiting for monitor entry [0x00000000507ff000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:290) - waiting to lock <0x00000000b26ee8a8> (a org.apache.commons.dbcp.PoolableConnectionFactory) at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:771) at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95) … 1 threads at “resin-tcp-connection-*:3231-149″ daemon prio=10 tid=0x000000004d67e800 nid=0x66d7 runnable [0x000000005180f000] java.lang.Thread.State: RUNNABLE … at org.apache.commons.dbcp.DriverManagerConnectionFactory.createConnection(DriverManagerConnectionFactory.java:46) at org.apache.commons.dbcp.PoolableConnectionFactory.makeObject(PoolableConnectionFactory.java:290) - locked <0x00000000b26ee8a8> (a org.apache.commons.dbcp.PoolableConnectionFactory) at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:771) at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:95) at …
4. 很多线程都在等待外部服务的响应
100 threads at “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)
5. 很多线程都在等待FutureTask完成，而FutureTask在等待外部服务的响应
100 threads at “Thread-0″ prio=6 tid=0×18861000 nid=0x38b0 waiting on condition [0x1951f000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for [***] (a java.util.concurrent.FutureTask$Sync) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186) at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834) at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:994) at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1303) at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:248) at java.util.concurrent.FutureTask.get(FutureTask.java:111) at IndirectWait$MyThread.run(IndirectWait.java:51) 100 threads at “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)
为方便读者使用，将故障定位三个步骤的图合并如下：
图示：故障定位步骤汇总
故障定位是一个较复杂和需要经验的过程，如果现在故障正在发生，对于分析经验不很多的开发或运维人员，有什么简单的操作步骤记录下需要的信息吗？下面提供一个
六、给运维人员的简单步骤
如果事发突然且不能留着现场太久，要求运维人员：
1. top: 记录cpu idle%。如果发现cpu占用过高，则c, shift+h, shift + p查看线程占用CPU情况，并记录
2. free: 查看内存情况，如果剩余量较小，则top中shift+m查看内存占用情况，并记录
3. 如果top中发现占用资源较多的进程名称（例如java这样的通用名称）不太能说明进程身份，则要用ps xuf | grep java等方式记录下具体进程的身份
4. 取jstack结果。假如取不到，尝试加/F
jstack命令：jstack PID > jstack.log
5. jstat查看OLD区占用率。如果占用率到达或接近100%，则jmap取结果。假如取不到，尝试加/F
jstat命令： jstat -gcutil PID
S0 S1 E O P YGC YGCT FGC FGCT GCT 0.00 21.35 88.01 97.35 59.89 111461 1904.894 1458 291.369 2196.263
jmap命令： jmap -dump:file=dump.map PID
6. 重启服务
参考资料
- BTrace官网
- MAT官网
- 使用jmap和MAT观察Java程序内存数据
- 使用Eclipse远程调试Java应用程序
- Linux下输入【man strace/top/iostat/vmstat/netstat/jstack】
