分类 默认分类 下的文章

记录一次奇怪的 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 文件里面查一吧, 确实发现了这个线程:
    log.png
    原来真正的线程名字叫 "WrapperJarAppMain" 其它地方只是字长的省略.
  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

类似这样的线程有:

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)

可以看到这些线程的数量也不少:
total.png

  1. 列表项目

-- 未完待续 --

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 都终止了, 那么这些对象必然会被回收掉.

gdb python debug

如果是 python 2.7

  1. 先安装 gdb 和 python2.7 debug package
    sudo apt-get install gdb python2.7-dbg

完全按照这个: https://wiki.python.org/moin/DebuggingWithGdb

  1. 启动gdb
    sudo gdb /usr/bin/python2.7-dbg 9193

这个 python2.7-dbg 即使上面安装之后, 在 /usr/bin/ 目录下. 9193 是我的目标 python 进程号 pid

  1. 不过还是现实 ?? 说明glibc 的调试符号没有加载
    xiatian_art-4167758___usr_bin.png
  2. 安装 glibc 的调试符号表
    sudo apt-get install libc6-dbg
  3. 使用上面的命令进来之后, 还是现实 ?? , 这个时候, 要重启这个进程 使用 c
    c

然后 Ctr + C

  1. 再次使用 bt , 已经可以看到符号.
    xiatian_art-416usr_bin.png

leetcode 刷题体会

  1. 检查边界;
  2. 拿最简单的去试一试, 逐渐复杂, 找到规律;
  3. 从最笨的方法开始, 写完之后, 从某个点渐渐优化;
  4. 空间换时间;
  5. 充分运用约束条件, 比如用参数里面的 Array, 不要新 malloc 一个;
  6. 特殊的约束条件, 用特殊的值;