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

2023-09-22 09:00:00

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

文章目录

背景与问题

本问题来源于 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%。
在这里插入图片描述

内存分析

确定代码陷入死循环，但原因还不明确。为尽可能收集信息，做了一次 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

更多推荐

Android设计支持库

本文所有的代码均存于https://github.com/MADMAX110/BitsandPizzas设计支持库（DesignSupportLibrary）是Google在2015年的I/O大会上发布的全新MaterialDesign支持库，在这个support库里面主要包含了8个新的MaterialDesign组件

C#里面的三种定时计时器：Timer

在.NET中有三种计时器：1、System.Windows.Forms命名空间下的Timer控件，它直接继承自Componet。Timer控件只有绑定了Tick事件和设置Enabled=True后才会自动计时，停止计时可以用Stop()方法控制，通过Stop()停止之后，如果想重新计时，可以用Start()方法来启动计

什么是Jmeter?Jmeter使用的原理步骤是什么？

1.1什么是JMeterApacheJMeter是Apache组织开发的基于Java的压力测试工具。用于对软件做压力测试，它最初被设计用于Web应用测试，但后来扩展到其他测试领域。它可以用于测试静态和动态资源，例如静态文件、Java小服务程序、CGI脚本、Java对象、数据库、FTP服务器，等等。JMeter可以用于对

【Linux】分布式版本控制工具git

​​📝个人主页：@Sherry的成长之路🏠学习社区：Sherry的成长之路（个人社区）📖专栏链接：Linux🎯长路漫漫浩浩，万事皆有期待上一篇博客：【Linux】Linux调试器-gdb文章目录一、前言二、版本控制1、何为版本控制2、版本控制工具①集中式版本控制工具②分布式版本控制工具三、代码托管平台四、Lin

【TAPD】实践：TAPD 项目管理配置

目录一、30人以内团队申请免费企业版（1）首次申请试用期3个月（2）进一步申请免费续期二、成员管理三、用户组管理四、项目管理（1）首个项目配置（2）自定义项目模板（3）二次创建项目五、自定义项目模板好处一、30人以内团队申请免费企业版【Tapd】30人以内团队：申请永久免费的Tapd企业版步骤https://gusan

新款 锐科达 SV-2402VP SIP广播音频模块 支持RTP流音频广播

新款锐科达SV-2402VPSIP广播音频模块支持RTP流音频广播SV-2402VP网络音频模块是一款通用的独立SIP音频功能模块，可以轻松地嵌入到OEM产品中。该模块对来自网络的SIP协议及RTP音频流进行编解码。该模块支持多种网络协议和音频编解码协议，可用于VoIP和IP寻呼以及高质量音乐流媒体播放等应用。同时，S

数字孪生在灌区信息中的应用

灌区信息是智慧水利的组成部分，对灌区现代化改造的支撑作用和地位尤为重要，对促进水利可持续发展有重要意义。灌区信息化系统主要对对灌区的水情、雨情、土壤墒情、气象等信息进行监测，对重点区域进行视频监控，同时对泵站、闸门进行远程控制，实现了信息的测量、统计、分析、控制、调度等功能。为灌区管理部门科学决策提供了依据，提升灌区的

TCP并发服务器的多进程实现与多线程实现

TCP并发服务器的多进程实现与多线程实现一、TCP并发服务器的多进程实现代码#include<my_head.h>#defineSERVER_IP"192.168.125.11"//服务器IP#defineSERVER_PORT6666//服务器端口//子进程处理客户端信息函数intdeal_client_messag

小插曲 -- 使用Linux编写 判断程序是否在运行的小程序

编写思路首先，在执行“ps-elf|grepxxx”时，如果xxx存在，通常会有两条结果，一个是xxx对应的PID，一个则是grep对应的PID，但是如果我希望执行命令后，xxx存在就只有xxx对应的PID，不存在就什么都不显示的话，可以将指令修改成：“ps-elf|grepXXX|grep-vgrep”，这样就可以屏

雷电9模拟器抓包

背景本人一开始使用fiddler，然后使用wireshark。然后一直没能成功对雷电9完成JDapp的抓包任务，后来发现一款新产品Reqable，实现了JD请求抓包。思路经过查找资料，我发现核心思路都相差不大，基本使用模拟器wifi代理+证书的形式，把同一局域网下的请求由本地端口代理，再通过工具进行抓包。实战本文以Re

