分类 Troubleshooting 相关 下的文章

诊断由 modelmapper 导致的内存泄漏

发现一个 Java 应用 GC overhead 非常高, 查看 verbose GC log, 发现 heap 基本用完. 做了一个 heap dump, 发现其中一个 ClassLoader 管理着 327680 个类, 占用了 1.2G 的空间.

The classloader/component "org.springframework.boot.loader.LaunchedURLClassLoader @ 0x768800000" occupies 1,296,913,416 (77.87%) bytes. The memory is accumulated in one instance of "java.lang.Object[]" loaded by "<system class loader>".

仔细检查最新加入的这些类(一般Java 应用运行在稳定状态,很少有新的类被载入), 都有一些通用的模式:

  1. 类名类似于: com.tianxiaohui.MyClass$ByteBudddy$Ag2xax0, 前面的到 ByteBuddy 都是一样的, 后面全是类似 Hash 码的字符串, 看上去是一些代理子类;
  2. 类名类似于: org.modelmapper.internal.TypeMapImpl$Property@3f59d6c7, 都是基于 TypeMapImpl$Property的一些类.

通过以下 btrace 脚本, 在加入的 ClassLoader 的 classes 之前, 可以截获这些类, 并能查看到底哪个地方新加的这些类:

package test;

import static org.openjdk.btrace.core.BTraceUtils.println;

import org.openjdk.btrace.core.BTraceUtils;
import org.openjdk.btrace.core.BTraceUtils.Strings;
import org.openjdk.btrace.core.annotations.BTrace;
import org.openjdk.btrace.core.annotations.OnMethod;
import org.openjdk.btrace.core.annotations.ProbeClassName;
import org.openjdk.btrace.core.annotations.ProbeMethodName;

@BTrace
public class NewClassTracer {

    @OnMethod( clazz="/java\\.util\\.Vector/", method="/addElement/")
    public static void m(@ProbeClassName String probeClass, @ProbeMethodName String probeMethod, Object obj) {
            //print(Strings.strcat("entered ", probeClass));
            //println(Strings.strcat(".", probeMethod));
            println(Strings.strcat("new Class: ", Strings.str(obj)));
            BTraceUtils.jstack();
    }
}

通过上面的 btrace 脚本, 可以看到如下的 stacktrace:

java.util.Vector.addElement(Vector.java)
java.lang.ClassLoader.addClass(ClassLoader.java:263)
java.lang.ClassLoader.defineClass1(Native Method)
java.lang.ClassLoader.defineClass(ClassLoader.java:763)
sun.reflect.GeneratedMethodAccessor10.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
java.lang.reflect.Method.invoke(Method.java:498)
org.modelmapper.internal.bytebuddy.dynamic.loading.ClassInjector$UsingReflection$Dispatcher$Direct.defineClass(ClassInjector.java:604)
org.modelmapper.internal.bytebuddy.dynamic.loading.ClassInjector$UsingReflection.injectRaw(ClassInjector.java:235)
org.modelmapper.internal.bytebuddy.dynamic.loading.ClassInjector$AbstractBase.inject(ClassInjector.java:111)
org.modelmapper.internal.bytebuddy.dynamic.loading.ClassLoadingStrategy$Default$InjectionDispatcher.load(ClassLoadingStrategy.java:232)
org.modelmapper.internal.bytebuddy.dynamic.loading.ClassLoadingStrategy$Default.load(ClassLoadingStrategy.java:143)
org.modelmapper.internal.bytebuddy.dynamic.TypeResolutionStrategy$Passive.initialize(TypeResolutionStrategy.java:100)
org.modelmapper.internal.bytebuddy.dynamic.DynamicType$Default$Unloaded.load(DynamicType.java:5623)
org.modelmapper.internal.ProxyFactory.proxyFor(ProxyFactory.java:97)
org.modelmapper.internal.ProxyFactory.proxyFor(ProxyFactory.java:72)
org.modelmapper.internal.ReferenceMapExpressionImpl.map(ReferenceMapExpressionImpl.java:67)
org.modelmapper.internal.ConfigurableConditionExpressionImpl.map(ConfigurableConditionExpressionImpl.java:65)

那么诊断下来, 就是每次使用下面的代码的时候, 就创建一些新的类 (例子代码中 Man 和 Person 都是一个只有 name 字段的 POJO):

People p = new People();
p.setName("eric");

//type 1
ModelMapper modelMapper = new ModelMapper();
Man man = modelMapper.map(p, Man.class);
System.out.println(man);

