记录一次奇怪的 CPU profiling 问题
本文记录了一次奇怪的线上线程相关问题的案例.
- 先是看到 CPU 稍微有点高
- 大概看了下, 发现这个机器没做啥耗 CPU 的操作, 大多数都是网络请求, 于是做 CPU profiling, 于是出现了下面奇怪的方法调用
首先, 看上去这个不像 Java 的方法, 于是推断是 JVM 里面调用的系统 native 方法. 其次, 去 google 了一把, 这是系统的一个方法, 它的意图就是让出 CPU, 让其它 CPU 去执行. 可是为什么要频繁让出呢? 为什么占用这么多 CPU 资源呢? 另外, 搜了一下有没有人遇到过类似问题, 并没有发现. - 是不是 Native 代码调用, 那些 native 代码调用了它? 于是从系统层面针对这个 Java 进程的这个方法调用, 又专门做了一次 CPU profiling, 看到下面的火焰图:
- 从上的火焰图看, 貌似有个叫 WrapperJarAppMa 的方法调用了 __sched_yield 方法. 于是去 google 了一下这个关键字, 相当失望:
不过注意 google 给的提示! 后面再说. 正常的推理已经不能解决问题, 于是开始归纳总结. 发现如下模式:
- 这个应用分配了 174G 内存, 分配了 24 个 CPU, 资源相当丰富
- 这个应用的 heap 给了 154G, heap 常规占用在 75G 左右, 空闲也非常多;
- 这个应用占用这么多 heap 是因为内存加载了非常多的缓存, 系统启动就加载, 加载完要十几分钟, 然后再接收流量;
可是从上面的这些模式, 并么有推断出什么.
- 这个应用分配了 174G 内存, 分配了 24 个 CPU, 资源相当丰富
- 于是又回到已知的关键字 "__sched_yeild" 和 "WrapperJarAppMa". 想到 AsyncProfiler 其实可以根据线程做火焰图, 于是又根据线程做了火焰图, 看到如下:
两边都是业务线程, 中间只有 2 层方法的都是我们看到的上面 "WrapperJarAppMa" 调用 "__sched_yeild", 所以, 中间从下数第二层红色的都是"WrapperJarAppMa", 第三层都是"__sched_yeild". 虽然这次也只能看到上面已经看到的 2 个关键字, 可是从于业务线程对比, 可以明显看出来: "WrapperJarAppMa" 是线程名字, 因为绿色的业务线程那边, 第二层也是线程名字. - 于是通过 pstree 去查看线程的结构关系, 发现确实如此:
- 可是代码里面从来没有看到这个线程的关键字, 这个线程从那里来的? 为什么这么多? 于是打算到 log 文件里面查一吧, 确实发现了这个线程(原来真正的线程名字叫 "WrapperJarAppMain" 其它地方只是字长的省略):
- 这个时候在拿这个线程名字去 google, 就发现了线程出处, 原来在我们付费使用的商业软件 Java Service Wrapper 里面. 因为是付费软件, 在 maven 里面没有发现它的踪影, 于是从生产环境下载一个正在使用的 wrapper.jar. 反编译后重要找到了这个线程的出处:
- 为什么会有这么多 "WrapperJarAppMa" 线程一直存活, 并且一直 sched_yeild 呢? 想看看这些线程到底在做什么? 是不是在上面的 while 循环里面出不来了? 于是做了一个 54G 的 heap dump, 然后压缩到38G 下载到本地去做 heap 分析, 竟然没有看到这些线程:
- 于是怀疑在做 heap dump 过程中这些线程已经死掉了, 于是重新去查看了这些线程, 发现线程还好好的活着:
- 这次还注意到, 在 heap dump 里面线程共计277个, 可是使用 pstree 能看到383个, 考虑到系统正在运行中, 有好多线程可能在变动中, 但是也不能差别这么多. 仔细观察, 发现类似这样的线程都没有出现在 heap dump 中
类似这样的线程有:
- {C2 CompilerThre}(123318)
- {G1 Main Marker}(123296)
- {G1 Marker#X}(123297)
- {G1 Refine#XX}(123295)
- {GC Thread#XX}(123247)
- {VM Periodic Tas}(123322)
- {VM Thread}(123313)
- {WrapperJarAppMa}(130114)
- {default-microme}(123384)
- {java}(123246)
- 可以看到这些线程的数量也不少:
在生产环境看到这个问题之后, 去测试环境看了一下, 有如下总结:
- 测试环境在 CPU profiling 中并没有看到 __sched_yeild 被调用;
- 测试环境 也有 WrapperJarAppMa 线程;
- WrapperJarAppMa 总数与当前物理机的 CPU 合数一致, 除了一个正常结束的 WrapperJarAppMa 线程, 剩下 (CPU 核总数 - 1) 个这样的线程;
- 这些后来不死的线程, 在 heap 中看不到, 类似JDK 某些自带的线程;
- 这些线程的名字完全复制第一个线程的名字, 可是看不到创建的地方.
改动 WrapperJarApp 的源码, 在生产新线程的地方加了日志, 改了线程的名字, 发现日志中该方法只有一次被调用
long i = System.currentTimeMillis() % 10; Thread mainThread = new Thread(this, i + "-WrapperJarAM"); Thread.dumpStack();
如今的问题:
- 这些后来是怎么创建出来的?
- 为什么生产环境他们一直在运行, 可是在测试环境 profiling 中看不到运行;
- 另外发现 Wrapper-Connection 线程的优先级是 10, 怀疑这些不死的线程优先级也是 10
终于看到这些线程在干嘛
- 怀疑这些线程不是 Java 代码创建 (拦截Thread.start() 不到, 并且没有出现在 thread dump), 于是做了一个 core dump;
- 使用 gdb 从 core dump 可以看到线程正在运行的栈
- 果然在对应的目录找到了对应的共享库文件, 于是去查该项目的git 工程, 也找到了对应的共享库;
找到调用 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(); } }
为什么会创建 (cpu count - 1) 个线程?
- 我们找到了这个共享库的源码, 结合 core dump 中看到的栈, 找出了创建这些线程的源代码行. 这里使用了 CPU 个数去创建 blas server 的服务线程数.
- 下面的 blas_thread_server 方法就是 blas server 要执行的 routine. 我们通过 gdb 看到的代码, 就是这个里面的代码
- 为了进一步验证我们的想法, 下载了 https://github.com/xianyi/OpenBLAS 的代码, 在本地 Linux 上面重新编译包含符号的共享库, 这次, 我们看到这些线程在哪行代码运行:
到此为止, 我们终于搞明白了这些线程哪来的?这些线程数目和 CPU 个数的关系. 其它一些相关的话题:
- blas 和 openBlas 应该是人工智能相关的算法类库;
- 其实 WrapperJarApp 里面设置的线程优先级在 Linux 上面其实没啥用.
- C 代码 (通过 pthread_create 创建的线程, 在Java 的 thread dump 看不到)