JAVA问题定位跟踪技术

Posted 2020-09-17 开发者里程碑

常用的JAVA调试技巧： 
线程堆栈解读 
性能瓶颈分析 
远程调试 
内存泄露检测 

常用工具集： 
proc工具集 
系统跟踪命令truss/strace 
Core文件管理coreadm 
进程状态监控prstat 
网络状态监控netstat 
磁盘监控iostat 
CPU和内存监控vmstat抓包工具…… 

输出线程堆栈： 
Windows:在运行java的控制台上按ctrl+break组合键 
Unix:保留启动java的控制台，使用kill -3 <pid> 
*:启动时进行重定向是一个不错的习惯：run.sh > start.log 2>@1 

堆栈的作用： 
线程死锁分析 
辅助CPU过高分析 
线程资源不足分析 
性能瓶颈分析 
关键线程异常退出 

解读线程堆栈： 
wait() ————会释放监视锁 
sleep() ————与锁操作无关，继续保持监视锁 
当一个线程占有一个锁的时候，会打印- locked <0xe7402c48> 
当该线程正在等待别的线程释放该锁，就会打印：waiting to lock <0xe7402c48> 
如果代码中有wait()调用的话，首先是locked，然后又会打印 - waiting on <0xe7402c48> 
例如： 
"http-0.0.0.0-27443-Processor4" daemon prio=5 tid=0x599a7520 nid=0x1858 in Object.wait() [5c9ef000..5c9efd88] 
at java.lang.Object.wait(Native Method) 
- waiting on <0x1693d2f8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) 
at java.lang.Object.wait(Object.java:429) 
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:655) 
- locked <0x1693d2f8> (a org.apache.tomcat.util.threads.ThreadPool$ControlRunnable) 
at java.lang.Thread.run(Thread.java:534) 
其中- waiting on <0x1693d2f8>表示线程正停在该对象的wait上面。同时wait会自动释放该锁；- locked <0x1693d2f8>表示该线程锁住了该锁。 

"smpp02:Sender-108" daemon prio=5 tid=0x59a751a0 nid=0x13fc waiting for monitor entry [6066f000..6066fd88] 
at org.apache.log4j.Category.callAppenders(Category.java:185) 
- waiting to lock <0x14fdfe98> (a org.apache.log4j.spi.RootCategory) 
at org.apache.log4j.Category.forcedLog(Category.java:372) 
at org.apache.log4j.Category.log(Category.java:864) 
at org.apache.commons.logging.impl.Log4JLogger.debug(Log4JLogger.java:137) 
at com.huawei.uniportal.comm.base.server.AbstractHandler.send(AbstractHandler.java:407) 
at com.huawei.tellin.usr.uc.sendmessage.UCSMPPTransaction.send(UCSMPPTransaction.java:102) 
at com.huawei.tellin.usr.uc.sendmessage.UCServerProxy.synSend(UCServerProxy.java:134) 
at com.huawei.uniportal.comm.base.proxy.SendWorker.run(AbstractProxy.java:666) 
at com.huawei.uniportal.utilities.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748) 
at java.lang.Thread.run(Thread.java:534) 
其中- waiting to lock <0x14fdfe98> waiting to lock <0x14fdfe98> 表示该锁已经被别的线程使用，正在等待该锁被释放。 

线程死锁分析： 
Found one Java-level deadlock: 
============================= 
"thread1": 
  waiting to lock monitor 0x009fccb4 (object 0x10032710, a java.lang.Object), 
  which is held by "thread1" 
"thread1": 
  waiting to lock monitor 0x009fcc94 (object 0x10032718, a java.lang.Object), 
  which is held by "thread1" 

Java stack information for the threads listed above: 
=================================================== 
"thread0": 
        at DeadLockTest.run(DeadLockTest.java:44) 
        - waiting to lock <0x10032710> (a java.lang.Object) 
        - locked <0x10032718> (a java.lang.Object) 
        at java.lang.Thread.run(Unknown Source) 
"thread1": 
        at DeadLockTest.run(DeadLockTest.java:24) 
        - waiting to lock <0x10032718> (a java.lang.Object) 
        - locked <0x10032710> (a java.lang.Object) 
        at java.lang.Thread.run(Unknown Source) 
0x10032710 和 0x10032718 都在等待对方释放，双方都被饿死. 

用户代码导致CPU过高/热点线程分析： 

首先可以通过kill -3 pid(unix下) 或 <ctrl>+<break>( windows下) 获取一个堆栈信息， 
几分钟之后再获取一个，通过两个堆栈信息对比，将一直在忙的线程找出来。 
通过分析对应的代码，确认不正常的线程。 