有多条业务线，mysql建多库多表比较好还是一个库多个表比较好呢？

这个问题的答案取决于您的具体需求。以下是一些需要考虑的因素：数据独立性：如果您的业务线之间的数据是独立的，并且不太可能需要进行跨业务线的查询，那么将它们分成多个数据库可能是有意义的。这样可以使每个业务线的数据更加独立，减少潜在的冲突和竞态条件。查询性能：在某些情况下，将数据分为多个表可能会提高查询性能。例如，如果您的数

热文推荐
  1. C++之template可变模板参数应用总结(二百二十八)

    简介：CSDN博客专家，专注Android/Linux系统，分享多mic语音方案、音视频、编解码等技术，与大家一起成长！优质专栏：Audio工程师进阶系列【原创干货持续更新中……】🚀人生格言：人生从来没有捷径，只有行动才是治疗恐惧和懒惰的唯一良药.更多原创,欢迎关注：Android系统攻城狮1.前言本篇目的：C++之

  2. 步步为营，如何将GOlang引用库的安全漏洞修干净

    文章目录引场景构建第一步、直接引用的第三方库升级修复策略1.确认是否为直接引用的第三方库2.找到需要升级的版本是否为release版本第二步、间接引用的第三方库升级修复策略那么问题来了，我们这么间接引用库的对应的直接引用库是哪个呢？（一）没有release版本，但直接引用库有最新的代码可升级（1）将最新代码下载到项目某

  3. Redis 集合（Set）快速指南 | Navicat

    Redis支持通过多种数据类型来存储项目集合。其中，包括列表、集合和哈希。上周的博文介绍了列表（List）数据类型并重点介绍了一些用于管理列表（List）的主要命令。在今天的文章中，我们将转向关注集合（Set）数据类型。在Redis中，集合（Set）与列表（List）相似，但是，集合（Set）中的元素是无序的，并且每个

  4. skywalking入门

    参考：https://www.jianshu.com/p/ffa7ddcda4ab参考：https://developer.aliyun.com/article/1201085skywalking（APM）调用链路分析以及应用监控分析工具Skywalking主要由三大部分组成：agent、collector、webap

  5. 行为型模式-策略模式和责任链模式对比

    一、区别：目的和问题解决方式：策略模式的主要目的是将一组算法或行为封装成独立的策略对象，并使客户端能够在运行时选择其中一个策略来执行。这种模式通常用于实现相同操作的不同算法或策略之间的切换和替换。责任链模式的主要目的是将请求的发送者和接收者解耦，允许多个对象依次处理请求，直到其中一个对象能够处理请求为止。责任链模式通常

  6. opencv dnn模块 示例(16) 目标检测 object_detection 之 yolov4

    博客【opencvdnn模块示例(3)目标检测object_detection(2)YOLOobjectdetection】测试了yolov3及之前系列的模型，有在博客【opencvdnn模块示例(15)opencv4.2版本dnn支持cuda加速（vs2015异常解决）】说明了如何使用dnn模块进行cuda加速推理。

  7. Android 混淆使用及其字典混淆（Proguard）

    1.使用背景ProGuard能够通过压缩、优化、混淆、预检等操作，检测并删除未使用的类,字段,方法和属性，分析和优化字节码，使用简短无意义的名称来重命名类，字段和方法。从而使代码更小、更高效、更难进行逆向工程。Android代码混淆，又称Android混淆，是一种AndroidAPP保护技术，用于保护APP不被破解和逆

  8. css知识学习系列（2）-每天10个知识点

    目录1.基础知识CSS中的伪元素和实际元素有什么区别？2.动画与过渡CSS中的transition和animation有何区别？在什么情况下使用哪种动画？3.Flexbox在Flexbox布局中，“flex-wrap”属性有什么作用？4.Grid请解释CSS中的网格线（gridlines）和轨道（tracks）是什么？

  9. Docker 容器生命周期：创建、启动、暂停与停止

    🌷🍁博主猫头虎带您GotoNewWorld.✨🍁🦄博客首页——猫头虎的博客🎐🐳《面试题大全专栏》文章图文并茂🦕生动形象🦖简单易学！欢迎大家来踩踩~🌺🌊《IDEA开发秘籍专栏》学会IDEA常用操作，工作效率翻倍~💐🌊《100天精通Golang(基础入门篇）》学会Golang语言，畅玩云原生，走遍大