一个jstack/jmap等不能用的case

今天一个同学问我:”我排查问题时总是遇到,jmap -heap或-histo 不能用,是不是我们机器配置有啥问题哇? ” 分享下这个case的解决过程。

登上同学说的那台不能用的机器,执行jstack,报错:“get_thread_regs failed for a lwp”,这个问题以前碰到过,但忘了当时是什么原因了,执行其他的jmap -histo什么也卡着不动。

既然jstack没法弄,就pstack看看进程到底什么状况吧,于是pstack [pid]看,发现有一个线程的堆栈信息有点奇怪:
#0 0x00000038e720cd91 in sem_wait ()

对系统函数不太懂,但总觉得sem_wait这个有点奇怪,于是Google之,基本明白了这个是由于进程在等信号,这个时候通常会block住其他所有的线程,于是立刻ps看了下进程的状态,果然进程的状态变成了T,那上面碰到的所有现象都很容易解释了,于是执行:kill -CONT [pid],一切恢复正常。

继续查为什么进程状态会变成T,问问题的同学告诉了下我他在机器上执行过的一些命令,我看到其中一个很熟悉的命令:jmap -heap,看过我之前文章的同学估计会记得我很早以前分享过,在用cms gc的情况下,执行jmap -heap有些时候会导致进程变T,因此强烈建议别执行这个命令,如果想获取内存目前每个区域的使用状况,可通过jstat -gc或jstat -gccapacity来拿到。

到此为止,问题终于搞定,以后碰到jstack/jmap等不能用的时候,可以先看看进程的状态,因此还是那句话,执行任何一句命令都要清楚它带来的影响。

手头还有另外一个case,折腾了一个多星期了还是没太有头绪,case的现象是ygc越来越慢,但可以肯定不是由于cms gc碎片问题造成的,感兴趣的同学可以拿这个case去玩玩,如果能告诉我原因就更好了,:),执行下面的代码,启动参数可以为-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xms512m -Xmx512m -Xmn100m -XX:+UseConcMarkSweepGC:
[code]
import com.thoughtworks.xstream.XStream;

public class XStreamTest {

public static void main(String[] args) throws Exception {
while(true){
XStream xs = new XStream();
xs.toString();
xs = null;
}
}

}
[/code]

应该就可以看到ygc的速度从10+ms一直增长到100+ms之类的…

=============================
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。

jmap的几个操作要慎用

JDK中带有了一堆的工具是可以用来查看运行状况,排查问题的,但对于这些工具还是要比较清楚执行后会发生什么,否则有可能会因为执行了一个命令就导致严重故障,重点讲下影响比较大的jmap。

最主要的危险操作是下面这三种:
1. jmap -dump
这个命令执行,JVM会将整个heap的信息dump写入到一个文件,heap如果比较大的话,就会导致这个过程比较耗时,并且执行的过程中为了保证dump的信息是可靠的,所以会暂停应用。

2. jmap -permstat
这个命令执行,JVM会去统计perm区的状况,这整个过程也会比较的耗时,并且同样也会暂停应用。

3. jmap -histo:live
这个命令执行,JVM会先触发gc,然后再统计信息。

上面的这三个操作都将对应用的执行产生影响,所以建议如果不是很有必要的话,不要去执行。

另外,在排查问题的时候,对于保留现场信息的操作,可以用gcore [pid]直接保留,这个的执行速度会比jmap -dump快不少,之后可以再用jmap/jstack等从core dump文件里提取相应的信息,不过这个操作建议大家先测试下,貌似在有些jdk版本上不work。

之前碰到过一次语言集的问题,我们的Java应用多数在做字符串转码的时候是没有指定编码的,编码信息主要靠启动脚本里面设置LANG来控制,但没想到在某种场景下,竟然有地方设置了LC_ALL,在之前的一篇语言集的文章中,有讲过LC_ALL的优先级是最高的,所以导致启动脚本里设置的LANG失效了,从而导致了乱码,这个Case来看,对于Java应用,还是在启动参数上指定下-Dfile.encoding比较安全一点,避免这种默认的转码依赖系统的配置,很容易踩进坑里。

=============================
题图来源于:http://goo.gl/q2ppqr
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。

YGC频繁、NettyClient误用的两个Case

写写最近碰到的两个case,一个是关于ygc频繁排查的case,另一个是netty client误用造成的cpu sy高的case。

ygc频繁的case
很多人都问过我多久一次的ygc叫频繁,其实由于ygc通常是非常快的(几十ms或更低),所以通常来说ygc很频繁的发生也不会造成太大的影响,例如我们很多生产系统都是4s左右一次ygc。
ygc频繁是比较难查的,原因是ygc频繁,但通常来说都是ygc后就回收掉了,所以内存dump下来是看不出什么的,对于这个case我给的建议是多jmap -histo [pid]几次,原因是希望多看看在ygc的阶段中产生的对象到底是些什么…
业务方多执行了几次后,很幸运的看到了频繁产生的对象是一个自定义的对象,看到这个后就用btrace去跟了,看看到底是哪里在频繁的产生这个对象。
不过这个排查方法其实并没有通用,例如如果看到频繁产生的是char[],那就非常不好跟了….

netty client误用造成cpu sy高
有一个应用出现了cpu sy非常高的状况,sy大概使用到了60%,对于java应用而言sy如此高通常是由于线程太多,或线程主动切换太多造成的,按照这个思路,先统计了下线程数:ps -eLf | grep java -c,看到结果后,我和我的小伙伴们都惊呆了,1.6w个java线程,对大多数java应用而言,这不是太正常的现象,于是jstack dump看看线程到底什么状况。

jstack dump出来的结果显示,大部分的线程都是Netty I/O Worker线程…

对netty熟一些的同学会知道netty创建一个连接后,会将连接交给后端的NioWorker线程,由NioWorker线程来处理具体的I/O读写事件,NioWorker的线程池的线程数默认为cpu * 2,在上面的场景中创建了1w+的NioWorker线程,那只能是更前端让NioWorker产生了更多的线程数。

往上追朔可以看到NioWorker的线程数要创建更多的话,必然是NioClientSocketChannelFactory每次重新创建了,如每次创建连接时,NioClientSocketChannelFactory重新创建,就会直接导致每次创建的这个连接都会扔到一个新的NioWorker线程去处理。

和业务方确认后,可以看到业务方的代码里确实是在每次创建连接时都重新new NioClientSocketChannelFactory,这就能解释通了。

因此这问题的解决方法也很简单,NioClientSocketChannelFactory创建一个就够了,可以直接static创建一个,然后赋值到每次new的BootStrap里。

不过话说,这一定程度上来说确实是个“坑”,mina也是同样如此,server端由于通常只是启动一个端口监听,所以通常不会出现这现象,对于client而言,这貌似是挺容易犯的一个错。

=============================
题图来源于:http://www.caps-entreprise.com.cn/wp-content/uploads/2012/06/%E6%88%90%E5%8A%9F%E6%A1%88%E4%BE%8B.jpg
欢迎关注微信公众号:hellojavacases

关于此微信号:
分享Java问题排查的Case、Java业界的动态和新技术、Java的一些小知识点Test,以及和大家一起讨论一些Java问题或场景,这里只有Java细节的分享,没有大道理、大架构和大框架。

公众号上发布的消息都存放在http://hellojava.info上。