JVM故障分析排障用到的一些命令和工具

为什么80%的码农都做不了架构师？>>>   

这次记录一下最近生产环境上遇到的种种看起来奇怪的问题，虽然是其他团队发生的，但是也可从中学习到很多知识。接下来我们会首先描述“奇怪的问题场景”，接下来结合各种系统、JVM指标对问题进行分析。看完这篇短文，你将学会：

1.JVM原生命令工具的使用，以及使用这些工具进行JVM分析调优

2.了解JVM内存模型，堆参数设置以及GC原理，以及读懂gc.log

3.常用的OS 命令工具的使用。

接下来我们从小怪开始打起，一路升级。。。首先说明的是这台服务器配置 8C24G，JVM : heap 20G，GC: ParaNew + CMS

【问题一】服务器夯死，无法提供服务，JVM错误Java.lang.OutOfMemoryError: unable to create new native thread

【分析】 看到这个异常，即便是不熟悉JVM的同学也会知道是因为创建线程失败，因为错误信息描述的很清楚。但是失败的原因可能会有很多情况：OS或JVM没有内存分配了，又或者是触发了OS的某种限制，很容易想到使用ulimit -a。

先分析内存使用情况，熟悉JVM的同学这个时候应该会去看下每个线程栈的大小（-XSS）是多少？另外，目前已经开了多少线程了？那么两者的乘积就是占用的内存大小， 使用java -XX:+PrintFlagsFinal -version | grep ThreadStackSize 查看线程栈大小为1M， 使用Top -Hp pid 查看该进程所有的线程数量为1200，也就是说，这1000个线程会用掉1G的内存，离着20G差的有点远。。

再看下OS资源限制的问题，使用操作系统ulimit -u（指定对用户可以创建的进程数的限制）查看max_user_processor参数为为4096，该服务器最高时httpclient、jetty、Dubbo线程池相加为4700，在高并发请求下触发了4096阀值，所以触发限制创建线程失败。。原因找到了，问题也就解决了，最后调大了max_user_processor。

【补充】在不能减少线程数的情况下，只能通过减少最大堆(-Xmx)和减少线程栈(-Xss)来换取更多的线程数。Heap+Stack 约等于JVM内存大小，减小堆大小，可以获得更多的栈内存，从而获得更多线程。

【问题二】不同配置下，相同GC，耗时不同

生产存在两种不同的JVM配置，目前存在4C8G和8C24G两种类型服务器，其中4C8G服务器的JVM配置为堆大小4G，新生代3G(Eden=2.4g, S0=0.3g, S1=0.3g)，年老代1G，垃圾回收算法ParNew+CMS，这种配置下YGC效率和性能较高，交易高峰期为70秒一次YGC，每次STW(SafePoint)对交易的影响较小，影响为10～20ms；另外一批8C24G的服务器的JVM配置为堆区20G，其中新生代4G(Eden=3.2g, S0=0.4, S1=0.4g)，年老代16g，这种配置下YGC效率和性能较差，交易高峰期为90秒一次YGC，每次STW(SafePoint)对交易的影响较大，影响为70～300ms；

【分析】从问题来看，JVM不是越大越好。

【问题三】现象是造成Young GC时间长（由100ms~200ms增加至800ms～30000ms），频率为两个小时一次，该问题是由于服务器CPU中断和上下文切换每隔两小时突然大幅度升高一次引起，具体引起中断和上下文切换的Root cause未知？这个问题也是最诡异，影响最大的，当时已经导致交易响应超时而失败。

【分析】分析gc日志，发现gc耗时800ms～30000ms的这段时间，该时间段内服务器Zabbix监控发现cpu的usr和sys指标突然偏高，并且均发生了非常明显的Interrupts(中断)和context switch(上下文切换)突然升高的现象。并且是每隔2小时会发生一次CPU利用率、中断和上下文切换等指标突然升高的现象。

在下一个预计的时间节点前后用pidstat（监控指定进程的指标）和vmstat（监控系统的指标）命令进行了采样分析。13:02分几乎准时的出现该问题，通过对采样数据的分析发现：所有进程的cswch/s（每秒任务主动切换上下文的次数）和nvcswch/s（每秒任务被动切换上下文的次数）均未发生异常波动，所有进程的上下文切换值相加约为200。而系统的Interrupts采样峰值为62011，context switch采样峰值为117391，远大于正常值1000和1200左右。因此，暂时排出了应用程序引起的系统中断和上下文切换问题

pidstat 命令详解

【Root Cause】操作系统的SWAP和Java进程YGC同时触发导致了该现象。JVM里有一个特殊的线程VM Threads，在执行GC前，会让所有线程堵塞，即进入安全点(Safepoint)，然后STW(Stop the world)，并开始标记需要被清理的对象，从服务器上用vmstat/jstat/iostat等工具命令的监控来看，当VM Threads标记时需要对相应堆分区的已用内存进行遍历，这时候正好触发了操作系统内核将有堆的一部分内容被交换到SWAP中，遍历到这部分的时候就需要将其交换回内存，由于Swap分区在磁盘，将其交换会内存及其浪费性能，导致JVM卡顿，从而导致YGC耗时增加平时的十倍以上。那么为什么在操作系统物理内存还有剩余的情况下，会主动的将进程内存交换至swap分区？从监控上看在发生swap时，操作系统仍然后576M的物理内存（free），用户内存为8.9G（free + buffers + cached）, 但是此处操作系统触发Swap操作，仅跟物理内存有关系，跟用户占用的内存没关系。这里解释为什么在576M的时候触发swap？操作系统有一个参数叫：swappiness（通过cat /proc/sys/vm/swappiness查看），读i 该参数解释如下：当swappiness为0的时候表示最大限度使用物理内存，然后才是 swap空间，当swappines为100的时候，则表示积极的使用swap分区，并且把内存上的数据及时的搬运到swap空间里面。服务器目前将该值设置为了30，因此当物理内存还剩下576M(总物理内存为24G)时触发了swap操作就不奇怪了。

【总结】最后整理下整个分析过程用到的命令

首先是 jdk 工具命令Oracle官方

jvm参数设置，-Dproterties的设置

https://blog.csdn.net/turkeyzhou/article/details/7619472

转载于:https://my.oschina.net/nipin/blog/2051702