Eric 发布的文章

为什么Java CMS GC 使用单线程做 Full GC?

虽然今天 CMS GC 已经不被推荐, 可是还经常被用来和G1 GC 做对比. 其中导致CMS 不被推荐的重要原因是: CMS 的full GC 是单线程的, 在如今多核统治天下的情况下, 单线程的 full GC 肯定比多线程的 full GC 慢很多.

CMS 什么情况下会产生full GC

  1. 并发模式失败(concurrent mode failures) 老年代并发回收的速度跟不上年轻代晋升的速度;
  2. 碎片化, 老年代虽然有足够的空间, 可是都是碎片化的, 没有一个连续的可容纳的空间;
  3. 元数据区(metaspace)/老年代没有空间;
  4. 明确的 System.gc() 或 Runtime.gc() 调用

为什么不把 parallel old 的算法引入CMS, 使之可以多线程

二者的数据结构不一样, 如果引入需要大量修改

为什么不重新为了 CMS 写一个多线程的 full gc?

据说开发工程师把更多的时间都用去写 G1 了, 并且 G1 各方面的期望都比CMS 好, 没有必要再写要给给CMS.

其它

google 内部有一个CMS 的老年代GC 实现, 并且曾经尝试patch到openJDK, 不过最后没有做到:
http://openjdk.java.net/jeps/8130200

最好还是用G1

记录一次奇怪的 CPU profiling 问题