//type 2
ModelMapper modelMapper2 = new ModelMapper();
modelMapper2.getConfiguration().setAmbiguityIgnored(true);

TypeMap<People, Man> typeMap = modelMapper2.createTypeMap(People.class, Man.class);
typeMap.addMappings(mapper -> {
    mapper.map(source -> source.getName(), Man::setName);
});

System.out.println(modelMapper2.map(p, Man.class));

原因在于每个 ModelMapper 实例都会管理自己的 Model, 每次都会创建一些新的类. 所以官方站点上明确说明:

Unless you need different mappings between the same types, then it’s
best to re-use the same ModelMapper instance.

一些其他人遇到类似的问题: https://github.com/modelmapper/modelmapper/issues/375

所以, 最好是这些 ModelMapper 都是 static final 的, 保证尽最大可能重用, 否则就会出现内存溢出问题.

确诊线程池没有 shutdown 引起的内存泄漏

遇到好几次 Java 应用程序因为不正确的使用线程池, 没有 shutdown 导致内存泄漏, 最终不断 GC, 引起 CPU 100% 的问题. 这里举个例子来说明如何确认这种问题.

首先, 如果不是有活动线程数量的时序数据(active thread number trend metrics), 很难一开始就发现这种问题, 一般都是到最后引起 GC overhead 或者 CPU 100%的时候, 才开始查起. 当然, 如果有持续的活动线程数量统计信息, 那么一开始就能看到应用的线程数量不断的增加, 这就是问题的体现(正常的应用程序活动线程数能保持在一个稳定状态).

当我们通过 GC overhead 或者 CPU 100% 最终确定线程数量增加引起的内存泄漏的时候, 我们就能发现原来是某些线程不断的被创建, 却没有销毁.
当我们通过活动线程数持续增加判断出来之后, 我们可以通过查看线程的 thread dump (jcmd <pid> Thread.print > /tmp/thread.log) 来查看不断增加的线程.

当我们确定是线程不断增加的问题之后, 那么就需要确诊到底是哪里不断的添加新线程? 这里, 我们可以使用 btrace (btrace <pid> <script_file>) 来打出创建线程的 stacktrace.

btrace script

package com.ilikecopy.btrace;

import org.openjdk.btrace.core.annotations.*;
import static org.openjdk.btrace.core.BTraceUtils.*;

@BTrace 
public class Trace {
    
    @OnMethod( clazz="/java\\.util\\.concurrent\\.Executors/", method="/.*/" )
    public static void createThreadPool(@ProbeClassName String probeClass, @ProbeMethodName String probeMethod) {
        print(Strings.strcat("trace ... entered ", probeClass));
        println(Strings.strcat(".", probeMethod));
        println(jstackStr());
    }
    
    @OnMethod( clazz="/java\\.lang\\.Thread/", method="/init/" )
    public static void createThread(@ProbeClassName String probeClass, @ProbeMethodName String probeMethod) {
        print(Strings.strcat("trace ... entered ", probeClass));
        println(Strings.strcat(".", probeMethod));
        println(jstackStr());
    }
}

-------------------- 例子 --------------------
今天遇到的问题: 不断的看到线程在增加, 且线程名字的模式是: pool-xxx-thread-1. 这个很明显是使用只有一个线程的线程池, 不断的创建新的线程池, 忘记的 shutdown 导致的问题. 使用上面的脚步就很容易确认是哪里创建了这个线程池.

一个Java类怎么算被加载成功

在之前的一个问题中 (一次诊断 org.xerial.snappy.Snappy NoClassDefFoundError), 我们看到 Snappy 这个类并没有被 ClassLoader 加载成功, 原因是它要加载 native 代码, 可是由于 /tmp 目录挂载方式的问题, 导致 Snappy 的静态块部分抛出了 Error, 最终没有加载成功. 如果要本地重现的话, 可以通过单步调试(debug)的方式, 把它正常写入本地临时目录的文件中途删掉, 那么同样可以达到让它无法加载成功的目的.

这里困扰我的问题是, 虽然不能加载成功, 可是我们在 heap dump 中已经可以看到这个类, 只不过按照正常初始化应该完成初始化的 impl 字段在 heap dump 中是空值. 如下图:
heap.png

同时, 从 ClassLoader 的 parallelLockMap 中, 也能发现这个类已经在列表中.

