记一次 Java Testcontainers CPU 100% 问题排查过程

以为代码进入了死循环，结果并没有！

背景与问题

本问题来源于 ShardingSphere issue:
Integration tests occasionally stuck in waiting for container ready #19648

为保证代码质量，Apache ShardingSphere 有自动化运行的单元测试、集成测试，测试会在每次提交 Pull Request 时通过 GitHub Actions 自动运行。

其中有一个专门做集成测试的模块，以前叫 integration-test，现在叫 e2e。集成测试会通过 Docker 启动 ZooKeeper、ShardingSphere-Proxy 等测试所需进程，通过客户端连接 Proxy 运行测试用例并断言。

前段时间，有几次在 GitHub Actions 上运行的集成测试发生超时退出，但是从日志上看，发生超时情况时都还没有开始运行测试用例，很可能是卡在环境准备阶段。

在开发 ShardingSphere 的过程中，也有本地运行集成测试的需求。有一次，在本地运行集成测试时，发现测试运行了十几分钟还是没有动静。

排查过程

代码路经确认

通过 top 命令观察，发现 Java 进程 CPU 100%，只有其中一条线程 100%。
jstack 观察到，消耗 CPU 的应该只有主线程 main，CPU 100% 的情况已经跑了接近 20 分钟了。以下为 jstack 输出结果节选：

"main" #1 prio=5 os_prio=0 cpu=1161262.57ms elapsed=1164.15s tid=0x00007feca80259b0 nid=0x22f2ae runnable  [0x00007fecadfb5000]
   java.lang.Thread.State: RUNNABLE
	at org.testcontainers.shaded.okio.Buffer.getByte(Buffer.java:312)
	at org.testcontainers.shaded.okio.RealBufferedSource.readHexadecimalUnsignedLong(RealBufferedSource.java:310)
	at org.testcontainers.shaded.okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.readChunkSize(Http1ExchangeCodec.java:492)
	at org.testcontainers.shaded.okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.read(Http1ExchangeCodec.java:471)
	at org.testcontainers.shaded.okhttp3.internal.Util.skipAll(Util.java:204)
	at org.testcontainers.shaded.okhttp3.internal.Util.discard(Util.java:186)
	a分析t org.testcontainers.shaded.okhttp3.internal.http1.Http1ExchangeCodec$ChunkedSource.close(Http1ExchangeCodec.java:511)
	at org.testcontainers.shaded.okio.ForwardingSource.close(ForwardingSource.java:43)
	at org.testcontainers.shaded.okhttp3.internal.connection.Exchange$ResponseBodySource.close(Exchange.java:313)
	at org.testcontainers.shaded.okio.RealBufferedSource.close(RealBufferedSource.java:476)
	at org.testcontainers.shaded.okhttp3.internal.Util.closeQuietly(Util.java:139)
	at org.testcontainers.shaded.okhttp3.ResponseBody.close(ResponseBody.java:192)
	at org.testcontainers.shaded.okhttp3.Response.close(Response.java:290)
	at org.testcontainers.shaded.com.github.dockerjava.okhttp.OkDockerHttpClient$OkResponse.close(OkDockerHttpClient.java:285)
	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder.lambda$null$0(DefaultInvocationBuilder.java:272)
	at org.testcontainers.shaded.com.github.dockerjava.core.DefaultInvocationBuilder$$Lambda$178/0x0000000800ec12b0.close(Unknown Source)
	at com.github.dockerjava.api.async.ResultCallbackTemplate.close(ResultCallbackTemplate.java:77)
	at org.testcontainers.containers.output.FrameConsumerResultCallback.close(FrameConsumerResultCallback.java:100)
	at org.testcontainers.containers.wait.strategy.LogMessageWaitStrategy.waitUntilReady(LogMessageWaitStrategy.java:51)
	at org.testcontainers.containers.wait.strategy.AbstractWaitStrategy.waitUntilReady(AbstractWaitStrategy.java:35)
	at org.testcontainers.containers.GenericContainer.waitUntilContainerStarted(GenericContainer.java:892)
	at org.testcontainers.containers.GenericContainer.tryStart(GenericContainer.java:440)
	at org.testcontainers.containers.GenericContainer.lambda$doStart$0(GenericContainer.java:325)
	at org.testcontainers.containers.GenericContainer$$Lambda$194/0x0000000800ece220.call(Unknown Source)
	at org.rnorth.ducttape.unreliables.Unreliables.retryUntilSuccess(Unreliables.java:81)
	at org.testcontainers.containers.GenericContainer.doStart(GenericContainer.java:323)
	at org.testcontainers.containers.GenericContainer.start(GenericContainer.java:311)
	at org.apache.shardingsphere.test.integration.env.container.atomic.DockerITContainer.start(DockerITContainer.java:49)
	at org.apache.shardingsphere.test.integration.env.container.atomic.ITContainers$$Lambda$95/0x0000000800d9ac08.accept(Unknown Source)
	at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(java.base@17.0.1/ForEachOps.java:183)
	at java.util.stream.ReferencePipeline$2$1.accept(java.base@17.0.1/ReferencePipeline.java:179)
	at java.util.LinkedList$LLSpliterator.forEachRemaining(java.base@17.0.1/LinkedList.java:1242)
	at java.util.stream.AbstractPipeline.copyInto(java.base@17.0.1/AbstractPipeline.java:509)
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(java.base@17.0.1/AbstractPipeline.java:499)
	at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(java.base@17.0.1/ForEachOps.java:150)
	at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(java.base@17.0.1/ForEachOps.java:173)
	at java.util.stream.AbstractPipeline.evaluate(java.base@17.0.1/AbstractPipeline.java:234)
	at java.util.stream.ReferencePipeline.forEach(java.base@17.0.1/ReferencePipeline.java:596)
	at org.apache.shardingsphere.test.integration.env.container.atomic.ITContainers.start(ITContainers.java:82)
	- locked <0x000000061cefdc20> (a org.apache.shardingsphere.test.integration.env.container.atomic.ITContainers)
	at org.apache.shardingsphere.test.integration.container.compose.mode.ClusterComposedContainer.start(ClusterComposedContainer.java:64)
	at org.apache.shardingsphere.test.integration.engine.BaseITCase.setUp(BaseITCase.java:78)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@17.0.1/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@17.0.1/NativeMethodAccessorImpl.java:77)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@17.0.1/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@17.0.1/Method.java:568)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49