本文记录了一次奇怪的线上线程相关问题的案例.

  1. 先是看到 CPU 稍微有点高
    cpu.png
  2. 大概看了下, 发现这个机器没做啥耗 CPU 的操作, 大多数都是网络请求, 于是做 CPU profiling, 于是出现了下面奇怪的方法调用
    sched_yield.png
    首先, 看上去这个不像 Java 的方法, 于是推断是 JVM 里面调用的系统 native 方法. 其次, 去 google 了一把, 这是系统的一个方法, 它的意图就是让出 CPU, 让其它 CPU 去执行. 可是为什么要频繁让出呢? 为什么占用这么多 CPU 资源呢? 另外, 搜了一下有没有人遇到过类似问题, 并没有发现.
  3. 是不是 Native 代码调用, 那些 native 代码调用了它? 于是从系统层面针对这个 Java 进程的这个方法调用, 又专门做了一次 CPU profiling, 看到下面的火焰图:
    native.png
  4. 从上的火焰图看, 貌似有个叫 WrapperJarAppMa 的方法调用了 __sched_yield 方法. 于是去 google 了一下这个关键字, 相当失望:
    google.png
    不过注意 google 给的提示! 后面再说.
  5. 正常的推理已经不能解决问题, 于是开始归纳总结. 发现如下模式:

    1. 这个应用分配了 174G 内存, 分配了 24 个 CPU, 资源相当丰富
      cpuMem.png
    2. 这个应用的 heap 给了 154G, heap 常规占用在 75G 左右, 空闲也非常多;
    3. 这个应用占用这么多 heap 是因为内存加载了非常多的缓存, 系统启动就加载, 加载完要十几分钟, 然后再接收流量;
      可是从上面的这些模式, 并么有推断出什么.
  6. 于是又回到已知的关键字 "__sched_yeild" 和 "WrapperJarAppMa". 想到 AsyncProfiler 其实可以根据线程做火焰图, 于是又根据线程做了火焰图, 看到如下:
    flameWithThread.png
    两边都是业务线程, 中间只有 2 层方法的都是我们看到的上面 "WrapperJarAppMa" 调用 "__sched_yeild", 所以, 中间从下数第二层红色的都是"WrapperJarAppMa", 第三层都是"__sched_yeild". 虽然这次也只能看到上面已经看到的 2 个关键字, 可是从于业务线程对比, 可以明显看出来: "WrapperJarAppMa" 是线程名字, 因为绿色的业务线程那边, 第二层也是线程名字.
  7. 于是通过 pstree 去查看线程的结构关系, 发现确实如此:
    wrappThread.png
  8. 可是代码里面从来没有看到这个线程的关键字, 这个线程从那里来的? 为什么这么多? 于是打算到 log 文件里面查一吧, 确实发现了这个线程(原来真正的线程名字叫 "WrapperJarAppMain" 其它地方只是字长的省略):
    log.png
  9. 这个时候在拿这个线程名字去 google, 就发现了线程出处, 原来在我们付费使用的商业软件 Java Service Wrapper 里面. 因为是付费软件, 在 maven 里面没有发现它的踪影, 于是从生产环境下载一个正在使用的 wrapper.jar. 反编译后重要找到了这个线程的出处:
    wrapperJarApp.png
  10. 为什么会有这么多 "WrapperJarAppMa" 线程一直存活, 并且一直 sched_yeild 呢? 想看看这些线程到底在做什么? 是不是在上面的 while 循环里面出不来了? 于是做了一个 54G 的 heap dump, 然后压缩到38G 下载到本地去做 heap 分析, 竟然没有看到这些线程:
    wrapperThreadHeap.png
  11. 于是怀疑在做 heap dump 过程中这些线程已经死掉了, 于是重新去查看了这些线程, 发现线程还好好的活着:
    threadAgain.png
  12. 这次还注意到, 在 heap dump 里面线程共计277个, 可是使用 pstree 能看到383个, 考虑到系统正在运行中, 有好多线程可能在变动中, 但是也不能差别这么多. 仔细观察, 发现类似这样的线程都没有出现在 heap dump 中
    g1.png
  13. 类似这样的线程有:

    1. {C2 CompilerThre}(123318)
    2. {G1 Main Marker}(123296)
    3. {G1 Marker#X}(123297)
    4. {G1 Refine#XX}(123295)
    5. {GC Thread#XX}(123247)
    6. {VM Periodic Tas}(123322)
    7. {VM Thread}(123313)
    8. {WrapperJarAppMa}(130114)
    9. {default-microme}(123384)
    10. {java}(123246)
  14. 可以看到这些线程的数量也不少:
    total.png
  15. 在生产环境看到这个问题之后, 去测试环境看了一下, 有如下总结:

    1. 测试环境在 CPU profiling 中并没有看到 __sched_yeild 被调用;
    2. 测试环境 也有 WrapperJarAppMa 线程;
    3. WrapperJarAppMa 总数与当前物理机的 CPU 合数一致, 除了一个正常结束的 WrapperJarAppMa 线程, 剩下 (CPU 核总数 - 1) 个这样的线程;
    4. 这些后来不死的线程, 在 heap 中看不到, 类似JDK 某些自带的线程;
    5. 这些线程的名字完全复制第一个线程的名字, 可是看不到创建的地方.
  16. 改动 WrapperJarApp 的源码, 在生产新线程的地方加了日志, 改了线程的名字, 发现日志中该方法只有一次被调用

    long i = System.currentTimeMillis() % 10;
    Thread mainThread = new Thread(this, i + "-WrapperJarAM");
    Thread.dumpStack();
  17. 如今的问题:

    1. 这些后来是怎么创建出来的?
    2. 为什么生产环境他们一直在运行, 可是在测试环境 profiling 中看不到运行;
    3. 另外发现 Wrapper-Connection 线程的优先级是 10, 怀疑这些不死的线程优先级也是 10
  18. 终于看到这些线程在干嘛

    1. 怀疑这些线程不是 Java 代码创建 (拦截Thread.start() 不到, 并且没有出现在 thread dump), 于是做了一个 core dump;
    2. 使用 gdb 从 core dump 可以看到线程正在运行的栈
      coreBt.png
    3. 果然在对应的目录找到了对应的共享库文件, 于是去查该项目的git 工程, 也找到了对应的共享库;
  19. 找到调用 JNI 共享库的代码 - 从项目源代码中找到了相应的代码, 如下:

    private static final String PATH = "/home/supra/work/test/blas/netlib-blas-dist/src/main/resources/linux-x86_64";
    private static final String[] NETLIB_LIBS = {
              "libquadmath.so.0", "libgfortran.so.3", "libopenblas.so.0", "libblas.so.3", "liblapack.so.3" };
    
    public static void main(String[] args) throws IOException {
      for (String lib : NETLIB_LIBS) {
        System.load(new File(PATH + "/" + lib).getAbsolutePath());
        NativeLibrary.getInstance(lib);
      }
    
      NativeSystemBLAS blas = new NativeSystemBLAS();
      double prod = blas.ddot(4, new double[] { 1.0, 1.0, 1.0, 1.0 }, 1, new double[] { 1.0, 0.0, 1.0, 0.0 }, 1);
      if (prod != 2.0) {
        throw new IllegalArgumentException("BLAS sanity test failed. Expected 2.0. Got: " + prod);
      }
    
      System.out.println("done");
      try {
        Thread.currentThread().sleep(1000000);
      } catch (InterruptedException e) {
        e.printStackTrace();
      }
    }
  20. 为什么会创建 (cpu count - 1) 个线程?

    1. 我们找到了这个共享库的源码, 结合 core dump 中看到的栈, 找出了创建这些线程的源代码行. 这里使用了 CPU 个数去创建 blas server 的服务线程数.
      https://github.com/xianyi/OpenBLAS/blob/974acb39ff86121a5a94be4853f58bd728b56b81/driver/others/blas_server.c#L639
    2. 下面的 blas_thread_server 方法就是 blas server 要执行的 routine. 我们通过 gdb 看到的代码, 就是这个里面的代码
  21. 为了进一步验证我们的想法, 下载了 https://github.com/xianyi/OpenBLAS 的代码, 在本地 Linux 上面重新编译包含符号的共享库, 这次, 我们看到这些线程在哪行代码运行:
    bt_thread.png

到此为止, 我们终于搞明白了这些线程哪来的?这些线程数目和 CPU 个数的关系. 其它一些相关的话题:

  1. blas 和 openBlas 应该是人工智能相关的算法类库;
  2. 其实 WrapperJarApp 里面设置的线程优先级在 Linux 上面其实没啥用.
  3. C 代码 (通过 pthread_create 创建的线程, 在Java 的 thread dump 看不到)

如何从 mysql 数据库恢复删除的 grafana dashboard

上周整理某个grafana文件夹下的 dashboard 的时候, 看到一个 dashboard 的名字叫 XXX-copy, 觉得这个太无趣, 可能是一个临时 copy 的 dashboard, 立马起了杀意, 直接删除. 这周到公司, 直接有人说我删除了他辛辛苦苦已经加工了半个月的 dashboard. 我无语. 想该怎么恢复.

google 了一下, UI 上无法恢复已经删除的 dashboard. 我们的 Grafana 没有用默认的 sqlite3, 而是使用 msyql, 并且是 DBA 专业30年维护. 于是找到 DBA 要了一个删除之前的那天的数据库 snapshot. 这个 snapshot 是一个 sql 文件. 压缩后300多M, 解压后2.5G.

于是拿到这个数据库 snapshot, 先解压, 然后通过 docker 安装一个 msyql, 导入数据, 然后再安装一个 grafana, 然后导出dashboard 数据, 再导入正在使用的grafana, 问题解决. 下面是具体步骤(前提本地有安装好的 docker)

  1. 安装 mysql

    $ docker run -itd --name mysql -p 3306:3306 -e MYSQL_ROOT_PASSWORD=123456 mysql
  2. 复制 数据文件到 mysql container (ec2c00bc4837 是 上面 mysql 的 container id [docker ps])

    $ docker cp ~/Downloads/grafana.sql ec2c00bc4837:/
  3. 进入 mysql container 导入数据

    $ docker exec -it ec2c00bc4837 /bin/bash
    # /usr/bin/mysql -u root -p > /grafana.sql
  4. 本地定制 grafana 的配置文件 custom.ini, 只要修改 defaults.ini 的 database 部分, 具体参考这里: https://grafana.com/docs/grafana/latest/administration/configuration/

    [database]
    type = mysql
    host = mysql
    name = mygrafanaDB
    user = root
    password = 123456
  5. docker 安装 grafana 使用定制配置文件

    $ docker run --link mysql -d --name grafana -p 3000:3000 -v                 ~/Downloads/custom.ini:/etc/grafana/grafana.ini  grafana/grafana

现在就可以等你的 grafana 了 http://localhost:3000/

另外如果你发现你需要某些特定的用户名/密码才能改这个页面, 研究下数据库里的这3个表:
dashboard
dashboard_acl
user

JDBC 无法建立到 Oracle 数据库的连接

A 程序使用和 B 程序一样的数据库访问用户名, 密码, 主机名, 端口等配置, 可是 A 程序无法建立到数据库的连接, B 程序却可以.

A 程序的代码在建立连接的时候, 只是打印了一句: 无法建立连接, 再也没任其它信息.

首先, 怀疑是不是防火墙问题 -> 使用 telnet 和 curl 测试了一下端口, 发现端口完全可以建立正常的 tcp 连接;

虽然可以建立 tcp 连接, 可是并不一定不是防火墙问题, 因为防火墙可能根据协议规则等建立, 允许基本的 tcp 端口连接;

下一步, 在建立连接的时候, 进行 tcp 抓包, 重要找到了问题所在: 原来在建立连接之后的协商阶段, 发生了错误->

...AUTH_PID...1234....AUTH_SID.  /ORA-28040: No matching authentication protocol

原来是认证协议不匹配, 还给出了 Oracle 官方的错误 ID.

根据这个错误 ID, 我们搜索一下, 发现基本是客户端JDBC 版本和服务器版本不一致造成的.

最近Oracle 服务器升级到 19c, 可是客户端还是用的适配 11c 的 JDBC 连接, 所以导致出现了这个错误.

为什么程序 B 没问题呢? 程序 B 使用的是 JDK 8, 它的 jdbc 驱动也升级了, 所以完全没问题. 然而程序 A 是一个基于 JDK 7 的程序, 它无法升级到最新的 JDBC 驱动, 因为 Oracle 最新的 JDBC 驱动只支持最低 JDK 8.

所以, 为了解决这个问题, 程序 A 应该升级 JDK 最低为 JDK8.

Java ForkJoinPool 的 worker thread 是如何自我终止的?

最近研究一个 Java 应用程序的性能问题, 当观察该应用程序的线程的时候, 发现有很多 ForkJoinPool 的 worker 线程, 这种线程数量很大, 并从线程的编号来看, 该应用创建了非常多的这样线程, 然后它们又逐渐被销毁.

下面是一个 Thread dump 的截图, 从截图中可以看到, 这种线程基本处于 2 种状态: TERMINATED 和 TIMED_WAITING. 理论来讲, 应该还有 Runnable 状态的, 只是没有出现在我们的 thread dump 中.
bad_method.png

通过 Btrace 代码注入, 我们很容易找到了错误使用线程池的代码:
forkJoin.png

这段代码在一个 Stream 的代码块中, 使用 Executors.newWorkStealingPool() 创建了一个 ForkJoinPool. 意味着每次调用这个方法, 都要创建一个新的 ForkJoinPool. 然而这正是线程池本来设计要解决的问题: 不要重复创建线程, 要复用.

所以, 解决办法就是替换这个线程池的创建和使用方式, 使用应用生命周期内复用线程的方法.

虽然上面的问题解决了, 那么还有个疑惑的地方: 我们看到上面线程池的编号是一个非常大的数字, 说明它已经被创建了这么多线程池了, 可是我们现在活着的总的线程数才几千, 说明早期创建的线程池都已经消亡了. 从那些 worker 的状态: TERMINATED 来看, 这些线程正在死亡, 最终线程池也会消亡.

一般情况下, 想让一个线程池终止, 我们都是通过调用线程池的 shutdown() 方法或者 shutdownNow() 方法. 可是我们观察上面线程池创建的地方, 并没有任何对象引用这个线程池, 那么是哪里调用这个 shutdown() 或者 shutdownNow() 方法的呢? 看上去这是一个矛盾的问题: 没用人调用 shutdown() 或者 shutdownNow(), 但是这些智能的 worker 线程却在慢慢消亡.

为了查清 worker 线程智能消亡的问题, 我们写了如下的 Btrace 代码来查找 worker 线程消亡的原因:

import static org.openjdk.btrace.core.BTraceUtils.jstackStr;
import static org.openjdk.btrace.core.BTraceUtils.println;
import org.openjdk.btrace.core.annotations.BTrace;
import org.openjdk.btrace.core.annotations.OnMethod;

@BTrace 
public class ForkJoinPoolTrace {

    /**
     * 用来查找那里创建了 ForkJoinPool
    @OnMethod( clazz="/java\\.util\\.concurrent\\.ForkJoinPool/", method="/<init>/" )
    public static void createPool() {
        println(jstackStr());
    }**/
    
    @OnMethod( clazz="/java\\.util\\.concurrent\\.ForkJoinPool/", method="/shutdown/" )
    public static void shutdownPool() {
        println(jstackStr());
    }
    
    @OnMethod( clazz="/java\\.util\\.concurrent\\.ForkJoinPool/", method="/tryTerminate/" )
    public static void tryTerminate() {
        println(jstackStr());
    }
    
    @OnMethod( clazz="/java\\.util\\.concurrent\\.ForkJoinPool/", method="/shutdownNow/" )
    public static void shutdownPoolNow() {
        println(jstackStr());
    } 
}

最终找到了让 worker 线程消亡的原因: 是在 awaitWorker() 方法中使用了 tryTerminate() 方法.

java.util.concurrent.ForkJoinPool.tryTerminate(ForkJoinPool.java)
java.util.concurrent.ForkJoinPool.awaitWork(ForkJoinPool.java:1807)
java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1693)
java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:175)

其实终止的原因就是: 如果 worker 线程发现很久没有活可以干, 那么就 自我终止吧.
ForkJoinPool.awaitWork 方法:
whyT.png

可能有人会问, 线程消亡了, 那么创建的那些 ForkJoinPool 呢? 这些对象要靠 Thread 活着, 如果那些 Worker Thread 都终止了, 那么这些对象必然会被回收掉.