正常情况下, 如果一个类的的静态块出错(跑出异常), 并且它有 try {} catch{} 并且 catch 部分捕获异常的话, 应该算正常执行完了静态块. 可是在这里例子中, 静态块跑了 Error, catch 部分没有捕获 Throwable 或 Error, 所以应该属于非正常退出静态块, 所以这里是该类未正常完成初始化.

所以在哪个测试的例子中, 第一次尝试使用 Snappy 类的时候, 并没有发生重新加载该类的行为, 直接跑出了异常:

Exception in thread "main" java.lang.NoClassDefFoundError: Could not initialize class org.xerial.snappy.Snappy at SnappyTest.main(SnappyTest.java:13)

那么 JVM 到底在哪里记录某个类是不是被正常初始化了呢? 第二次是如何快速的就跑出了NoClassDefFoundError 呢?
在 openJDK 源码里 instanceKlass.cpp 中, 我们发现了对应的代码.
http://hg.openjdk.java.net/jdk/jdk/file/tip/src/hotspot/share/oops/instanceKlass.cpp#l1038

在第5步中, 它判断是不是在 error 状态 (is_in_error_state), 如果是在 error 状态, 那么就抛出了上面的异常.

在这个源代码 instanceKlass.hpp 中, 我们看到了有个初始化状态字段: _init_state, 它有几个状态:

enum ClassState {
    allocated,              // allocated (but not yet linked)
    loaded,                 // loaded and inserted in class hierarchy (but not linked yet)
    linked,                 // successfully linked/verified (but not initialized yet)
    being_initialized,      // currently running class initializer
    fully_initialized,      // initialized (successfull final state)
    initialization_error    // error happened during initialization
  };

所以, 可以看到, 它在 Load, Link, Initialize 每一步都会记录状态, 如果出错, 都会有相应的处理. 至于对于什么错误, 怎么处理, 还是要继续看 instanceKlass.cpp 的源码. 但是这部分的数据结构是不一定在 heap 里面, 所以不一定能在 heap 看到(我没有确认).

什么情况下 Java 会卸载一个类 (unload class)

最近遇到一个线上问题, 一个 Java web 应用在运行一段时间(几个小时或几天)后, 会抛出 NoClassDefFoundError. 该应用使用的是 Akka 框架, 并且开启了参数: akka.jvm-exit-on-fatal-error. 所以, 当 Akka 捕获这个 NoClassDefFoundError 后, 直接就发生了重启 JVM 的操作.

2020-04-22 01:11:39,369 ERROR [squbs-akka.actor.default-dispatcher-5] ActorSystemImpl ActorSystem(squbs) Uncaught error from thread [squbs-cal-publishing-dispatcher-18326] shutting down JVM since 'akka.jvm-exit-on-fatal-error' is enabled
java.lang.NoClassDefFoundError: Could not initialize class org.xerial.snappy.Snappy

这里使用 Snappy 这个类的代码是一个非常普遍, 经常使用的代码, 所以一开始怀疑 Snappy 这个类一开始是被正常加载且正常使用的. 之后, 某个时间点这个 Snappy 类由于某种原因被卸载了(unload), 当然最终这个怀疑是不正确的. 不过这里就引发了一个思考, 到底什么情况下一个 Java 类会被卸载 (unload)?

根据 The Java® Language Specification Java+SE 8 Edition 的说法, 只有当下面的情况下, 一个 Class 才有可能被卸载:

只有当加载该类的 ClassLoader 被卸载的情况下, 该类才有可能被卸载.

这里的前提条件是: 该类没有任何实例, 没有任何被任何类, 接口, 对象引用, 加载该类的 ClassLoader 也满足可以被卸载的前提下, 该类才有可能被卸载.

一次诊断 org.xerial.snappy.Snappy NoClassDefFoundError

某一天, 发现有些 Java web 应用突然自己重启, 有些时候重启完不能正常工作. 查看应用日志, 发现日志中出现下面的错误:

2020-04-22 01:11:39,369 ERROR [squbs-akka.actor.default-dispatcher-5] ActorSystemImpl ActorSystem(squbs) Uncaught error from thread [squbs-cal-publishing-dispatcher-18326] shutting down JVM since 'akka.jvm-exit-on-fatal-error' is enabled
java.lang.NoClassDefFoundError: Could not initialize class org.xerial.snappy.Snappy
    at com.tianxiaohui.java.BufferedWriteChannel.flush(BufferedWriteChannel.java:264)

