最近遇到2次由于 ServiceLoader 引起的 CPU 100%, 导致业务线程不能正常运行.

什么是 Service Loader

Spring 里面有个核心的概念, 就是依赖注入: 我期望有个服务, 但是一开始我并不指定具体的实现类, 等到我真正需要的时候, 这个依赖根据运行时自动注入. 同样, JDK 6 也引入了一个一样的实现框架, 就是 ServiceLoader. 它的实现也很简单. 使用的方法如下:

ServiceLoader<ServiceAPI> serviceLoader =ServiceLoader.load(ServiceAPI.class);
Iterator<ServiceAPI> iterator = serviceLoader.iterator();
while (iterator.hasNext()) {
    ServiceAPI impl = iterator.next();
}

它的主要作用就是: 你需要那个服务的具体实现, 让我来帮你找, 可能找到一个或多个, 或找不到. 结果返回的是一个 Iterator.

如何找到具体的实现的?

如果某个 Jar 包提供某个服务的具体实现, 按照 JDK 定义的规则, 它就会在在 Jar 包的 META-INFO/services 文件夹提供一个名为某个service的文件, 文件的内容就是具体的实现类.
比如 xerceslmpl-x.x.x.jar 提供了 javax.xml.datatype.DatatypeFactory 的具体实现:

文件的内容就是本 jar 包里面的具体实现类的全名.
所以, 可以通过判断当前 jar 包里面的 META-INFO 文件夹下面是不是包含某个service 文件名来判断是不是有这个实现.

如何出问题的?

出问题的就是下面这行代码:

javax.xml.datatype.DatatypeFactory df = javax.xml.datatype.DatatypeFactory.newInstance();

就是要初始化一个xml 转换成 Java对象的类型工厂类, 如果去 JDK 里面查看这个类的源代码, 会发现其实它是一个抽象 Service. 运行时它有4种查找具体实现类的方法. 前2种都是通过配置, 第三种就是通过 ServiceLoader 去查找它的具体实现.

出问题的方式就是通过 ServiceLoader 的方式, 这种方式就是通过 ClassLoader 去查找所有的 Jar 包, 一个个去看有没有某个 jar 的 META-INFO/services 文件夹下面包含这么一个 service 的具体实现.

通常的实现的一个具体栈:

java.lang.Thread.State: RUNNABLE
    at java.util.zip.ZipCoder.getBytes(ZipCoder.java:77)
    at java.util.zip.ZipFile.getEntry(ZipFile.java:325)
    - locked <0x00000007157ac988> (a java.util.jar.JarFile)
    at java.util.jar.JarFile.getEntry(JarFile.java:253)
    at java.util.jar.JarFile.getJarEntry(JarFile.java:236)
    at sun.misc.URLClassPath$JarLoader.getResource(URLClassPath.java:1084)
    at sun.misc.URLClassPath$JarLoader.findResource(URLClassPath.java:1062)
    at sun.misc.URLClassPath$1.next(URLClassPath.java:281)
    at sun.misc.URLClassPath$1.hasMoreElements(URLClassPath.java:291)
    at java.net.URLClassLoader$3$1.run(URLClassLoader.java:609)
    at java.net.URLClassLoader$3$1.run(URLClassLoader.java:607)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader$3.next(URLClassLoader.java:606)
    at java.net.URLClassLoader$3.hasMoreElements(URLClassLoader.java:631)
    at sun.misc.CompoundEnumeration.next(CompoundEnumeration.java:45)
    at sun.misc.CompoundEnumeration.hasMoreElements(CompoundEnumeration.java:54)
    at java.util.ServiceLoader$LazyIterator.hasNextService(ServiceLoader.java:354)
    at java.util.ServiceLoader$LazyIterator.hasNext(ServiceLoader.java:393)
    at java.util.ServiceLoader$1.hasNext(ServiceLoader.java:474)
    at javax.xml.datatype.FactoryFinder$1.run(FactoryFinder.java:296)
    at java.security.AccessController.doPrivileged(Native Method)
    at javax.xml.datatype.FactoryFinder.findServiceProvider(FactoryFinder.java:292)
    at javax.xml.datatype.FactoryFinder.find(FactoryFinder.java:268)
    at javax.xml.datatype.DatatypeFactory.newInstance(DatatypeFactory.java:144)