从代码路径上看，和等待容器就绪逻辑相关，看到有个 close 操作，结合容器所使用的等待策略为 LogMessageWaitStrategy，可能是正在关闭对 docker log 命令对应的接口的调用。

	at org.testcontainers.containers.output.FrameConsumerResultCallback.close(FrameConsumerResultCallback.java:100)
	at org.testcontainers.containers.wait.strategy.LogMessageWaitStrategy.waitUntilReady(LogMessageWaitStrategy.java:51)
1
2

定位到相关代码，close 方法在 LogMessageWaitStrategy.java:51，代码中没有直接 close 方法，而是通过 try-with-resources 代码块隐式调用。

能够走到 close 方法，说明 51 行上面的等待逻辑已经执行结束或者抛出了异常。但如果是 callback.close() 方法内部产生了死循环，从日志和代码路径可能无法确定逻辑是正常结束还是抛了异常。

从内存快照上来看，好像既没有 TimeoutException，也没有 ContainerLaunchException，所以代码可能没有发生异常。

由于 jstack 是瞬时输出，在不确定代码是否陷入 getByte 方法死循环的情况下，可以用 async-profiler 做个 on-cpu 采样。
做了大约 78 秒 100 Hz 采样，样本数恰好 7800 左右，基本确定代码陷入了 Buffer.getByte 死循环导致 CPU 100%。

内存分析

确定代码陷入死循环，但原因还不明确。为尽可能收集信息，做了一次 Heap Dump 分析。
检查 Buffer 实例的信息，发现了问题：

咨询 okio 社区

我在 okio 社区提问了以上现象 Is it normal that the pos greater than limit in Buffer? #1133

得到的回复是：可能是多线程操作了线程不安全的 Buffer 导致的问题。

等等，好像并没有死循环

根据代码路径，查看循环代码。根据前面分析所得，代码应该是在 else 内的 while 循环：

循环的退出条件是 pos >= 0L，pos 在循环中不断 -2 的，如果 pos 是负数，持续 -2 是不是就能溢出为正数了？

这么看也许代码并没有进入死循环，可能只是执行的时间不够久？

打算用 jshell 执行循环累加 -2 模拟死循环情况，不过考虑到 long 类型的长度，先把步进调大一点。

执行发现，long 类型初始值 -1：

• 每次加 -200,000,000 的话，需要 11 秒才能变为正数；
• 每次加 -20,000,000 的话，需要 107 秒才能变为正数。

以此推算，如果每次加 -2，大约就需要 1,000,000,000 秒才能把 long 溢出为正数？

1000000000 / 3600 / 24 / 365 约等于 31.71 年

所以，代码实际上并没有进入死循环，只是还没有运行完！ 🌚️🌚️

能否从内存快照发现其他问题？

粗略看了一下暂时没能发现新的点。从内存快照中只能看到目前只有 main 线程的栈中引用了这个存在问题的 Buffer。

如果大家有兴趣也可以下载内存快照和 JFR 文件分析看看。

testcontainers 100% CPU 采样与内存快照 https://download.csdn.net/download/wu_weijie/87522297