又一个陷入困局的case,求助

最近排查case实在是非常的不顺,又碰到了一起至今为止还无解的case,分享并顺带求助下。

这个case的现象是应用负载很低,但执行jstack或jmap都提示需要加-F来强制执行,碰到这样的现象,自己常用的一招就是先gcore pid生成下core dump,然后再用jstack/jmap去拿,jstack从core dump里提取java stack信息的时候报错了,于是只好jmap去提取内存dump信息,这个成功了,放到内部的web版的mat上一看,内存使用很正常,线程也挺正常的。

于是用pstack去看那个java的进程到底在做什么,诡异的是看到的是这个java进程正在执行cms gc,执行到MarkSweep::follow_stack这一步,一直不动,这太奇怪了,这个时候刚好应用这边的人告诉我一个信息是,卡住之前gc log里显示一直在做cms gc。

到这个阶段为止,这个现象仍然是非常的奇怪,第一次碰到一个应用一直做cms gc然后到卡死的状况,百思不得其解,在一通瞎折腾后,突然看到这个进程的状态与众不同的处于T状态,T状态表明进程处于STOPPED或TRACED状态,那就可以解释为什么会卡住了,猜想应该没人做TRACE,于是就执行了下kill -18 pid,进程恢复了,gc log里开始继续输出信息,一直在做full gc,后来查明进程进入T状态的原因是之前执行jmap后异常退出,导致进程变成T状态了,但为什么会变成这个细节目前还没去查,如果有人知道也欢迎反馈。

到这步,理论上问题就好查了,进入了典型的OOM排查模式,悲催的是dump内存,还是失败,gcore再jmap,分析后显示只占了几十M的内存,这还是不对,只好再次尝试执行jmap –dump,在dump了两次后终于成功了,拿着这个dump文件开始分析。

dominator tree显示内存主要是被三个线程占用,每个线程里占用最多的都是com.sun.tools.javac.util.ListBuffer,三个线程都是在执行com.sun.tools.javac.Main.compile中产生出来的,而且都是在compile同一个java代码。

对这块的机制不太熟,猜想莫非是多个线程compile同一段代码会出现并发问题,导致死循环了,于是自己在本机模拟写了一个多线程compile同一个java代码的测试,没碰到问题,在生产环境里也用真实环境去测试了下,也没重现。

这个case到目前仍然是这个状况,完全不明白为什么compile产生出了一个暴大的ListBuffer,不知道有没有看官们碰到过类似问题呢,求建议或帮助。

—————————–
这个case爆出后,前两天还出现了一个同学在线上执行jmap -heap,然后导致进程进入T状态,这个有可能是两个原因,一是在用cms gc的情况下,有些时候jmap -heap的输出会一直循环,然后就卡住了,另一种就是执行的时候异常退出了,所以我以前给的建议一直是不要在生产环境执行jmap -heap,jstat完全可以满足需求,而且更安全。

—————————–
上篇文章中提及到一个tomcat支持长连接的问题,里面有说到很难找到文章清晰的讲解tomcat的三种connector(apr、nio、bio)模式的工作原理,同事@宏江 同学写了一篇很不错的文章,让自己受益匪浅,推荐给大家看看,感兴趣的可以点击阅读原文

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

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

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

一个挺有意思的OOM Case

上周有个应用出现了OOM,但现象还挺有意思的,非常与众不同,分享下。

当时出问题的时候现象为应用的日志里打了这样的日志:
allocating large array…
array_size[1073741848 bytes]
array_length[1073741826 elememts]
这个在之前阿里版JDK里有说过是阿里版JDK的增强功能,当运行时有地方出现创建一个巨大的数组(例如>700MB)时,会直接打印出这样的日志,并同时会输出相应的线程堆栈信息。
如果不是阿里版的JDK,在这种情况下看到的现象就会是OOM的异常信息,那样排查会稍微麻烦一些。

线程堆栈信息如下:
at java.util.Arrays.copyOf(Arrays.java:2786)
at java.io.ByteArrayOutputStream.write(ByteArrayOutputStream.java:94)
– locked <0x0000000799b41f58> (a java.io.ByteArrayOutputStream)
at java.io.ObjectOutputStream$BlockDataOutputStream.drain(ObjectOutputStream.java:1847)
at java.io.ObjectOutputStream$BlockDataOutputStream.setBlockDataMode(ObjectOutputStream.java:1756)
at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1169)
at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:330)
at java.util.HashMap.writeObject(HashMap.java:1000)
at sun.reflect.GeneratedMethodAccessor134.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:940)
at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1469)

从这个线程堆栈信息来看,是在序列化一个HashMap时写了一个巨大的数组。

逻辑上来说,造成这样的现象,应该是HashMap本身非常大,因此就去查看了下当时dump下来的内存信息,看看当时在序列化的这个HashMap的状况。

在MAT中查看,发现这个HashMap中的一个桶里的链表出现了头尾是同一个对象的现象,按照经验,出现这种现象的原因是在并发场景中使用了HashMap进行读写,并且没做线程安全的保护。

和业务方确认后确定确实这个HashMap被用在了并发场景,并且没做保护,而这个HashMap又是要作为结果对象返回给调用端的,所以导致在序列化这个HashMap的时候出现了HashMap.writeObject一直结束不了,并且会积累出很大的数组,从而引发了上面的异常信息。

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

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

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

java.lang.OutOfMemoryError:Map failed

