分类 Troubleshooting 相关 下的文章

Apache HttpClient 连接池泄漏诊断思路

经常在线上看到一些应用直接因为连接池无法获得连接, 导致整个应用不在响应任何请求. 常见的有数据库连接池连接泄漏, Http 连接池泄漏. 对于这种连接泄漏的问题, 一般是应用没有考虑到某些特殊情况, 特殊异常的处理导致不能用完之后返回连接到连接池. 这里就针对 Apache HttpClient 连接池泄漏这种清楚, 分析一下基本的求解思路.

- 阅读剩余部分 -

诊断由 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 看到(我没有确认).