遇到好几次 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 导致的问题. 使用上面的脚步就很容易确认是哪里创建了这个线程池.

公司的 web 应用基础框架几年前升级到 Java 8 之后, 很多开发人员很开心地使用起了很多 Java 8 提供的API新功能. 可是也遇到了不少问题. 其中一个便是使用非常广泛的 Iterable 的 forEach(Consumer<? super T> action) API.

在 Java 8 之前, 我们通常这样循环遍历一个可以 iterable 的对象:

    public void oldWay() {
        List<String> lines = Arrays.asList("test");
        
        Iterator<String> iterator = lines.iterator();
        while (iterator.hasNext()) {
            //do something
            System.out.println(iterator.next());
        }
        
        for (String line : lines) {
            //do something
            System.out.println(line);
        }
    }

使用 Java 8 的 forEach() API 我们可以这么遍历对象

    public void newWay() {
        List<String> lines = Arrays.asList("test");
        
        lines.forEach(new Consumer<String>() {
            @Override
            public void accept(String line) {
                //do something
                System.out.println(line);
            }
        });
        
        // or use Lambda
        lines.forEach(line -> {
            //do something
            System.out.println(line);
        });
        
        // or just println
        lines.forEach(System.out::println);
    }

那么这个新的 API 到底有什么好处呢?

1. 这个简洁的语法, 深受一些熟悉 JavaScript/Node.js 或者 其它脚本语言的开发者欢迎, 看上去简洁;
2. 能够使用一些并行流的 API, 省去了自己维护 ExecutorService 的开销;

不过从实际应用来看, 遇到的问题更多.

1. 无法抛出 checked exception, 从 Consumer 的 accept 方法可以看到, 它没有声明任何异常, 所以一旦里面执行的代码中需要跑出 checked exception, 直接无法使用这个 API;
2. 无法中途退出. 如果我们执行一个10000次的循环, 如果其中某次出错, 我们不想执行后面的, 可是 forEach 无法做到; 无法像一般的 loop 一样使用 continue, return 等关键字达到的效果.
3. forEach 里面必须使用外层传入的 final 变量. 那么一旦是 final, 内层则无法直接赋值. 除非使用 container 类(如 一个对象的属性, map, list 等), 可以把值传出.

    public void newWayMustFinal () {
        List<String> lines = Arrays.asList("test");
        
        final Object finalTmp = "test";
        Object tmp = null;
        lines.forEach(line -> {
            //do something
            if (finalTmp.equals(line)) {
                System.out.println(line);
                
                //tmp = line; // can not do this, as it is not final
            }
        });
    }

1. 对于一般的 for loop, JVM 是可以进行优化的, 比如 for 循环有10000次, JVM 可以每次做100次, 这些 CPU 在某些指令( fetch, load, save) 等操作上可以实现流水线; forEach 暂时无法使用这些优化;
2. 可读性差. 除了读 lambda 表达式感觉不直接, 另外读 stack 也不直接, 比如下面的 stack:

java.lang.Exception: Stack trace
    at java.lang.Thread.dumpStack(Thread.java:1336)
    at com.ilikecopy.basic.IterableForEach.lambda$0(IterableForEach.java:46)
    at java.util.Arrays$ArrayList.forEach(Arrays.java:3880)
    at com.ilikecopy.basic.IterableForEach.newWay(IterableForEach.java:43)
    at com.ilikecopy.basic.IterableForEach.main(IterableForEach.java:12)

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

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

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

某一天, 发现有些 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.

虽然这段静态块包装了原始异常 (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 我们可以看到, 虽然该类没有加载成功, 但是这个类以及在内存中, 只不过必要的字段应该有值, 不过现在是空.

从上面的截图中看到 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 属性, 重新挂载, 去掉这个属性, 一切就回复正常了.