两个OOM Cases排查过程的分享

Posted on feb. 2 2014

两个OOM Cases排查过程的分享

BlueDavy之技术blog

{互联网，OSGi，Java, High Scalability, High Performance,HA}

两个OOM Cases排查过程的分享

Jan 13

bluedavy jvm 5 Comments 分享一下两个OOM Cases的查找过程，一个应用是Native OOM；另外一个应用其实没有OOM，只是每隔一段时间就会出现频繁FGC的现象，OOM的查找已经具备了不错的工具，但有些时候还是会出现很难查的现象，希望这两个排查过程的分享能给需要的同学带来一些帮助。

Native OOM的排查Case 之前的几个PPT里我都说到了，目前查找Native OOM最好的方法就是用google perftools了，于是挂上google perftools，等待应用再次native oom，很幸运，两天后，应用就再次native oom了，于是分析crash之前那段时间谁在不断的分配堆外的内存，pprof看到的结果主要是java.util.Inflater造成的，由于之前已经碰到过类似的case，知道如果使用了Inflater，但不显式的调用Inflater.end的话，确实会造成这个现象。于是剩下的问题就是找出代码里什么地方调用了Inflater，这种时候btrace这个神器就可以发挥作用了，一个简单的btrace脚本： ?1

2 3

4 5

6 7

8 9

10 11

12 13import

static

com.sun.btrace.BTraceUtils./*;

import

com.sun.btrace.annotations./*;

@BTrace

public

class

Trace{

@OnMethod

(

clazz=

"java.util.zip.Inflater"

method=

"/./*/"

)

public

static

void

traceExecute(

@ProbeMethodName

String methodName){

println(concat(

"who call Inflater."

,methodName));

jstack();

} }

执行后很快就找到了代码什么地方调用了Inflater，于是加上了显式的调用Inflater.end，搞定收工。

偶尔频繁FGC的排查Case 这个Case就没上面的那个那么顺利了，查了有接近一个月才查出最终的原因。当这个应用出现频繁FGC时，dump了内存，用MAT分析后，看到内存被消耗完的原因是由于几个线程内的ThreadLocalMap中有大量的数据，ThreadLocal中消耗最多内存的主要是一个HashMap，这里面有大量的数据。于是当时想到的第一个方法就是查查应用里面什么地方往ThreadLocal里放了HashMap，杯具的是，当查找代码后发现应用本身的代码并没有往ThreadLocal里放HashMap，那就只能是应用依赖的其他jar包做了这样的事了，但不可能去抓出这个应用依赖的所有的jar的源码来扫描，于是继续借助BTrace，写了个脚本来跟踪这类型的线程中谁调用了ThreadLocal.set，并且放的是HashMap，btrace脚本如下： ?1

2 3

4 5

6 7

8 9

10 11

12 13

14 15

16 import

static

com.sun.btrace.BTraceUtils./*;

import

com.sun.btrace.annotations./*;

@BTrace

public

class

Trace{

@OnMethod

(

clazz=

"java.lang.ThreadLocal"

method=

"set"

)

public

static

void

traceExecute(Object value){

(startsWith(name(currentThread()),

"xxx"

) && startsWith(

"java.util.HashMap"

,name(classOf(value))) ){

println(

"-------------------------"

);

jstack();

println();

}

OK，开始运行上面的脚本，发现竟然一直都没打印出什么内容，只能一直等了，杯具的是一直到了一周后再次出现频繁FGC时，这个脚本都没输出任何的东西，于是只好转换思路。

既然是HashMap里put了大量的某种类型的数据，那干脆用btrace来看看是谁在往HashMap里put这些数据，于是又写了一个btrace脚本，执行后，很快就看到了是代码中什么地方在put这些数据，但是从抓到的调用者来看，不仅仅是目前有大量数据的这类型的线程会调，其他类型的线程也会调用，如果这个地方有问题的话，应该就全部有问题了，于是跳过这里。

回到MAT看到的现象，会不会是因为代码什么地方用ThreadLocal的方式不对，又或是什么地方往ThreadLocal里放了东西，又忘了清除呢，因此要做的就是找出这个应用中所有属性为ThreadLocal的地方，来人肉分析了，于是写了一个jsp，扫描所有的classloader中的所有class，找出属性类型为ThreadLocal的，扫描后找到了一些，还真发现有一个和现在HashMap中放的数据一样的private ThreadLocal，这种用法在线程复用的情况下，如果是每次new ThreadLocal的话，会导致ThreadLocal放的东西一直不释放，兴奋的以为已经发现原因了，可惜和业务方一确认，这个类借助Spring保证了singleton的，因此不会有问题。好吧，到这一步，只能猜想是由于某种参数请求的时候造成业务上会获得大量的数据了，于是想着要找业务方来分析代码了，这个非常麻烦，于是到此就几乎停滞不前了。

今天静下心来，重新仔细的看了下MAT分析的结果，决定仍然用btrace跟踪下之前往HashMap中put数据的那个业务代码，突然发现，在web类型的处理线程中它借助的是filter去clear数据的，而杯具的是出问题的这种类型线程的处理机制是没有filter机制的，因此猜测问题估计出在这里了，继续btrace，看看这种类型的线程中是不是只有人调put，没人调clear，btrace脚本运行，很快就验证了这个猜测，于是相应的解决掉了这个case，搞定收工。

在这第二个case中，可见在频繁FGC或者OOM时，很有可能MAT只能告诉你初步的原因，但要对应到代码上到底是什么地方造成的，还得花很大精力分析了，这个时候BTrace通常能帮上很大的忙。

Sun JDK 1.6内存管理服务框架演变过程

5 Comments (+add yours?)

Jimmy Jan 18, 2011 @ 15:40:15 google perftools这个怎么用呢？能不能讲讲？
bluedavy Jan 18, 2011 @ 21:04:09 perftools装上后，只用设置上export LD_PRELOAD=[libtcmalloc所在的目录]/libtcmalloc.so，然后env HEAPPROFILE=dump的内存信息的文件名 java …，启动后就会每隔一段时间自动生成一些dump文件，最后通过perftools里面的pprof对dump文件进行分析就可以看到结果了。
sand May 21, 2011 @ 23:05:26 要是能有人多分享一下这种实际案例就好了
Leave a Reply

Cancel

Name (required)

Mail (required)

Website

CAPTCHA Image

CAPTCHA Code /*

July 2013 M T W T F S S « Mar 1234567 891011121314 15161718192021 22232425262728 293031

My Book

Icons & Wordpress Theme by N.Design

It so life

love as life

两个OOM Cases排查过程的分享

两个OOM Cases排查过程的分享

BlueDavy之技术blog

两个OOM Cases排查过程的分享

5 Comments (+add yours?)

Leave a Reply

Categories

Recent Comments

Tags

订阅

推荐书籍

My Book