排查java进程cpu100%的大致过程
- 之前遇到过
之前也遇到过cpu 100%的问题,原因是while循环,死循环了,一直占有cpu。 - cpu为什么会100%
我们都知道cpu是时分(time division)的,操作系统里有很多线程,每个线程的运行时间由cpu决定,cpu会分给每个线程一个时间片,时间片是一个很短的时间长度,如果在时间片内,线程一直占有,则是100%;我们应该意识到,cpu运行速度很快(主频非常高),除非密集型耗费cpu的运算,其它类型任务都会在小于时间片的时间内结束。 - cpu 100%大致排查过程
排查java cpu100%的问题,大致步骤是固定的,首先找到占用cpu的进程,如果是java进程,则继续查看是哪个线程占用cpu,然后根据线程id从线程栈中找到对应线程栈,到这里,问题基本也就解决了。
故事背景
今天后台管理系统出现cpu 100%,这个问题间歇性出现,后台管理系统使用ssm(spring+springmvc+mybatis)+shiro实现,用户量很小,所以可以排除高并发导致。接下来,我们按照前述排查步骤,进行排查。
找到cpu 100%的进程
登录linux服务器找到占用cpu的进程,使用top
top
找出服务器的所有java进程,
ps -ef | grep java
或者使用
jps
经对比,占用cpu的进程是java进程,继续挖,找出占用CPU的线程
top -H -p pid
-H
表示以线程的维度展示,默认以进程维度展示。
一共4个占用cpu的线程id 2944-2947,需要将线程id从十进制转为十六进制,因为java线程栈文件中的线程id是十六进制。十进制 转十六进制的命令是
echo "obase=16;number" | bc
obase(output base)是输出的进制,number是输入值,默认十进制,bc(An arbitrary precision calculator language)是任意进制转换语言。
执行
echo "obase=16;2944" | bc
结果是
B80
或者使用printf
10进制转16进制
[root@localhost ]# printf '%x\n' 15
f
导出栈
将java进程的线程栈导出,
jstack pid > pid.tdump
pid.tdump文件后缀名随意,通常以tdump结尾。
在pid.tdump中找到nid=0XB80
的线程,这4个线程都是gc线程。一般的cpu 100%问题到这就结束了,但是这次不一样,因为这4个线程是gc 线程。gc线程忙碌表示内存不够用了,要进行内存回收,第一反应是java内存回收不了,导致一直gc。
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007fa49c01f000 nid=0xb80 runnable
"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007fa49c020800 nid=0xb81 runnable
"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007fa49c022800 nid=0xb82 runnable
"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007fa49c024000 nid=0xb83 runnable
导出堆
首先看一下堆的使用情况
jstat -gcutil pid
查看Java内存占用情况,发现老年代和伊甸区,使用率都90%多,但是存活区分配的很小大约500KB,并且基本没有使用;伊甸园区本来应该复制到存活区,但存活区过小,所以直接复制到老年代,但老年代已经没有空间了,所以,伊甸区越积累越多。那么到底是什么占着老年代不释放呢?
没办法,导出java 堆来看看吧。如下将堆内存导出,只导出live的对象:
jmap -dump:live,format=b,file=pid.hprof pid
同样的 文件后缀名可以是任意的,因为它也是二进制的,不过通常以hprof结尾。
jvisualvm分析快照
使用JAVA_HOME/bin/jvisualvm.exe
,载入快照(文件----->载入—>文件类型(堆))
按照大小排序,找出占用内存最大的类别,居然是字节数组,右击在实例图中显示,
我们发现字节数组的值都很规律,前半部分的字节数组基本都相同,我就想能不能把字节数组转为字符串,这样就能 知道字节数组是什么内容了,恰好左下角有个将字节数组另存为二进制文件的选项。
将二进制文件转为字符串,发现这些字节数组是当前用户的信息,如下
File file = new File("C:\\Users\\DELL\\Desktop\\heap.bin");
final FileInputStream fileInputStream = new FileInputStream(file);
byte[] buffer = new byte[300];
int len = -1;
while((len=fileInputStream.read(buffer))!=-1){
System.out.println(new String(buffer,0,len , "utf8"));
}
结合项目分析
当前用户信息放在session中,而session又放在ehcache和redis,check shiro的sessionDAO发现,session销毁时,只将redis的session删除,而未将ehcache中的也删除,另外查看ehcache中关于session cache配置,内存中元素个数是0,也就是不限制,这个很危险,并且配置的也不正确。为了重现这个问题,重启了tomcat,然后jmeter压测登录,发现老年区和伊甸区又满了,在等待了3个小时(最大存活时间)后,cpu仍然100%。
RedisSessionDAO .java
public class RedisSessionDAO extends EnterpriseCacheSessionDAO {
@Override
public void doDelete(Session session) {
//将redis中的session清除
}
}
ehcache.xml,shiro session ehcache配置可以参考shiro session设置了过期时间不起作用、无效;
<cache name="shiro-activeSessionCache"
maxEntriesLocalHeap="0"
eternal="false"
timeToIdleSeconds="10800" //3小时
timeToLiveSeconds="10800" //3小时
overflowToDisk="false"/>
session过期时间为3小时,时间太长了
<bean id="sessionManager" class="org.apache.shiro.web.session.mgt.DefaultWebSessionManager">
<property name="globalSessionTimeout" value="10800000"></property>
</bean>
改正
改正,session销毁时,将ehcache中的session也销毁
RedisSessionDAO .java
public class RedisSessionDAO extends EnterpriseCacheSessionDAO {
@Override
public void doDelete(Session session) {
//将echache中的session也删除
getActiveSessionsCache().remove(sessionId);
//将redis中的session清除
}
}
ehcache.xml
<cache name="shiro-activeSessionCache"
maxEntriesLocalHeap="100"
eternal="true"
timeToIdleSeconds="0"
timeToLiveSeconds="0"
overflowToDisk="true"/>
去掉globalSessionTimeout,默认是30分钟
<bean id="sessionManager" class="org.apache.shiro.web.session.mgt.DefaultWebSessionManager">
</bean>
观察
jmeter压测一段时间后,老年代上升了,但过了1个小时(session调度器的默认执行间隔)后,old区,降下去了。到此为止,问题基本解决了。
必知必会java内存分析命令
上文提到的jstack、jmap、jstat、jvisualvm都位于 JAVA_HOME/bin 目录下,这个目录下有很多有用的工具。
疑问
虽然ehcache配置错误,但配了最大存活时间和最大空闲时间为3个小时,即使内存不限制数量,但到了3个小时ehcache应该会删除才是,为什么没删除呢?这个由于时间限制加上本身配置就是错误的应该配置为不限制,所以没继续追踪下去。