记一次 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)

从代码路径上看，和等待容器就绪逻辑相关，看到有个 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)

定位到相关代码，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%。
在这里插入图片描述