Perm区持续增长的问题排查

线上出现:java.lang.OutOfMemoryError: PermGen space

java.lang.OutOfMemoryError: PermGen space
[2016-05-12 16:55:49.272] [DubboServerHandler-10.252.115.167:20880-thread-180] [ERROR] com.alibaba.dubbo.rpc.filter.ExceptionFilter:90 x:(_cid=a:5bf5c0|t:117|s:1463043299969) -  [DUBBO] Got unchecked and undeclared exception which called by 10.117.22.115. service: com.sfebiz.logistics.api.LogisticsCallbackService, method: bspcallback, exception: java.lang.OutOfMemoryError: PermGen space, dubbo version: 2.5.3-notification-fix, current host: 10.252.115.167
java.lang.OutOfMemoryError: PermGen space

第一时间查看Perm区大小,发现JVM启动参数没有配置,默认情况下是82M左右,原因是运维同学在脚本修改的时候漏了XX参数设置,加上Perm参数,并重启应用。 jvm-start-params-perm-set

但系统监控中的Perm区:呈现缓慢增长

current-logistics-jvm-perm-growing

 

查看历史Perm区的数据信息:

history-logistics-jvm-perm-growing

 

能造成Perm缓慢增长的方式一般有以下几种:
  1. 常量池的膨胀,比如String.intern调用,但是一般会通过GC回收;(JDK7之前常量池位于Perm区,JDK7及8常量池重Perm区迁移到了Heap中)
  2. 动态Java类创建,比如使用Cglib创建类、Gson对象转换、Jaxb对象转换等。

分析一:怀疑Bpm动态创建类导致:

期初判断可能是BPM中动态生成类造成的,但是我之前在BPM编译Java代码的地方打印了日志:

tbpm-load-class

 

通过统计日志分析,只找到了12条编译代码,不会是由于此问题导致

[yanmingming@logistics1.hz /home/admin/logs/logistics-service/info]$grep "Local file path is" info-2016-05-12*.log |awk '{FS="Local file"} {print $2}' |uniq  -c
      1 17:21:19.503]
     12  path is /home/admin/bpmclasses/

其次,通过查看BPM的代码,每次预编译的之后都会进行对象的缓存,不会每一个实例都创建一个新的对象:

bpm-dy-gen-class-cache

 

分析二:找出持续创建Class的因素
排查方法:
对于Perm区的OutOfMemory,常健的排查方法和解决方法有:
jvm-oom-perm-bixuan-any
jvm-perm-oom-bixuan-fix
jvm-perm-oom-bixuan-any-fix
下载btrace工具包并解压:
如果你通过 tar -zxvf btrace-bin.tar.gz 解压不开,通过 file  btrace-bin.tar.gz 查看文件的类型,很可能你下载的是一个html文本。
mkdir /home/admin/btrace
cd /home/admin/btrace
wget https://kenai.com/projects/btrace/downloads/download/releases/release-1.2.2/btrace-bin.tar.gz
tar -zxvf btrace-bin.tar.gz
如果你通过 tar -zxvf btrace-bin.tar.gz 解压不开,通过 file  btrace-bin.tar.gz 查看文件的类型,很可能你下载的是一个html文本。
下载解压后目录结构:
drwxr-xr-x 2 admin admin  4096 May 12 23:16 bin
drwxr-xr-x 2 admin admin  4096 May 12 22:38 build
-rw-r--r-- 1 admin admin  3352 May  9  2012 COPYRIGHT
drwxr-xr-x 3 admin admin  4096 May 12 22:38 docs
-rw-r--r-- 1 admin admin 19227 May  9  2012 LICENSE.txt
-rw-r--r-- 1 admin admin   154 May  9  2012 README.txt
drwxr-xr-x 2 admin admin  4096 May 12 22:38 samples
btrace 的使用方法:
[admin@vm47 /home/admin/btrace/bin]$sh btrace
Usage: btrace   
where possible options include:
  -classpath  Specify where to find user class files and annotation processors
  -cp         Specify where to find user class files and annotation processors
  -I          Specify where to find include files
  -p          Specify port to which the btrace agent listens for clients
