debug分析问题 jps jmap jstat starce pmap pstack

linux系统下

pstree：树结构显示进程

ps -Lf pid 查看有多少子进程

 

pmap  查看进程占用内存 

Usage: pmap [-x | -d] [-q] pid...

-x  show details

-d  show offset and device number

-q  quiet; less header/footer info

-V  show the version number

 

-d

扩展格式和设备格式域：

        Address:  start address of map  映像起始地址

        Kbytes:  size of map in kilobytes  映像大小

        RSS:  resident set size in kilobytes  驻留集大小

        Dirty:  dirty pages (both shared and private) in kilobytes  脏页大小

        Mode:  permissions on map 映像权限: r=read, w=write, x=execute, s=shared, p=private (copy on write)  

        Mapping:  file backing the map , or '[ anon ]' for allocated memory, or '[ stack ]' for the program stack.  映像支持文件,[anon]为已分配内存 [stack]为程序堆栈

        Offset:  offset into the file  文件偏移

        Device:  device name (major:minor)  设备名

最后一行的值
mapped 表示该进程映射的虚拟地址空间大小，也就是该进程预先分配的虚拟内存大小，即ps出的vsz
writeable/private  表示进程所占用的私有地址空间大小，也就是该进程实际使用的内存大小      
shared 表示进程和其他进程共享的内存大小

 

循环显示进程3066的设备格式的最后1行，间隔2秒，

while true; do pmap -d  3066 | tail -1; sleep 2; done

 

 

 

pstack pid

查看进程堆栈信息

 

 

strace pid

跟踪进程具体在干啥

strace  -tt -f -p 22621 -e trace=network

 

内存泄露的问题,用jdk自带的jps jmap jstat 等工具

 

core文件：

ulimit -c 

为o表示不生成，则执行

ulimit -c unlimited

unlimited

 

对应进程也会现在，可以如下查看：

cat /proc/<pid>/limits

这样当jvmcrash时候，就可dump core信息，当然

通过gcore $pid命令直接导出相应进程的core文件，此命令运行后， 会恢复程序的执行， 不影响程序的运行

 

gdb $JAVA_HOME/bin/java coredump_file

 

jstack $JAVA_HOME/bin/java coredump_file

jmap  $JAVA_HOME/bin/java coredump_file

 

这些命令，就可以查看当时的系统一些信息。

 

 

 

 

 

 

CLHSDB

java -classpath .:$JAVA_HOME/lib/sa-jdi.jar sun.jvm.hotspot.CLHSDB （启动CLHSDB）

hsdb> attach 30157 （连接到目标java进程）

hsdb> universe （查看java heap的情况）

hsdb> scanoops 0x0000000604000000 0x00000006042aebf0 Test   （在eden里搜索Test对象）

0x000000060404e248 Test

hsdb> revptrs 0x000000060404e248 （查找引用该Test对象的所有对象）

Oop for Main @ 0x000000060404d408

hsdb> inspect 0x000000060404d408 （查看找到的Main对象的内部结构）

instance of Oop for Main @ 0x000000060404d408 @ 0x000000060404d408 (size = 16)

<<Reverse pointers>>: 

_mark: 1

test: Oop for Test @ 0x000000060404e248 Oop for Test @ 0x000000060404e248

 

 

jps:
相当于linux下的ps,列出所有java相关线程的pid等信息
example:
$ jps  
18861 Bootstrap
1418 Jps
jmap:
显示java进程内存使用的相关信息
jmap pid 打印内存使用的摘要信息
jmap -histopid >mem.txt 打印比较简单的各个有多少个对象占了多少内存的信息，一般重定向的文件
jmap -dump:format=b,file= mem.dat pid 将内存使用的详细情况输出到mem.dat 文件

jmap -dump:live,format=b,file=heap.bin <pid>

 

 

 

jmap -histo 9201 >> aa.log

 

 

 num     #instances         #bytes  class name