通过上面的栈, 我们可以看到, 它其实是到 jar 到文件里面去看有没有这个项目, 没有就继续查找下一个.
这种方式相对消耗CPU到, 因为每次都要查找所有的jar 包, 一个个去查看压缩jar里面有没有这个文件. 如果以线上项目有2百多个jar, 查找一次要消耗即使毫秒.

但是, 即便这样, 还打不到让CPU很高的程度.

如何推高 CPU 的?

如果大家查看上面的线程栈, 其实在遍历某个jar 之前, 外层的遍历其实是遍历一些 ClassLoader, 然后每个 ClassLoader 都会有一些 Jar, 然后再遍历这些 jar.
其实真正出问题的是在 TomcatEmbeddedWebappClassLoader 里面. 这个 ClassLoader 在遍历每个Jar 的时候, 如果没有对应的 service 具体实现的 META-INFO/services 文件, 它会抛出一个 FileNotFoundException, 既然有 Exception, 就会有回溯栈, 就会非常耗时, 甚至进入C 代码. 看下面的火焰图:

本文列出作者在日常使用 Java 内存分析工具 MAT 的过程中用到的一些技巧

导出长字符串

有时候我们经常要从 heap 中复制出某些很长的字符串, 来观察它到底有哪些数据. 通常我们通过: 在某个字符串上点击右键 - Copy -> Value. 但是通常这个复制出的内容都有长度限制.

比如下面的例子, 我想从 HTTP request 的 HeapByteBuffer 复制出它已经读取请求的内容, 但是通过上面的方法只能复制出几千的字符:

但是如果其内容远超这个数量, 拿到的就是部分数据, 根据部分数据可能得出错误的结论.
如何完全导出其内容?
在上面的菜单中选择 -> Save Value To File. 就能导出全部内容.

不过对于上面例子中的 HeapByteBuffer 要特别注意, 它是通过当前的位置(pos)来标记那里是有效数据的, pos 位置之后可能还有数据, 只不过是无效数据.

根据字段值分组统计

SQL 里面有 select * from table_0 group by column_0. 可是 OQL 里面却没有这个语句. 但是MAT 却提供了这样的功能.
根据下面的菜单栏, 就能找到 Group By Value 选项.

然后填入你想分组的类名字和要分组的字段. 下面以 java.util.regex.Pattern 的 normalizedPattern 来分组:

最终看到每个 normalizedPattern 的统计个数:

写了一个非常简单的 java main 函数, 然后运行, 然后做 core dump, 竟然发现 core dump 竟然有 6.6G.

Java 程序:

public class ErrorExample {
    public static void main(String[] args) throws InterruptedException {
        Thread.sleep(600000);
    }
}

做 core dump 和 2种不同的 heap dump.

gcore <pid>

$ ls -lah 
-rw-rw-r-- 1 supra supra 6.6G Apr 30 00:26 core.276268
-rw-rw-r-- 1 supra supra  67M Apr 30 00:26 core.276268.gz
-rw-rw-r-- 1 supra supra 1.3M Apr 30 01:02 heap.bin
-rw-rw-r-- 1 supra supra 334K Apr 30 01:02 heap.bin.gz
-rw------- 1 supra supra 2.8M Apr 30 01:01 heap.hprof
-rw------- 1 supra supra 855K Apr 30 01:01 heap.hprof.gz

上面分别是使用不同工具得到的不同 dump 及进一步压缩过后的:

1. gcore 276268 得到 core.276268
2. jhsdb jmap --binaryheap --pid 280038 得到 heap.bin
3. jcmd 280038 GC.heap_dump heap.hprof 得到 heap.hprof.

可以看到 jhsdb 做出的最小, core dump 最大. 这很有可能是 JVM 保留了很多想用但是还没用到的内存.

查看JVM 当前使用的内存, 发现其实使用的很小:

$ jcmd 281746 GC.heap_info
281746:
 garbage-first heap   total 258048K, used 1744K [0x0000000707e00000, 0x0000000800000000)
  region size 1024K, 2 young (2048K), 0 survivors (0K)
 Metaspace       used 155K, capacity 4486K, committed 4864K, reserved 1056768K
  class space    used 6K, capacity 386K, committed 512K, reserved 1048576K

然后查看使用的启动参数, 可以看到保留的最大的堆是将近4G(MaxHeapSize=4162846720), 保留的代码缓存区是240M(ReservedCodeCacheSize=251658240), 再加上其它, 比如 JDK 库, 元数据区等, 可能达到6G多.