常用的查看Java类加载的brace脚本BtraceAll.java文件:
import static com.sun.btrace.BTraceUtils.*;
import com.sun.btrace.annotations.*;
@BTrace
public class BtraceAll
 {
    @TLS
    private static long beginTime;
    @OnMethod(clazz="java.lang.ClassLoader",method="defineClass")
    public static void traceMethodBegin(){
        beginTime = timeMillis();
    }

    @OnMethod(
            clazz="java.lang.ClassLoader",
            method="defineClass",
            location=@Location(Kind.RETURN)
    )
    public static void traceMethdReturn(@Return String result, @ProbeClassName String clazzName,@ProbeMethodName String methodName){
        println("===========================================================================");
        println(strcat(strcat(clazzName, "."),methodName));
        println(strcat("Time taken : ",str(timeMillis() - beginTime)));
        println("java thread method trace:---------------------------------------------------");
        jstack();
        println("----------------------------------------------------------------------------");
        println(strcat("Reuslt :",str(result)));
        println("============================================================================");
    }
}
是遇到了JAVA_HOME的问题:Please set JAVA_HOME before running this script
[admin@vm47 /home/admin/btrace/bin]$sudo sh  btrace -cp /home/admin/btrace/build 39 /home/admin/btrace/bin/BtraceAll.java
Please set JAVA_HOME before running this script

 

设置JAVA_HOME:
export JAVA_HOME=/opt/haitao/java
但是不起作用,最后把 JAVA_HOME=/opt/haitao/java 加入到btrace脚本中起效。

又遇到了异常:Unable to open socket file: target process not responding or HotSpot VM not loaded

[admin@vm47 /home/admin/btrace/bin]$sudo sh  btrace  -cp /home/admin/btrace/build 39 /home/admin/btrace/bin/BtraceAll.java
Unable to open socket file: target process not responding or HotSpot VM not loaded
这个是在测试环境遇到的,也许更环境有关,在预发环境中没有提示此错误。
为了拿到更长时间的用户classload 加载的类信息,使用:
[admin@logistics2.hz /home/admin/btrace/bin]$sh  btrace  -cp /home/admin/btrace/build 24071 /home/admin/btrace/bin/BtraceAll.java >user-class-load.log &
[3] 9668
进行数据收集,等待第二天查看收集到的日志信息。
对收集到的类加载信息进行分类汇总:
grep -a "loaded" user-class-load.log  | awk '{FS="Reuslt :"} {print $2}' |sort |uniq -c > logistics-loadclass.log
打开logistics-loadclass.log 文件:
      3  ch.qos.logback.classic.spi.ClassPackagingData
      3  ch.qos.logback.classic.spi.PackagingDataCalculator
      3  ch.qos.logback.classic.spi.StackTraceElementProxy
      3  ch.qos.logback.classic.spi.STEUtil
      3  ch.qos.logback.classic.spi.ThrowableProxy
      3  ch.qos.logback.classic.spi.ThrowableProxyUtil
      3  ch.qos.logback.core.rolling.FixedWindowRollingPolicy$1
      3  ch.qos.logback.core.status.WarnStatus
      3  cn.gov.zjport.newyork.ws.bo.Body
      …….
从打印出来的class load信息中并没有发现什么异常的类加载信息,唯一看到的是JSON和Jaxb在序列化的时候对每一个属性都进行了一次class load操作。

 

Jvm在启动的时候并不是吧所有类都加载进来,而是使用时加载,所以在运行期会有很多类被加载进来。
查看服务的lib下的jar包总大小,为80M:
[admin@logistics2.hz /home/admin/logistics-service/deploy/lib]$du -h
80M     .
此时决定Dump JVM的Perm区进行分析:
[admin@logistics1.hz /home/admin/btrace/bin]$jmap -permstat 8784 > perm.log
Attaching to process ID 8784, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.71-b01
finding class loader instances ..done.
computing per loader stat ..done.
please wait.. computing liveness................
这里注意,是Dump Jvm的Perm区,而不是Dump整个Heap区
jmap -heap:format=d,file=dump.bin 8784  (dump heap)