第一步：通过kill -3 java_pid 获取当前堆栈信息。 
第二步：等待一段时间后。再获取一下当前堆栈信息。 
第三步：预处理前两个获取的堆栈信息，去掉处于sleeping或waiting的状态的线程。 
例如如下线程处于wait或者sleep状态， 
这种线程是不消耗CPU的，因此这些线程可以直接忽略掉，重点关注其它线程： 
"EventManager-Worker-1" daemon prio=8 tid=0x00c3ea58 nid=0x14a in Object.wait() [935ff000..935ffc28] 
at java.lang.Object.wait(Native Method)   //该线程已挂起，忽略掉 
- waiting on <0xbb9515a8> (a org.exolab.core.util.FifoQueue) 
at java.lang.Object.wait(Object.java:429) 
第五步：对比预处理后的1，2堆栈信息，找出处于busy状态的线程，该类线程可能是导致cpu高占用率的可疑线程。 
例如：(下面的是在第一个堆栈信息中找到的处于active 活跃状态的线程) 

"http-80-Processor6" daemon prio=5 tid=0x013ea770 nid=0x143 runnable [92eff000..92f019c0] 
at com.huawei.u_sys.common.licmgr.LicenseIntf.nativeCheckLicense(Native Method) 
at com.huawei.u_sys.common.licmgr.LicenseIntf.checkLicense(LicenseIntf.java:168) 
at com.huawei.u_sys.meetingone.sysmgr.ejb.LicRelateBean.updateLic(LicRelateBean.java:80) 

同一个线程在第二个堆栈信息中仍处于活跃状态。 
"http-80-Processor6" daemon prio=5 tid=0x013ea770 nid=0x143 runnable [92eff000..92f019c0] 
at com.huawei.u_sys.common.licmgr.LicenseIntf.nativeCheckLicense(Native Method) 
at com.huawei.u_sys.common.licmgr.LicenseIntf.checkLicense(LicenseIntf.java:168) 
at com.huawei.u_sys.meetingone.sysmgr.ejb.LicRelateBean.updateLic(LicRelateBean.java:80) 
两次打印堆栈该线程一直在运行，说明该线程已运行了5分钟，请在代码中检查该线程是否属于长时间运行线程？如果属于暂态线程，如此长时间运行说明可能有死循环等导致的CPU过高。

性能瓶颈分析 

高性能的含义： 
有的场合高性能意味着用户速度体验，如界面操作。- 适合使用OptimizeIt分析 
还有的场合，高吞吐量意味着高性能，如短信。 - 适合使用堆栈分析 
还有的场合是二者的结合，如IP电话- 适合使用堆栈分析 

性能瓶颈问题产生的源头分析 
常见架构和设计问题： 
   不恰当的线程同步 
不良的架构（同步／异步使用不当） 
并发设计不当－资源抢占导致的资源竞争, 连接池和线程池等应用不当等 
效率低下的通信方式 
数据库连接等竞争资源参数设置不当 
    内存泄漏/不恰当的虚拟机运行参数 
    缓慢的磁盘/网络 IO 

… … 
常见编码问题 
String +，getByte()的不恰当使用：很多时侯可以使用StringBuf 
过大的同步范围 
ＳＱＬ语句设计不当 
… … 

性能瓶颈分析手段和方法之一－线程堆栈剖析 
原理：通过分析JVM线程运行情况，定位性能问题 
方法：　kill -3 <pid> (UNIX)  ctrl+break (windows) 打印出当前的虚拟机的一个运行剖面，进行分析 

"WorkerThread-8" ... in Object.wait() ... 
... - locked <0xf14213c8> (a Queue) ... 
"WorkerThread-10" ... in Object.wait() ... 
... - locked <0xf14213c8> (a Queue) ... 
"WriterThread-3" ... in Object.wait() ... 
... - locked <0xf14213c8> (a Queue) ... 

能够发现的性能问题： 
(1) 资源争用 
(2) 锁的粒度过大
(3) sleep的滥用 

适用场合： 
识别只有在高负载的时候才出现的性能瓶颈。 
多线程场合 

不适用的场合： 
单操作单线程下的代码段耗时分析,如一次界面点击，感觉迟缓。 

性能瓶颈分析手段和方法之一     －两种典型的性能瓶颈的堆栈特征 
1.绝大多数线程都在做相同的事情，很少有空闲线程。 
   如： 90%的Sender线程都在执行callAppender 
    "smpp02:Sender-108" daemon prio=5 tid=0x59a751a0 nid=0x13fc waiting for monitor entry   [6066f000..6066fd88] 
at org.apache.log4j.Category.callAppenders(Category.java:185) 
- waiting to lock <0x14fdfe98> (a org.apache.log4j.spi.RootCategory) 
at org.apache.log4j.Category.forcedLog(Category.java:372) 
at org.apache.log4j.Category.log(Category.java:864) 
可能的原因： 
线程数量过小 
锁粒度过大 
资源竞争（数据库连接池等） 
耗时操作（大量的磁盘IO，最终是串行操作） 