$ jcmd 281746 VM.flags
281746:
-XX:CICompilerCount=4 -XX:ConcGCThreads=2 -XX:G1ConcRefinementThreads=8 -XX:G1HeapRegionSize=1048576 -XX:GCDrainStackTargetSize=64 -XX:InitialHeapSize=262144000 -XX:MarkStackSize=4194304 -XX:MaxHeapSize=4162846720 -XX:MaxNewSize=2497708032 -XX:MinHeapDeltaBytes=1048576 -XX:NonNMethodCodeHeapSize=5836300 -XX:NonProfiledCodeHeapSize=122910970 -XX:ProfiledCodeHeapSize=122910970 -XX:ReservedCodeCacheSize=251658240 -XX:+SegmentedCodeCache -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseG1GC

如果使用 pmap 查看这个进程的虚拟内存使用情况, 可以发现确实使用了6.6G(最后一行):

$ pmap -x 280038
280038:   java ErrorExample
Address           Kbytes     RSS   Dirty Mode  Mapping
0000000707e00000  256000     328     328 rw---   [ anon ]
0000000717800000 2758656       0       0 -----   [ anon ]
00000007c0000000 1048576       0       0 -----   [ anon ]
............ 省略 ....................
00007f39c513e000       8       8       0 r---- ld-linux-x86-64.so.2
00007f39c5178000       8       8       8 rw--- ld-linux-x86-64.so.2
00007ffc854ed000     132      32      32 rw---   [ stack ]
ffffffffff600000       4       0       0 --x--   [ anon ]
---------------- ------- ------- -------
total kB         6821276   37464   10660

什么是core dump

在 Linux 系统中，当一个进程崩溃（例如，由于段错误或其他严重错误），它通常会产生一个称为 "核心转储"（core dump）的文件。核心转储文件包含了进程崩溃时的内存映像和一些执行上下文信息，如寄存器状态、程序计数器位置、内存管理信息等。这些信息对于开发者来说非常有价值，因为它们可以用来调试程序，了解程序崩溃的原因。

Java 进程如何产生 core dump

对于正在运行的 Java 进程, 它就是一个标准的linux 进程, 可以使用 linux 上的各种工具来产生 core dump, 比如 gcore 或者 kill :

$ gcore <pid>
$ kill -11 <pid>

对于 Java 应用程序自身, 当它奔溃的时候, 默认会产生 core dump, 因为它有如下默认参数-XX:+CreateCoredumpOnCrash:

$ java -XX:+PrintFlagsFinal -version | grep Core
     bool CreateCoredumpOnCrash                    = true                                      {product} {default}

虽然上面的方式都能产生 core dump, 但是很有可能你并不能看到 core dump, 因为有各种其它条件会阻碍 core dump的产生:

1. 系统设置了 core size 的大小太小, 查看 ulimit -c
2. core dump 要写入的文件夹没有权限
3. core dump 被系统设置拦截, 比如 apport, 它产生了 crash report, 却拦截了 core dump的产生.

core dump 有什么用?

core dump 里有进程当时时间点上的全部内存信息, 寄存器信息, 栈信息, 栈上变量值, 打开文件句柄, 打开的socket 等各种非常有用的信息, 对于诊断应用为什么崩溃具有很大的意义.

gdb 可以直接打开core dump 文件, 并读取里面的信息.