----------------------------------------------

   1:       1007994       93830552  [C

   2:       2087930       83517200  java.lang.String

   3:         28122       38178800  [B

 

 

他的输出是按照总占用内存排序的

num是排序

 

#instance是对象的实例个数

 

#bytes是总占用的字节数

 

class name对应的就是Class文件里的class的标识

B代表byte

C代表char

D代表double

F代表float

I代表int

J代表long

Z代表boolean

前边有[代表数组，[I 就相当于int[]

 

对象用[L+类名表示

 

analyze heap 

将二进制的heap dump文件解析成human-readable的信息，自然是需要专业工具的帮助，这里推荐Memory Analyzer 。

用jhat命令可以参看 jhat -port 7000 mem.dat
在浏览器中访问：http://10.5.22.65:7000/ 查看详细信息
jstat:
显示java虚拟机的一些统计信息
jstat -选项 pid 间隔显示时间 显示次数
jstat -gc 18861 250 10
jstat -gccapacity 18861 250 10
jstat -gcnew 18861 250 10
jstat -gcnewcapacity 18861 250 10
jstat -gcold 18861 250 10

jstat -gcutil pid 1000 200

表示每1秒打印一次，共200次

 

 

 S0  — Heap上的 Survivor space 0 区已使用空间的百分比
    S1  — Heap上的 Survivor space 1 区已使用空间的百分比
    E   — Heap上的 Eden space 区已使用空间的百分比
    O   — Heap上的 Old space 区已使用空间的百分比
    P   — Perm space 区已使用空间的百分比
    YGC — 从应用程序启动到采样时发生 Young GC 的次数
    YGCT– 从应用程序启动到采样时 Young GC 所用的时间(单位秒)
    FGC — 从应用程序启动到采样时发生 Full GC 的次数
    FGCT– 从应用程序启动到采样时 Full GC 所用的时间(单位秒)
    GCT — 从应用程序启动到采样时用于垃圾回收的总时间(单位秒)
调试流程

内存泄漏一般都是有一定特征的，任何代码和数据都要占用内存，简单总结内存泄漏的特征是内存占用不可控制，GC不可回收。追踪内存使用量的曲线发现一些特征，在估计虚拟机即将崩溃时，使用 jmap -histopid >mem.txt 发现相关内存泄漏的对象占用非常打比例的内存空间，然后很容易猜测问题大概的位置，一下子就解决了。

 

 

 

 对于内存泄露的压力测试也开始实实在在的做起来。经过这次问题的定位和解决以后，大致觉得对于一个大用户量应用要放心的话，那么需要做这么几步。

1.       在GC输出的环境下，大压力下做多天的测试。（可以在 JAVA_OPTS增加-verbose:gc -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError）

2.       检查GC输出日志来判断是否有内存泄露。（这部分后面有详细的实例说明）

3.       如果出现内存泄露问题，则使用jprofiler等工具来排查内存泄露点（之所以不一开始使用，因为jprofiler等工具对于压力测试有影响，使得大压力无法上去，也使问题不那么容易暴露）

4.       解决问题，并在重复2步骤。

（这里的内存泄露问题就是在以前blog写过的jdk的concurrent包内LinkedBlockingQueue的poll方法存在比较严重的内存泄露，调用频率越高，内存泄露的越厉害）

两次压力测试都差不多都是两天，测试方案如下：

开始50个并发，每个并发每次请求完毕后休息0.1秒，10分钟后增长50个并发，按此规律增长到500并发。

 

 

先说一下日志输出的结构：(1.6和1.5略微有一些不同，只是1.6对于时间统计更加细致)

[GC [<collector>: <starting occupancy1> -> <ending occupancy1>, <pause time1> secs] <starting occupancy3> -> <ending occupancy3>, <pause time3> secs]

<collector>GC收集器的名称

<starting occupancy1> 新生代在GC前占用的内存

<ending occupancy1> 新生代在GC后占用的内存

<pause time1> 新生代局部收集时jvm暂停处理的时间

<starting occupancy3> JVM Heap 在GC前占用的内存

<ending occupancy3> JVM Heap 在GC后占用的内存

<pause time3> GC过程中jvm暂停处理的总时间

Jdk1.5 log：

启动时GC输出：

[GC [DefNew: 209792K->4417K(235968K), 0.0201630 secs] 246722K->41347K(498112K), 0.0204050 secs]

[GC [DefNew: 214209K->4381K(235968K), 0.0139200 secs] 251139K->41312K(498112K), 0.0141190 secs]

一句输出：

新生代回收前209792K，回收后4417K，回收数量205375K，Heap总量回收前246722K回收后41347K，回收总量205375K。这就表示100%的收回，没有任何新生代的对象被提升到中生代或者永久区（名字说的不一定准确，只是表达意思）。

第二句输出：

按照分析也就只是有1K内容被提升到中生代。

运行一段时间后：

[GC [DefNew: 210686K->979K(235968K), 0.0257140 secs] 278070K->68379K(498244K), 0.0261820 secs]

[GC [DefNew: 210771K->1129K(235968K), 0.0275160 secs] 278171K->68544K(498244K), 0.0280050 secs]

第一句输出：

         新生代回收前210686K，回收后979K，回收数量209707K，Heap总量回收前278070K回收后68379K，回收总量209691K。这就表示有16k没有被回收。

第二句输出：

         新生代回收前210771K，回收后1129K，回收数量209642K，Heap总量回收前278171K回收后68544K，回收总量209627K。这就表示有15k没有被回收。

比较一下启动时与现在的新生代占用内存情况和Heap使用情况发现Heap的使用增长很明显，新生代没有增长，而Heap使用总量增长了27M，这就表明可能存在内存泄露，虽然每一次泄露的字节数很少，但是频率很高，大部分泄露的对象都被升级到了中生代或者持久代。

又一段时间后：

[GC [DefNew: 211554K->1913K(235968K), 0.0461130 secs] 350102K->140481K(648160K), 0.0469790 secs]

[GC [DefNew: 211707K->2327K(235968K), 0.0546170 secs] 350275K->140921K(648160K), 0.0555070 secs]

第一句输出：

         新生代回收前211554K，回收后1913K，回收数量209641K，Heap总量回收前350102K回收后140481K，回收总量209621K。这就表示有20k没有被回收。

         分析到这里就可以看出每一次泄露的内存只有10几K，但是在大压力长时间的测试下，内存泄露还是很明显的，此时Heap已经增长到了140M，较启动时已经增长了100M。同时GC占用的时间越来越长。

后续的现象：

         后续观察日志会发现，Full GC的频率越来越高，收集所花费时间也是越来越长。（Full GC定期会执行，同时局部回收不能满足分配需求的情况下也会执行）。

[Full GC [Tenured: 786431K->786431K(786432K), 3.4882390 secs] 1022399K->1022399K(1022400K), [Perm : 36711K->36711K(98304K)], 3.4887920 secs]

java.lang.OutOfMemoryError: Java heap space

Dumping heap to java_pid7720.hprof ...

         出现这个语句表示内存真的被消耗完了。

Jdk1.6 log：

 

启动时GC的输出：

[GC [PSYoungGen: 221697K->31960K(229376K)] 225788K->36051K(491520K), 0.0521830 secs] [Times: user=0.26 sys=0.05, real=0.05 secs]

[GC [PSYoungGen: 228568K->32752K(229376K)] 232659K->37036K(491520K), 0.0408620 secs] [Times: user=0.21 sys=0.02, real=0.04 secs]

第一句输出：

         新生代回收前221697K，回收后31960K，回收数量189737K，Heap总量回收前225788K回收后36051K，回收总量189737K。100%被回收。

运行一段时间后输出：

[GC [PSYoungGen: 258944K->2536K(259328K)] 853863K->598135K(997888K), 0.0471620 secs] [Times: user=0.15 sys=0.00, real=0.05 secs]

[GC [PSYoungGen: 259048K->2624K(259328K)] 854647K->598907K(997888K), 0.0462980 secs] [Times: user=0.16 sys=0.02, real=0.04 secs]

第一句输出：

         新生代回收前258944K，回收后2536K，回收数量256408K，Heap总量回收前853863K回收后598135K，回收总量255728K。680K没有被回收，但这并不意味着就会产生内存泄露。同时可以看出GC回收时间并没有增加。

在运行一段时间后输出：

[GC [PSYoungGen: 258904K->2488K(259264K)] 969663K->713923K(1045696K), 0.0485140 secs] [Times: user=0.16 sys=0.01, real=0.04 secs]

[GC [PSYoungGen: 258872K->2448K(259328K)] 970307K->714563K(1045760K), 0.0473770 secs] [Times: user=0.16 sys=0.01, real=0.05 secs]

第一句输出：

         新生代回收前258904K，回收后2488K，回收数量256416K，Heap总量回收前969663K回收后713923K，回收总量255740K。676K没有被回收，同时总的Heap也有所增加。

         此时看起来好像和1.5的状况一样。但是查看了一下Full GC的执行还是400-500次GC执行一次，因此继续观察。

运行一天多以后输出：

[GC [PSYoungGen: 257016K->3304K(257984K)] 1019358K->766310K(1044416K), 0.0567120 secs] [Times: user=0.18 sys=0.01, real=0.06 secs]

[GC [PSYoungGen: 257128K->2920K(258112K)] 1020134K->766622K(1044544K), 0.0549570 secs] [Times: user=0.19 sys=0.00, real=0.05 secs]

可以发现Heap增长趋缓。

运行两天以后输出：

[GC [PSYoungGen: 256936K->3584K(257792K)] 859561K->606969K(1044224K), 0.0565910 secs] [Times: user=0.18 sys=0.01, real=0.06 secs]

[GC [PSYoungGen: 256960K->3368K(257728K)] 860345K->607445K(1044160K), 0.0553780 secs] [Times: user=0.18 sys=0.01, real=0.06 secs]

发现Heap反而减少了，此时可以对内存泄露问题作初步排除了。（其实在jdk1.6环境下用jprofiler来观察，对于concurrent那个内存泄露点的跟踪发现，内存的确还是会不断增长的，不过在一段时间后还是有回收，因此也就可以部分解释前面出现的情况）

总结：

         对于GC输出的观察需要分两个维度来看。一个是纵向比较，也就是一次回收对于内存变化的观察。一个是横向比较，对于长时间内存分配占用情况的比较，这部分比较需要较长时间的观察，不能仅仅凭短时间的几个抽样比较，因为对于抽样来说，Full GC前后的区别，运行时长的区别，资源瞬时占用的区别都会影响判断。同时要结合Full GC发生的时间周期，每一次GC收集所耗费的时间作为辅助判断标准。

         顺便说一下，Heap的 YoungGen,OldGen,PermGen的设置也是需要注意的，并不是越大越好，越大执行收集的时间越久，但是可能执行Full GC的频率会比较低，因此需要权衡。这些仔细的去了解一下GC的基础设计思想会更有帮助，不过一般用默认的也不错。还有就是可以配置一些特殊的GC，并行，同步等等，充分利用多CPU的资源。

         对于GC的优化可以通过现在很多图形工具来做，也可以类似于我这样采用最原始的分析方式，好处就是任何时间任何地点只要知道原理就可以分析无需借助外部工具。原始的总是最好的^_^。

 

 

 

默认情况下, top视图显示的为进程的cpu消耗的情况, 在top视图中按sheft+h, 可按线程来查看cpu的消耗状况. 

当cpu消耗严重时, 主要体现在us, sy, wa或hi的值变高, wa的值是io等待造成的, hi的值变高主要为硬件中断造成的, 例如网卡接收数据频繁的状况. 

对于java应用而言, cpu消耗严重主要体现在us, sy两个值上. 

us 
当us值过高时, 表示运行的应用消耗了大量cpu, 在这种情况下, 对于java应用而言, 最终的找到具体消耗cpu的值的线程锁执行的代码. 

首先通过linux提供的命令找到消耗cpu严重的线程以及id, 将此线程id转换成十六进制的值. 之后通过jstack的方式dump出应用的java线程信息, 通过之前转换出的十六进制的值找到对应的nid值的线程, 该线程极为消耗cpu的线程, 在采样时须多执行几次上述的过程, 以确保找到真实的消耗cpu的线程. 

java应用造成us高的原因主要是线程一直处于可运行状态(runnable), 通常是这些线程在执行无阻塞, 循环, 正则或者纯粹的计算等动作造成的; 另外一个可能也会造成us高的原因是频繁的gc, 如果每次请求都要分配较多的内存, 当访问量高的时候就将导致不断进行gc, 系统响应速度下降, 进入造成堆积的请求更多, 消耗的内存更严重, 最严重的时候有可能导致系统不断进行full gc, 对于频繁gc的状况可以通过分析jvm内存的消耗来查找原因. 

在程序运行时 使用top命令打开线程(sheft+h)查看情况 
找到最消耗线程的pid (26697), 将其转换为十六进制(0x6849), 结合java thread dump(jstack 26697 | grep 'nid=0x6849), 找到对应的线程 
由于jstack需要时间, 因此基于jstack并不一定能分析出真正消耗cpu的代码是哪行. 例如一个操作中循环调用了很多次其他的操作, 如其他的操作每次都比较快, 但由于循环太多次, 造成了cpu消耗, 在这种情况下jstack是无法捕捉出来的. 

sy 
当sy值高时, 表示linux花费了更多的时间在进行线程切换, java应用造成这种线程的主要原因是启动的线程比较多. 且这些线程多数都处于不断的阻塞(例如锁, io等待状态)和执行状态的变化过程中, 这就导致了操作系统要不断地切换执行的线程, 产生大量的上下文切换, 在这种状态下, 对java应用而言, 最要的是找出线程要不断切换的原因, 可采用的方法是通过jstack -l pid的方式dump出java应用程序的线程信息, 查看线程的状态信息以及锁信息, 找出等待状态或者锁竞争过多的线程. 

linux中可采用sar来分析网络io的消耗情况. 

vmstat 
在命令行中输入vmstat, 其中的信息和内存相关的主要是memory下的swpd, free, buff, cache以及swap下的si和so. 
其中swapd是指虚拟内存已经使用的部分, 单位为kb, free表示空闲的物理内存, buff表示用于缓存的内存, cache表示用于作为缓存的内容, swap下的si是指每秒从disk读取至内存的数据量, so是指每秒从内存中写入disk的数据量. 
swpd值过高通常是由于物理内存不够用了. os将物理内存中的一部分数据转为放入硬盘上进行存储, 以腾出足够的空间给当前运行的程序使用. 在目前运行的程序变化后, 即从硬盘上重新读取数据到内存中, 以便恢复程序的运行, 这个过程会产生swap io, 因此看swap的消耗情况主要要关注的是swap io的状况, 如swap io发生得较为频繁, 那么会严重影响系统的性能. 

sar -r 
用来查看内存的消耗情况 

引用

02:00:01 PM kbmemfree kbmemused  %memused kbbuffers  kbcached kbswpfree kbswpused  %swpused  kbswpcad 
02:10:01 PM    770152   3377524     81.43    144100    733408   2062708     33764      1.61       772 
02:20:01 PM    728776   3418900     82.43    145252    742916   2062708     33764      1.61       772

其中和swap相关的信息: kbswpfree表示swap空间的大小, kbswpused表示已使用的swap大小, %swpused  表示使用的swap的空间比率. 
kbmemfree kbmemused  %memused表示的是物理内存相关的信息, 当物理内存有空闲时, linux会使用一些物理内存用于buffer以及cache, 以提升系统的运行效率, 因此可以认为系统中可用的物理内存为:kbmemfree +kbcached +kbbuffers  

sar相比vmstat的好处是可以查看历史状况, 以便更加准确地分析趋势状况. 


如果系统不是cpu密集型, 且从新生代进入旧生代的大部分对象是可回收的, 那么采用CMS GC可以更好的在旧生代满之前完成对象的回收, 更大程度降低full gc的可能. 

cpu us高的原因主要是执行程序无任何挂起动作, 且一直执行, 导致cpu没有机会去调用执行其他的线程, 造成线程饿死(线程始终无法获得资源)的现象. 对于这种情况, 常见的一种优化方法是对这种线程的动作增加Thread.sleep, 以释放cpu的执行权, 降低cpu的消耗. 

造成cpu sy高的原因除了启动的线程过多以外, 还有一个重要的原因是线程之间锁竞争激烈, 造成线程状态经常要切换, 因此尽可能降低线程间的锁竞争也是常见的优化方法.