2.绝大多数线程处于等待状态，只有几个线程在工作，总体性能上不去。 
可能的原因： 
系统存在关键路径，该关键路径没有足够的能力给下个阶段输送大量输送任务，导致其他地方空闲 
如：在消息分发系统，消息分发一般是一个线程，而处理是多线程，这时候消息分发是瓶颈的话，观察到的线程堆栈就会出现上面的现象。 

性能瓶颈分析手段和方法之二 －虚拟机参数调优 
原理： 
观察垃圾回收情况并且进行调整，使JVM的垃圾回收更加平滑和高效率 

方法：　Java 命令行中增加 –verbose:gc 运行参数 
[Full GC 792332K->412757K(1040896K), 8.9157secs] 
[Full GC 799898K->221096K(1040896K), 5.3018secs] 
如果每次回收完成后可用的内存持续减少则可能存在内存泄漏。 
能够发现的性能问题： 
垃圾回收参数设置不合理导致的严重的性能问题． 
内存泄漏 

可以调节的JVM 垃圾回收参数 
IBM JDK：主要参数： -Xconcurrentbackground  –Xconcurrentlevel, 以及堆大小。 
SUN，HP JDK 主要是 -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction 
JVM调优是个系统工程，和运行环境主要是内存配置密切相关，需要酌情配置处理 

适用场合： 
高负载但实时性要求不高的系统，如 Web 类应用，如移动彩铃应用，以及大容量且实时性要求非常高的系统，比如呼叫类应用。 

下列JVM参数可用于获取gc日志 

-verbose:gc 或 
-Xloggc:filename 

一些参考资料 
http://www-128.ibm.com/developerworks/cn/java/j-jtp11253/ 
http://www-128.ibm.com/developerworks/cn/java/j-perf05214/ 
http://www-128.ibm.com/developerworks/cn/java/j-perf06304/ 

性能瓶颈分析手段和方法之三 － 性能调优工具  

OptimizeIt或JProfile － 提供全面的内存泄漏分析，函数调用CPU时间和内存占用分析 

适用场合： 
（1） 单操作单线程下的代码段耗时分析,如一次界面点击，感觉迟缓。 

不适用的场合： 
（1）运行期间，同一段代码被不同线程执行时，由于线程是变化的，无法找出对应的线程。 
（2）大容量应用下出现的瓶颈, 因为启动这个工具性能会有几十倍甚至上百倍的的性能下降，难以支撑大容量情况下的测试分析。只有在大容量下出现的锁竞争也许不会出现，频繁的磁盘IO、数据库访问等导致的瓶颈也不会出现。现象不充分暴露，自然也就谈不上分析。 

JAVA 远程调试 

虚拟机远程调试开关： 

-Xdebug -Xrunjdwp:transport=dt_socket,server=y,address=%DEBUG_PORT%,suspend=n；suspend设为n时JVM会在打开调试端口后正常启动，若设为y则JVM启动后会等候调试器连接后才继续启动 

JAVA 内存泄漏检测 

内存泄露产生 
2.1      java的垃圾回收机制 
java虚拟机的垃圾回收算法要做两件事情。首先，它必须检测出垃圾对象。 
其次，它必须回收垃圾对象所使用的堆空间并还给程序。 
垃圾检测通常通过建立一个根对象的集合并且检查从这些根对象开始的可触及性来实现。 
如果正在执行的程序可以访问到的根对象和某个对象之间存在引用路径，这个对象就是可触及的。 
对于程序来说，根对象总是可以访问的。从这些跟对象开始， 
任何可以被触及的对象都被认为是“活动”对象。无法被触及的对象被认为是垃圾， 
因为它们不再影响程序的未来执行。 

2.2      内存泄漏的产生 
如果系统中存在越来越多的不再影响程序未来执行的对象，且这些对象和根对象之间存在引用路径， 
内存泄漏产生了。 

2.3      内存泄漏的消除 
根据 内存泄漏的产生 所述。发生内存泄漏要满足如下两个条件： 
1. 系统中存在越来越多的不再影响程序未来执行的对象。 
2. 这些对象和根对象之间存在引用路径。 
从这两个条件中能很容易找出消除内存泄漏的方法：截断系统中存在的不影响程序未来执行的对象与 
根对象之间的引用路径。这样，这些对象就成了“垃圾”对象，javm就能正常回收它们。 

常见的内存泄露陷阱 
常见的内存泄露 
（1） 全局HashMap等容器，在对象不需要后没有及时从容器中remove掉 
       特别是在抛出异常的时候，一定要确保remove方法执行到。 

（2） Runnable对象new了就必须使用线程来Run等 