以前在写各种处理Java OOM总结的ppt的时候,列到的OOM是以下这几种:
1.GC overhead limit exceeded
2.Java Heap Space
3.Unable to create new native thread
4.PermGen Space
5.Direct buffer memory
6.request {} bytes for {}. Out of swap space?
一直自认为不会有超过这个范围的OOM类型出现,没想到最近看到了一个新的OOM的类型,而这次OOM引发了一次严重的故障,整个排查过程是内部一个同事排查的,文章也是他写的,感谢他的文章,让我也学习到了之前遗漏的一个OOM相关的知识点。

故障现象为
应用日志中发现了大量的OOM异常:
Caused by: java.lang.OutOfMemoryError: Map failed

跟踪堆栈找到抛出异常的地方是在 FileChannle#map,这个方法是创建一个内存映射文件,应用为了降低堆内存的使用,同时提高写入的效率,将一个文件分成多段,内存映射多个MappedByteBuffer进行读写操作;

跟踪fileChannle.map的方法发现最终调用的是FileChannelImpl.c里的方法;

继续跟踪这段代码,发现里面调用的mmap64这个系统函数,当mmap64返回的错误码是ENOMEM时,会向上抛出OOME,进一步查阅了GNU的手册,可以发现抛出ENOMEM错误码的解释:
1. 内存不足;
2. 地址空间不足。

而从当时的现场信息来看,这两点都不成立,当时没有新的思路,于是就先按照FileChannleImpl.unmap方法中的主动释放占用内存的方法改了下代码,改了后应用就一切正常了。

当天这个机器的JVM还crash了一次,crash日志中heap占用和物理内存都是非常正常,但日志中有个现象比较诡异: Dynamic libraries:这部分信息非常多,统计以后发现有65532条。

翻阅资料,发现这个数据来自 /proc/{pid}/maps, 这个文件展示了进程的虚拟地址空间的使用情况,这时突然想到ENOMEM中有说到进程的地址空间不足导致的,但是最后的7fff005aa000还远不到上限,而且计算虚拟内存占用也就几个G的空间。
这时想到前面提到65532这个数据,联想到了file-max,但是一查看是4889494,顺势猜想虚拟内存映射是不是也有打开上限? 不出所料果然是有限制的。

max_map_count这个参数就是允许一个进程在VMAs(虚拟内存区域)拥有最大数量,VMA是一个连续的虚拟地址空间,当进程创建一个内存映像文件时VMA的地址空间就会增加,当达到max_map_count了就是返回out of memory errors。
这个数据通过下面的命令可以查看:
cat /proc/sys/vm/max_map_count

发现应用所在的机器这个数值果然是65536,而且测试修改max_map_count后filechannel#map的个数的上限也随之变化。 所以可以确定程序OOM是由于达到了这个系统的上限,也就是ENOMEM错误码中所指的out of process address。

确定了异常的触发原因,再排查引发的原因就比较容易了,再看下FileChannleImp#map的代码,发现在map第一次出现OOM时,会显式的调用System.gc去回收,但不幸的是应用启动参数上是有-XX:+DisableExplicitGC的,所以就导致了map失败,但如果在代码里主动clean是ok的现象。

总结来说,这个异常出现的原因是:
数据量增长,导致map file个数增长,应用启动参数上有-XX:+DisableExplicitGC,导致了在map file个数到达了max_map_count后直接OOM了(这也是因为heap比较大,所以full gc触发的频率低,这个问题就特别容易暴露)。

从这个问题来看,启动参数上加-XX:+DisableExplicitGC确实还是要小心,不仅map file这里是在OOM后靠显式的去执行System.gc来回收,Direct ByteBuffer其实也是这样,而这两个场景都有可能因为java本身full gc执行不频繁,导致达到了限制条件(例如map file个数达到max_map_count,而Direct ByteBuffer达到MaxDirectMemorySize),所以在CMS GC的场景下,看来还是去掉这个参数,改为加上-XX:+ExplicitGCInvokesConcurrent这个参数更稳妥一点。

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

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

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

答:Java线程创建相关的几个小知识点问题

昨天问题收到的两个典型答复如下:
1. 一个线程占用1m的空间,一直循环下去将会导致内存空间不足,进而占用swap区域,因此报第一个错;第二个错是因为swap区域亦不足,导致ls等命令都无空间可运行。
2. xss是一个线程的分配空间。题目设置的1m 一共2w 4w个当然会报内存溢出。

这两个回答都不正确。
正确的答案和原因是:
1. 当用-Xss1m执行时,VIRT会占用20000M左右,RES会很少,原因是线程启动后,只是会去先占用相应的栈大小的地址空间,但不会真正去占用内存,只有在真正需要使用的时候才会去占用;如果是在32bit机器上执行,Java进程会直接crash,原因是32 bit的linux默认每个进程最多申请3G的地址空间;

2. 可能会出现java.lang.OutOfMemoryError:unable to create new native thread的原因不是因为内存被耗光,而是因为os对每个用户能创建的最多进程/线程数的限制,限制的个数是多少可以通过ulimit -u进行查看,当创建的线程个数超过了os的这个值的限制,也会抛出上面的异常;

3. 可能会出现Resource temporarily unavailable的原因同样不是内存被耗光,像linux 2.6.18/32等内核默认的kernel.pid_max的值为32768,意味着在单台机器上最多创建32768个线程,即使ulimit -u的值超过32768也没用,因此如果在未调过kernel.pid_max的机器上执行创建4w个线程的代码,就会出现Resource temporarily unavailable。

之前微博上的九州-姬野之前给我分享了一个cpu sy高的排查case,挺有意思的,这里有个类似的case,感兴趣的可以看看:
http://structureddata.org/2012/06/18/linux-6-transparent-huge-pages-and-hadoop-workloads/