3年前 (2020-11-21)  jvm |   抢沙发  1147 
文章评分 0 次,平均分 0.0
[收起] 文章目录

我们将在GC日志中打印元空间的大小。假设我们设置了

-XX:MetaspaceSize=100M

-XX:MaxMetaspaceSize=100M

这意味着一旦metaspace的使用量达到100M就应该触发一个metaspace fulGC,但实际上我们从GC日志中发现了这个问题,metaspace只使用了70899KB。

[Full GC (Metadata GC Threshold) [PSYoungGen: 5092K->0K(132096K)] [ParOldGen: 85822K->60451K(181760K)] 90914K->60451K(313856K), [Metaspace: 70899K->70899K(1136640K)], 0.1482072 secs] [Times: user=0.52 sys=0.00, real=0.15 secs]

首先,让我们看看打印这行gc日志的代码,这实际上取决于metaspace使用的大小。

void MetaspaceAux::print_metaspace_change(size_t prev_metadata_used) {
  gclog_or_tty->print(", [Metaspace:");
  if (PrintGCDetails && Verbose) {
    gclog_or_tty->print(" "  SIZE_FORMAT
                        "->" SIZE_FORMAT
                        "("  SIZE_FORMAT ")",
                        prev_metadata_used,
                        used_bytes(),
                        reserved_bytes());
  } else {
    gclog_or_tty->print(" "  SIZE_FORMAT "K"
                        "->" SIZE_FORMAT "K"
                        "("  SIZE_FORMAT "K)",
                        prev_metadata_used/K,
                        used_bytes()/K,
                        reserved_bytes()/K);
  }

  gclog_or_tty->print("]");
}

但是,触发metaspace Full GC的基础不是基于metaspace的实际使用情况,而是基于提交的metaspace的内存大小。

size_t MetaspaceGC::allowed_expansion() {
  size_t committed_bytes = MetaspaceAux::committed_bytes();
  size_t capacity_until_gc = capacity_until_GC();

  assert(capacity_until_gc >= committed_bytes,
        err_msg("capacity_until_gc: " SIZE_FORMAT " < committed_bytes: " SIZE_FORMAT,
                capacity_until_gc, committed_bytes));

  size_t left_until_max  = MaxMetaspaceSize - committed_bytes;
  size_t left_until_GC = capacity_until_gc - committed_bytes;
  size_t left_to_commit = MIN2(left_until_GC, left_until_max);

  return left_to_commit / BytesPerWord;
}

显然,如果我们创建了很多类加载器,每个类加载器都将对应于一个元空间数据结构。我们的元空间的用法是指Metanchunk中的instance。内存大小已分配,但Metanchunk并没有全部用完。这个问题被简化了。就像CMS GC的碎片化一样,我们在提交的内存和使用的内存之间有一定的差距,触发metaspace FullGC是基于提交的内存大小,所以用户觉得metaspace没有达到我们的阈值触发Full GC,这似乎很可疑。

因此,我想提出一个小建议,对于全GC的场景,在打印metaspace的GC日志时,会更直接地打印提交内存大小而不是已用内存大小,这样可以让用户更清楚地看到,并且发现元空间的阈值已经达到了完全GC的触发器。

修改后的日志更明显,当到达100M时确实会触发,但它会带来另一个缺点,即我们不知道真正使用了多少元空间。

[Full GC (Metadata GC Threshold) [PSYoungGen: 5092K->0K(132096K)] [ParOldGen: 81395K->60429K(181248K)] 86488K->60429K(313344K), [Metaspace: 102400K->70599K(1136640K)], 0.1330421 secs] [Times: user=0.46 sys=0.00, real=0.13 secs]

这个问题会对各种GC策略产生一些影响,如下 metaspace gc 案例:

定位过程:

  1. 检查zabbix以查找FullGC时间点。
  2. 根据时间点搜索GC日志,找出GC的原因(GC case)-Xloggc:/dev/shm/gc20190226084714.log此启动参数指定GC日志存储位置
  3. 根据GC的原因,发现元空间的不断增长导致了完全GC。