Java内存泄漏的初步确定 
下面是使用GC输出分析内存泄漏的原理: 
 [GC 65.233: [DefNew: 12949K->1434K(13824K), 0.0122730 secs] 87703K->76189K(134892K), 0.0123500 secs] 
     (87703K->76189K(134892K), 87703K表示系统使用了多少内存(我们称之为当前使用内存), 
     76189K表示进行这次垃圾回收之后使用的内存数量(我们称之为垃圾回收后内存),134892K上两个数据相减)    
  
   可以按照如下思路分析GC输出,能够初步比较准确地判断系统是否存在内存泄漏: 
   (1) 首先要确保系统已经稳定运行(如初使化等已经完成等) (这个条件很重要) 
   (2) 然后取一个时间段的GC 输出作为分析数据，只分析FULL GC的行，以垃圾回收后的值为分析对象 
   (3) 然后根据GC分析内存的使用情况: 
       A. 如果当前使用内存持续增长, 而垃圾回收后内存也持续增长, 有一直增长到Xmx设置的内存的趋势, 
       那么这个时侯基本上就可以断定有内存泄漏问题了. 
       B. 如果当前使用内存增长到一个值之后,又能回落, 达到一个动态平衡, 那么就没有内存泄漏的情况. 

[Full GC 912526K->614350K(912576K), 2.5546922 secs] 
[Full GC 912526K->623890K(912576K), 2.5777505 secs] 
[Full GC 912575K->625359K(912576K), 2.5620272 secs] 
[Full GC 912575K->648552K(912576K), 2.5632979 secs] 
[Full GC 912532K->688576K(912576K), 2.5211377 secs] 
[Full GC 912532K->714354K(912576K), 2.6212585 secs] 
[Full GC 912538K->784362K(912576K), 2.5190768 secs] 
（1） 只有FULL GC的行才有分析价值 
（2） 只需要检查完全垃圾后剩余的内存值是否一直再增大。 

JAVA 内存泄漏精确定位 
借助一些工具，如：Optimizeit JProfiler、JRockit等， 
甚至可以使用Java虚拟机自带的工具HProf进行问题的定位；使用HProf的方法如下： 

java -Xrunhprof 其它参数 要运行的系统main函所在的类 
具体的参数列表如下： 
Hprof usage: -Xrunhprof[:help]|[:<option>=<value>, ...] 
Option Name and Value  Description                Default 
---------------------  ----------------------     ------- 
heap=dump|sites|all    heap profiling             all 
cpu=samples|times|old  CPU usage                  off 
monitor=y|n            monitor contention         n 
format=a|b             ascii or binary output     a 
file=<file>           write data to file         java.hprof(.txt for ascii) 
net=<host>:<port>      send data over a socket    write to file 
depth=<size>           stack trace depth          4 
cutoff=<value>         output cutoff point        0.0001 
lineno=y|n             line number in traces?     y 
thread=y|n             thread in traces?          n 
doe=y|n                dump on exit?              y 
gc_okay=y|n            GC okay during sampling    y 
Example: java -Xrunhprof:cpu=samples,file=log.txt,depth=3 FooClass 
使用HProf定位内存泄漏问题时，可以通过通过增加参数“heap=sites”来输出堆栈信息到文件中， 
然后通过分析堆栈信息h和线程信息来判断内存泄漏的位置； 

JAVA 内存泄漏检测-OptimizeIt 
使用OptimizeIt定位内存泄露确切位置的步骤： 

（1） 系统稳定运行一段时间，即按照从业务逻辑来讲， 
      不应该再有大的内存需求波动。这个非常重要。 
（2） 点击OptimizeIt上的垃圾回收按钮，然后马上再点mark按钮。 
      将当前实际对象的数量作为基准点。 
（3） 过一段时间（如一个小时或者更多） 
（4） 点击OptimizeIt上的垃圾回收按钮，检查是否有大量的对象增加， 
      如果有增加，主要是哪些对象 
确定可疑范围，通过结合阅读代码进行分析。 

Unix下调试利器-Proc工具介绍 
/proc文件系统不是普通意义上的文件系统，它是一个到运行中进程地址空间的访问接口。通过/proc，可以用标准Unix系统调用(比如open()、read()、write()、ioctl()等等)访问进程地址空间。 
大多数Unix(/Linux)操作系统在带一系列的工具集，借助这些工具，可以对进行进行剖析，从而协助定位相关问题。 
Windows下可以使用Taskinfo工具分析类似的内容 
Linux下直接到/Proc下面，大部分数据可读。 可结合lsof进行分析 

Proc工具列表 
pcred 
pfiles 
pflags 
pldd 
pmap 
prun 
psig 
pstack 
pstop 
ptime 
ptree 
pwait 
pwdx 
plimit