但是生产环境一直有流量进来,所以dump perm数据的时候一直卡在了 computing liveness 这个过程中。后来找了一台流量比较小的机器进行perm dump,分析perm.log 文件:

logistics-perm-dump-file

 

发现大量通过sun/reflect/DelegatingClassLoader加载进来的类处于dead状态。

那DelegatingClassLoader是什么呢?

DelegatingClassLoader存在的原因:java的反射机制运行效率是比较低的,执行Method.invoke()或Constructor.newInstance()都是通过调用native方法完成的,JDK为了提高反射运行效率,引入了一个机制叫“Inflation”,它首先通过DelegatingClassLoader去加载字节码,再执行相关的逻辑,字节码会缓存起来,所以第一次有加载的成本比正常执行慢3-4倍,但是后面的执行会有20倍以上的性能提升,这样整体性能会有很大的提升。
    Inflation机制提高了反射的性能,但是对于重度使用反射的项目可能存在隐患,它带来了两个问题:(1)初次加载的性能损失;(2)动态加载的字节码导致PermGen持续增长;
按道理标记为dead的类应该在FGC的时候被回收掉,所以在系统Perm区缓慢从80M增长到120M的时候,人工触发了一次Full GC:
[admin@logistics1.hz /home/admin/]$jcmd 8784 GC.run
7215:

查看系统的Perm区使用监控:

jvm-perm-force-gc

可以看到,Perm区的使用从120M降到了83M左右,处于dead状态的class被GC进行了回收。

 

在分析此问题的时候,顺便把Jvm内存也Dump出来了,通过MAT分析工具,打开柱状图Histogram,按照class load排序(Group by class loader):
`logistics-jvm-histogram-group-by-classloader
除了系统class loader 和AppClassLoader、ExtClassLoad外,还有两种类型的ClassLoad:Fastjson引入的ASMClassLoad和反射机制引入的DelegatingClassLoader,这与Dump -permstat的数据基本吻合,因为class的元数据存储在perm区,所以这里看不到对象的深堆大小。

全文总结:

我们系统出现Perm区持续增长是正常现象,只是需要注意的是在FullGC的时候需要观察系统中Perm区的大小是否被回收,如果没有被回收,就存在严重问题。其次,在编码中也要对重度使用反射机制的服务进行特殊处理。

 

JMap遇到的问题
jmap -permstat xxx 时,出现了
[admin@logistics.hz /home/admin/btrace/bin]$jmap -permstat 8784 > perm.bin
Attaching to process ID 8784, please wait...
Error attaching to process: sun.jvm.hotspot.debugger.DebuggerException: Can't attach to the process
似乎线程都卡死了,系统没有任何日志输出。
首先第一反应是重启系统,让系统可以 正常工作,接下来是解决问题。
解决方法:
1. echo 0 | sudo tee /proc/sys/kernel/yama/ptrace_scope
该方法在下次重启前有效。
2. 永久有效方法
sudo vi /etc/sysctl.d/10-ptrace.conf
编辑下面这行:
kernel.yama.ptrace_scope = 1
修改为:
kernel.yama.ptrace_scope = 0
重启系统,使修改生效。
该bug详细信息请参考官方文档: http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=7050524

参考:

Advertisements

发表评论

Fill in your details below or click an icon to log in:

WordPress.com 徽标

You are commenting using your WordPress.com account. Log Out /  更改 )

Google photo

You are commenting using your Google account. Log Out /  更改 )

Twitter picture

You are commenting using your Twitter account. Log Out /  更改 )

Facebook photo

You are commenting using your Facebook account. Log Out /  更改 )

Connecting to %s