从上面日志可以看出, 这个应用使用的是 Squbs 框架, 它其实是封装的 Akka. 当 Akka 遇到严重的出错(这里是 NoClassDefFoundError)时, 如果还设置了 "akka.jvm-exit-on-fatal-error" 选项, 那么就会迫使 JVM 系统就会自动重启.

那么问题是: 为什么这个类定义不能被找到呢?
首先, 我们查看了这个 snappy-java.xxx.jar 是在该应用的 classpath 的; 同时, 该应用在发生第一次自重启之前已经运行了一段时间.

仔细查看这个 Snappy.java 类, 就会发现其实它就是一个不做任何事情的 Java 代理类, 它的所有功能都是 native 代码实现的. 所以, 它的方法都是 static 方法. 关键的是, 它有一段静态块 (static block) 代码, 这个代码初始化 native 相关的功能实现. 也就是说, 如果这段静态块无法完成, 就会导致该类无法初始化完成, 导致 NoClassDefFoundError.

Snappy.png

虽然这段静态块包装了原始异常 (Exception), 并且抛出新异常, 可是在我们日志中, 并没有发现有关的信息. 为了搞清楚这里的具体出错, 我们做了如下测试代码:

import org.xerial.snappy.Snappy;

public class SnappyTest {
    public static void main(String[] args) {
        System.out.println("before ");
        try {
            Snappy.maxCompressedLength(4);
        } catch (Throwable t) {
            System.out.print(t.getClass());
            t.printStackTrace();
        }
        System.out.println("middle ");
        try {
            Snappy.maxCompressedLength(4);
        } catch (Exception t) {
            t.printStackTrace();
        }
        System.out.println("after ");
    }
}

测试结果:

java -cp snappy-java-1.1.0.jar:. SnappyTest
before
java.lang.UnsatisfiedLinkError: /tmp/snappy-1.1.0-cc87f5bb-c0a2-483b-9aed-1bf409ab2b94-libsnappyjava.so: /tmp/snappy-1.1.0-cc87f5bb-c0a2-483b-9aed-1bf409ab2b94-libsnappyjava.so: failed to map segment from shared object
                at java.lang.ClassLoader$NativeLibrary.load(Native Method)
                at java.lang.ClassLoader.loadLibrary0(ClassLoader.java:1941)
                at java.lang.ClassLoader.loadLibrary(ClassLoader.java:1824)
                at java.lang.Runtime.load0(Runtime.java:809)
                at java.lang.System.load(System.java:1086)
                at org.xerial.snappy.SnappyLoader.loadNativeLibrary(SnappyLoader.java:166)
                at org.xerial.snappy.SnappyLoader.load(SnappyLoader.java:145)
                at org.xerial.snappy.Snappy.<clinit>(Snappy.java:47)
                at SnappyTest.main(SnappyTest.java:7)
middle
Exception in thread "main" java.lang.NoClassDefFoundError: Could not initialize class org.xerial.snappy.Snappy at SnappyTest.main(SnappyTest.java:13)
end 

从上面的测试可以看出, 当加载该类的时候, ClassLoader 抛出了 UnsatisfiedLinkError, 这是一个 Error 类型, 导致Akka 重启 JVM.

另外从 heap dump 我们可以看到, 虽然该类没有加载成功, 但是这个类以及在内存中, 只不过必要的字段应该有值, 不过现在是空.
SnappyDebug.png

从上面的截图中看到 impl 这个本应该在静态块中初始化的值 现在却是空值. 另外, 我加了 2 个 Throwable 的字段用来存放内部抛出的异常, 和当前新建的异常. 并且之前抛出的异常部分要把原来代码的 Exception 改为 Throwable, 否则无法捕获.

另外从 heap dump 中的 SnappyLoader 的文件字段, 可以看到具体的文件存在什么地方. 我们出问题的文件就是上面日志中提到的:
/tmp/snappy-1.1.0-cc87f5bb-c0a2-483b-9aed-1bf409ab2b94-libsnappyjava.so

去查看这个文件, 发现文件缺失存在的, 进一步检查, 发现问题出在 /tmp 目录的挂载上面(mount).

:~$ mount | grep /tmp
tmpfs on /tmp type tmpfs (rw,nosuid,nodev,noexec)
:~$ sudo mount -o remount,rw,nosuid,nodev tmpfs  /tmp
:~$ mount | grep /tmp
tmpfs on /tmp type tmpfs (rw,nosuid,nodev)

通过上面的查看和修复可以看到, 一开始挂载的 /tmp 目录包含有 noexec 属性, 重新挂载, 去掉这个属性, 一切就回复正常了.