2019-02-26T08:24:09.252+0800: 391942.779: [Full GC (Metadata GC Threshold) 2019-02-26T08:24:09.252+0800: 391942.779: [CMS: 361366K->361612K(10485760K), 1.1662525 secs] 609428K->361612K(16148096K), [Metaspace: 187649K->187649K(1572864K)], 1.1694997 secs] [Times: user=1.24 sys=0.00, real=1.17 secs]
2019-02-26T08:24:10.421+0800: 391943.948: [Full GC (Last ditch collection) 2019-02-26T08:24:10.422+0800: 391943.948: [CMS: 361612K->361518K(10485760K), 1.1508390 secs] 361612K->361518K(16148096K), [Metaspace: 187608K->187608K(1572864K)], 1.1540049 secs] [Times: user=1.16 sys=0.00, real=1.15 secs]
2019-02-26T08:24:11.576+0800: 391945.103: Total time for which application threads were stopped: 2.3287421 seconds, Stopping threads took: 0.0001573 seconds

向打印类加载添加JVM参数:

# Add parameters to the catalina.sh script and restart. After restart, view the class loading in the tomcat/logs/catalina.out file log

JAVA_OPTS="$JAVA_OPTS -XX:+TraceClassLoading -XX:+TraceClassUnloading"

4. 查看catalina.out日志中,我们发现大量重复的反射类加载:

[Loaded sun.reflect.GeneratedConstructorAccessor72 from __JVM_DefineClass__]
[Loaded sun.reflect.GeneratedConstructorAccessor73 from __JVM_DefineClass__]
[Loaded sun.reflect.GeneratedConstructorAccessor74 from __JVM_DefineClass__]
[Loaded sun.reflect.GeneratedConstructorAccessor75 from __JVM_DefineClass__]
[Loaded sun.reflect.GeneratedConstructorAccessor76 from __JVM_DefineClass__]
[Loaded sun.reflect.GeneratedConstructorAccessor77 from __JVM_DefineClass__]
[Loaded sun.reflect.GeneratedConstructorAccessor78 from __JVM_DefineClass__]
[Loaded sun.reflect.GeneratedConstructorAccessor79 from __JVM_DefineClass__]

5. 由于Spring框架的动态代理,加载的类是反射类。不确定类是否有重复加载。有必要查看特定的动态代理类或方法。

6. 手动编写类筛选器以在转储元空间中加载类文件。

1) 写入方法访问筛选器:

import sun.jvm.hotspot.oops.InstanceKlass;
import sun.jvm.hotspot.tools.jcore.ClassFilter;

public class MethodAccessorFilter implements ClassFilter {

    @Override
    public boolean canInclude(InstanceKlass instanceKlass) {
        String klassName = instanceKlass.getName().asString();
        
        // Sun/reflect/Delegating ClassLoader can be replaced by a package path or class that requires Dump
        return klassName.startsWith("sun/reflect/DelegatingClassLoader");
    }
}

2) 编译方法访问筛选器:

$ javac -classpath $JAVA_HOME/lib/sa-jdi.jar  MethodAccessorFilter.java

3) 转储指定的类或包:

$ java -classpath ".:$JAVA_HOME/lib/sa-jdi.jar" -Dsun.jvm.hotspot.tools.jcore.filter=MethodAccessorFilter sun.jvm.hotspot.tools.jcore.ClassDump 269932
# Note: dump output files are stored in the current directory, such as:. / sun / reflect / Delegating Class Loader XX. class 

4) 找到大量的重复类(很多是例外情况需要根据自己的项目情况和经验判断),反编译这个类的类文件。

$ javap -verbose GeneratedMethodAccessor99.class

# Find the exact location of invokevirtual

5) 查找反射调用的类构造或方法(以下是反射方法的示例):

find ./ -name "GeneratedMethodAccessor*" | xargs javap -verbose | grep "invokevirtual #10" | grep "com.pjbest" >> /tmp/invokevirtual.txt

7. 查看实际代理的方法或类,并结合代码进一步分析元空间持续增长的根本原因。

事故原因如下:

事故是由于MapperFactory使用不当造成的。在使用MapperFactory时,需要维护单例或直接使用静态方法:

具有元空间泄漏可能性的代码:

metaspace会gc吗

正确代码:

metaspace会gc吗

总结

元空间溢出有很多原因。本文以spring框架为例进行分析。需要了解类加载原理和spring动态代理机制,然后利用工具进行分析,最后用代码找出问题的根源。

 

除特别注明外,本站所有文章均为老K的Java博客原创,转载请注明出处来自https://javakk.com/854.html

关于

发表评论

表情 格式

暂无评论

登录

忘记密码 ?

切换登录

注册