$ gdb core core.720444` 

使用 gdb 去debug Java 程序比较麻烦.

但是可以使用 JDK 自带的 jdb:

# java 8 版本
$ jdb -listconnectors
$ jdb -connect sun.jvm.hotspot.jdi.SACoreAttachingConnector:javaExecutable=$JAVA_HOME/bin/java,core=core.720444

java 11 版本
$ jhsdb clhsdb --exe ErrorExample --core core.720444

Core Dump vs Java Heap Dump

Core Dump

• 定义：
  Core dump 是操作系统在进程异常终止时生成的一个文件，它包含了进程终止时内存中的内容。
• 内容：
  Core dump 包含了进程的整个内存映像，包括程序计数器、寄存器、堆栈、堆内存、全局变量、打开的文件描述符、环境变量、程序代码、加载的共享库等。
• 用途：
  主要用于程序崩溃后的调试和故障排查。可以使用调试工具（如 gdb）来分析 core dump 文件，确定程序崩溃的原因。
• 大小：
  Core dump 文件通常很大，因为它包含了整个进程的内存映像。
• 生成方式：
  Core dump 通常由操作系统在进程崩溃时自动生成，或者可以使用 gcore 命令手动生成。

Java Heap Dump

• 定义：
  Java heap dump 是 JVM 在某一时刻的堆内存的快照，包含了所有的 Java 对象和类信息。
• 内容：
  Heap dump 专注于 Java 堆内存，包括对象实例、数组、类实例、垃圾收集器信息等。
• 用途：
  主要用于分析 Java 应用程序的内存使用情况，如检测内存泄漏、查看对象的分配和引用情况等。
• 大小：
  Heap dump 文件的大小取决于 Java 堆的大小，通常比完整的 core dump 小。
• 生成方式：
  Heap dump 可以通过 JVM 提供的工具（如 jmap）、管理接口（如 JMX）生成，或在发生 OutOfMemoryError 时自动生成（如果配置了 -XX:+HeapDumpOnOutOfMemoryError JVM 参数）。

heap dump vs crash log file

这就类似
core dump -> apport crash report
heap dump -> crash log file (err_log_pid.log)

-XX:OnError 选项

如果启动参数配置了-XX:OnError选项, 当 fatal error 产生的时候, JVM 就会执行该选项配置的命令. 多个执行命令可以用 ; 分割开. 可以用 %p 指代当前进程号, 因为 % 用作了特殊符, 所以遇到真的 %, 就要用两个 %% 代替. 官方给的例子:

java -XX:OnError="pmap %p" MyApp #使用 pmap 查看内存空间
java -XX:OnError="gcore %p; dbx - %p" MyApp # 使用 gcore 产生core dump 并用 dbx 进行debug
java -XX:OnError="gdb - %p" MyApp # 使用 gdb debug

-XX:ErrorFile 选项

设置当 fatal error 产生的时候, 把log写到哪个文件去, 需要全路径名(%p指代当前进程号, %%=%).
如果该文件存在, 并且可以写, 那么就覆盖.
如果不设置, 它的默认行为是: 产生一个 java_error_%p.log 文件, %p是进程号, 默认放在当前进程的当前工作目录(CWD), 如果当前工作目录不可用(比如写权限,空间不够等), 会写到临时文件夹目录(/tmp).
参考: https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/felog001.html

试验 -XX:OnError 和 -XX:ErrorFile

更多细节在:
https://www.tianxiaohui.com/index.php/Troubleshooting/Java-%E5%A6%82%E4%BD%95%E5%88%9B%E5%BB%BA%E4%B8%80%E4%B8%AA-fatal-error.html

jhsdb（Java HotSpot Debugger）是在JDK 9中引入的命令行实用程序，它是服务性代理（Serviceability Agent）工具的一部分。服务性代理是一个框架，允许对运行中的Java虚拟机（JVM）或崩溃后的核心转储进行深入分析。引入jhsdb的目的有几个：

1. 统一的调试工具：在JDK 9之前，开发者需要使用不同的工具，如jmap、jstack、jinfo等来执行各种调试任务。jhsdb将这些工具统一到一个命令行界面下，使得在不切换多个工具的情况下更容易执行广泛的调试和诊断任务。
2. 增强的事后诊断：jhsdb提供了分析核心转储和实时进程的能力，这对事后诊断至关重要。当JVM崩溃时，开发者需要了解崩溃时JVM的状态，这一点尤其有用。
3. 高级分析能力：使用jhsdb，开发者可以执行高级分析，如检查堆、分析内存使用情况和获取线程堆栈跟踪。它还允许使用内置的命令行调试器（CLD）来调试Java进程，这是一个类似于gdb的基于文本的界面。
4. 跨平台一致性：jhsdb旨在在不同平台上保持一致的工作，为在各种操作系统上进行诊断提供了标准化的方法。
5. 与HotSpot JVM集成：由于jhsdb是为HotSpot JVM量身定制的，它可以利用HotSpot的内部特性来提供有关JVM内部的详细信息，这对于性能调优和解决复杂问题非常宝贵。
6. 可访问性：通过包含在JDK中，jhsdb可以立即供所有Java开发者使用，无需额外下载或安装。
7. 可脚本化：作为命令行工具，jhsdb可以轻松地编写脚本并集成到自动化的调试和诊断工作流中，这对于持续集成和部署管道非常有益。

总的来说，JDK 9中引入jhsdb的目的是通过提供一个强大而多功能的JVM诊断和调试工具来改善开发者体验，从而增强分析和解决Java应用程序中复杂问题的能力。

实践

linux 系统现在有一个正在运行的 Java 程序, 进程号是 256487, 却遇到了下面的错误

$ jhsdb jmap  --pid 256487
Attaching to process ID 256487, please wait...
ERROR: ptrace(PTRACE_ATTACH, ..) failed for 256487: Operation not permitted
Error attaching to process: sun.jvm.hotspot.debugger.DebuggerException: Can't attach to the process: ptrace(PTRACE_ATTACH, ..) failed for 256487: Operation not permitted
sun.jvm.hotspot.debugger.DebuggerException: sun.jvm.hotspot.debugger.DebuggerException: Can't attach to the process: ptrace(PTRACE_ATTACH, ..) failed for 256487: Operation not permitted

这是因为 ptrace 权限的问题. 查看 /proc/sys/kernel/yama/ptrace_scope 可以看到里面的值是 1, 改成 0 就好了

$ cat /proc/sys/kernel/yama/ptrace_scope
1
$ echo 0 | sudo tee /proc/sys/kernel/yama/ptrace_scope
0

$ jhsdb jmap  --pid 256487 # as pmap output
Attaching to process ID 256487, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 11.0.22+7-post-Ubuntu-0ubuntu222.04.1
0x0000563f4efe6000    14K    /usr/lib/jvm/java-11-openjdk-amd64/bin/java
0x00007fe2671ba000    44K    /usr/lib/jvm/java-11-openjdk-amd64/lib/libzip.so
0x00007fe2671c5000    66K    /usr/lib/x86_64-linux-gnu/libresolv.so.2
0x00007fe2671d9000    22K    /usr/lib/x86_64-linux-gnu/libkeyutils.so.1.9
0x00007fe2671e0000    50K    /usr/lib/x86_64-linux-gnu/libkrb5support.so.0.1
0x00007fe2671ee000    18K    /usr/lib/x86_64-linux-gnu/libcom_err.so.2.1
0x00007fe2671f4000    178K    /usr/lib/x86_64-linux-gnu/libk5crypto.so.3.1
0x00007fe267223000    808K    /usr/lib/x86_64-linux-gnu/libkrb5.so.3.3
0x00007fe2672ee000    330K    /usr/lib/x86_64-linux-gnu/libgssapi_krb5.so.2.2
0x00007fe267342000    178K    /usr/lib/x86_64-linux-gnu/libtirpc.so.3.0.0
0x00007fe267370000    91K    /usr/lib/x86_64-linux-gnu/libnsl.so.2.0.1
0x00007fe26738a000    54K    /usr/lib/x86_64-linux-gnu/libnss_nis.so.2.0.0
0x00007fe267399000    42K    /usr/lib/x86_64-linux-gnu/libnss_compat.so.2
0x00007fe2673b8000    39K    /usr/lib/jvm/java-11-openjdk-amd64/lib/libjimage.so
0x00007fe2673c1000    213K    /usr/lib/jvm/java-11-openjdk-amd64/lib/libjava.so
0x00007fe2673ef000    14K    /usr/lib/x86_64-linux-gnu/librt.so.1
0x00007fe2674f4000    122K    /usr/lib/x86_64-linux-gnu/libgcc_s.so.1
0x00007fe267514000    918K    /usr/lib/x86_64-linux-gnu/libm.so.6
0x00007fe2675fb000    2207K    /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.30
0x00007fe267827000    22708K    /usr/lib/jvm/java-11-openjdk-amd64/lib/server/libjvm.so
0x00007fe268afc000    2168K    /usr/lib/x86_64-linux-gnu/libc.so.6
0x00007fe268d25000    80K    /usr/lib/jvm/java-11-openjdk-amd64/lib/jli/libjli.so
0x00007fe268d38000    106K    /usr/lib/x86_64-linux-gnu/libz.so.1.2.11
0x00007fe268d54000    67K    /usr/lib/jvm/java-11-openjdk-amd64/lib/libverify.so
0x00007fe268d67000    235K    /usr/lib/x86_64-linux-gnu/ld-linux-x86-64.so.2

$ jhsdb -h
    clhsdb           command line debugger
    hsdb             ui debugger
    debugd --help    to get more information
    jstack --help    to get more information
    jmap   --help    to get more information
    jinfo  --help    to get more information
    jsnap  --help    to get more information

$ jhsdb jmap --help

$ jhsdb jmap --binaryheap --pid 274471
Attaching to process ID 274471, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 11.0.22+7-post-Ubuntu-0ubuntu222.04.1
heap written to heap.bin