分类 Troubleshooting 相关 下的文章

诊断由 Apache HttpAsyncClient 引起的内存泄漏

异步 IO 的使用, 使得线程不再 block 在 IO 上面, 可以做更多的事情, 所以 Java 的 NIO 在很多地方都使用起来了. 同时由于微服务的广泛普及, 企业内部各种服务直接的相互调用更多了. 之前很多都是使用 Apache 社区的 HttpClient 来相互调用, 如今更多的代码转向了 HttpAsyncClient. 这里就记录一个由于 HttpAsyncClient 的错误使用引起的内存泄漏的案例.

- 阅读剩余部分 -

诊断由 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 也满足可以被卸载的前提下, 该类才有可能被卸载.