Bifromq 3.2.2 集群情况下 OOM （[Gossiper.java:137] Too many elapsed periods, sweep gossips in advance, currentPeriod=1712447, elapsedPeriod=130）
xiaonannet opened this issue · 25 comments
Describe the bug
构建集群各节点输出构建成功日志，集成了认证插件（插件其他环境正常在用的），验证功能正常可正常链接。跑了1天左右3个节点挂了。
可疑的是warn.log 中各节点都在输出：
2024-08-20 08:00:22.238 WARN [agent-host-scheduler] --- c.b.b.basecluster.messenger.Gossiper [Gossiper.java:137] Too many elapsed periods, sweep gossips in advance, currentPeriod=1712447, elapsedPeriod=130
2024-08-20 08:01:18.799 WARN [agent-host-scheduler] --- c.b.b.basecluster.messenger.Gossiper [Gossiper.java:137] Too many elapsed periods, sweep gossips in advance, currentPeriod=1712578, elapsedPeriod=282
Environment
- Version: [e.g. 3.2.x We highly recommend you to verify your issue using the latest version first.]
- JVM Version: [e.g. OpenJDK17]
- Hardware Spec: [e.g. 4C16G, 1Gbps NIC]
- OS: [CentOS Linux release 7.9.2009 (Core)
Docker version 26.1.4, build 5650f9b] - The Testing Tools
- etc
Reproducible Steps
- 拉取官方 Docker 3.2.2版本
master:
node1：
node2：
- 配置各节点的standalone.yml （以上截图中的ip均需要换成自己的实际服务器ip）
docker run -d -m 10G -e JVM_HEAP_OPTS='-Xms2G -Xmx4G -XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=500m -XX:MaxDirectMemorySize=1G'
--name bifromq
--network host
-v /data01/mqttsnet/bifromq/conf/standalone.yml:/home/bifromq/conf/standalone.yml
bifromq/bifromq:3.2.2
host模式直接跑，各节点所用到的端口防火墙均已开放！
然后观测日志，info显示各个节点的构建日志，3个节点均成功，warn应该这时就会有关于
Gossiper 的告警信息。
内存占用一直上升，最后挂掉。
Publicly Accessible Diagnostic Data(If Reproducible Steps are not available)
docker 守护进程日志：
efbd9ab1d07ab7d3e6f62acc3d77225073a537f3f0f0b5695f579d62826ad712-json.log
Additional context
Add any other context about the problem here.
按照Issue模板要求补充下你的Reproduce Steps？为了定位问题准确，复现环境不要包含自定义的插件。
另外，你提供的日志显示每个节点只有2C，如此受限的配置下会影响GC。
2024-08-20 11:51:17.024 INFO [main] --- c.b.bifromq.starter.StandaloneStarter [StandaloneStarter.java:626] Available Processors: 2
2024-08-20 11:51:17.034 INFO [main] --- c.b.bifromq.starter.StandaloneStarter [StandaloneStarter.java:628] JVM arguments:
-Xms1G
-Xmx4G
-XX:MetaspaceSize=64m
-XX:MaxMetaspaceSize=512m
-XX:MaxDirectMemorySize=512M
按照Issue模板要求补充下你的Reproduce Steps？为了定位问题准确，复现环境不要包含自定义的插件。
另外，你提供的日志显示每个节点只有2C，如此受限的配置下会影响GC。
2024-08-20 11:51:17.024 INFO [main] --- c.b.bifromq.starter.StandaloneStarter [StandaloneStarter.java:626] Available Processors: 2
2024-08-20 11:51:17.034 INFO [main] --- c.b.bifromq.starter.StandaloneStarter [StandaloneStarter.java:628] JVM arguments:
-Xms1G
-Xmx4G
-XX:MetaspaceSize=64m
-XX:MaxMetaspaceSize=512m
-XX:MaxDirectMemorySize=512M
已补充，每个节点2G，初始化情况下应该是够用的，因为没有任何的连接和业务操作，空跑的状态。现在的问题在于集群为啥一直有Gossiper 的错误
版本重新换回Docker 3.0.2版本，启动正常。相同的操作步骤换 3.2.2 内存也会不断增加，从节点不可以链接，引导节点可以
按你给的条件没法复现你的问题，3.2.2版本 2C4G docker host network组成的集群，即便是有压力的情况也依然运行正常。
从你的日志看集群地址跟你配置文件不一致，内存表现上大量内存被RPC对象占据，说明有业务压力。
2024-08-20 11:54:28.618 INFO [ForkJoinPool.commonPool-worker-1] --- c.b.bifromq.starter.StandaloneStarter [StandaloneStarter.java:688] AgentHost joined seedEndpoint: [/192.168.0.38:18899, /192.168.0.28:18899, /192.168.0.48:18899]
建议： 换一个cluster.env，用物理机组建干净的集群尝试复现问题
较高配置宿主机安装3.2.2(ssl)，3节点集群，完全空跑下仍占用极高内存：logs/gc-2024-08-26_18-40-24.log
[2024-08-27T10:24:12.363+0800][2302][gc] GC(1174) Garbage Collection (Allocation Stall) 22408M(100%)->22320M(100%)
全部日志打包
logs_____node42.tgz
standalone.yml见:
standalone.tgz
目录结构../bifromq-3.2.2
├── bin
│ ├── bifromq-start.sh
│ ├── bifromq-stop.sh
│ └── standalone.sh
├── conf
│ ├── logback.xml
│ ├── ssl
│ ├── standalone.yml
│ └── standalone.yml_orig
├── data
├── lib
├── logs
│ ├── basekv
│ ├── debug.log
│ ├── error.2024-08-27_00.log
│ ├── error.2024-08-27_02.log
│ ├── error.2024-08-27_05.log
│ ├── error.log
│ ├── event.log
│ ├── gc-2024-08-26_18-40-24.log
│ ├── info.log
│ ├── plugin.log
│ ├── stdout.log
│ ├── trace.log
│ ├── warn.2024-08-27_03.log
│ ├── warn.2024-08-27_04.log
│ ├── warn.2024-08-27_05.log
│ ├── warn.2024-08-27_06.log
│ ├── warn.2024-08-27_07.log
│ ├── warn.2024-08-27_08.log
│ ├── warn.2024-08-27_09.log
│ └── warn.log
└── plugins
├── bifromq-plugin-3.2.2-SNAPSHOT.jar
└── README.md
ps -eo rss,pmem,pcpu,vsize,args | sort -k 1 -r -n | less
69830812 99.9 213 1115864288 ...jdk-17.0.3.1/bin/java -Xms11203m -Xmx22407m -XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=500m -XX:MaxDirectMemorySize=6713219480 -server -XX:MaxInlineLevel=15 -Djava.awt.headless=true -XX:+UnlockExperimentalVMOptions -XX:+UnlockDiagnosticVMOptions -XX:+UseZGC -XX:ZAllocationSpikeTolerance=5 -Xlog:async -Xlog:gc:file=/ws/app/bifromq-3.2.2/bin/../logs/gc-%t.log:time,tid,tags:filecount=5,filesize=50m -XX:+CrashOnOutOfMemoryError -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/ws/app/bifromq-3.2.2/bin/../logs -Dio.netty.tryReflectionSetAccessible=true -Dio.netty.allocator.cacheTrimIntervalMillis=5000 --add-opens java.base/java.nio=ALL-UNNAMED -cp /ws/app/bifromq-3.2.2/bin/../lib/* -DLOG_DIR=/ws/app/bifromq-3.2.2/bin/../logs -DCONF_DIR=/ws/app/bifromq-3.2.2/bin/../conf -DDATA_DIR=/ws/app/bifromq-3.2.2/bin/../data -DBIND_ADDR=172.17.0.1 -Dlogback.configurationFile=/ws/app/bifromq-3.2.2/bin/../conf/logback.xml -Dpf4j.pluginsDir=/ws/app/bifromq-3.2.2/bin/../plugins com.baidu.bifromq.starter.StandaloneStarter -c /ws/app/bifromq-3.2.2/bin/../conf/standalone.yml
info.log里生效的配置显示，内部rpc server发现了与传入集群配置不同的地址，不确定这个地址在集群间是否有连通性问题。
rpcServerConfig:
host: "172.17.0.1"
port: 0
workerThreads: null
sslConfig: null
baseKVClientConfig:
workerThreads: 2
sslConfig: null
baseKVServerConfig:
host: "172.17.0.1"
port: 0
workerThreads: 4
sslConfig: null
你可以把日志调成debug或trace看下有什么输出，或者remote debug尝试定位内存增长的路径。
info.log里生效的配置显示，内部rpc server发现了与传入集群配置不同的地址，不确定这个地址在集群间是否有连通性问题。
rpcServerConfig:
host: "172.17.0.1"
port: 0
workerThreads: null
sslConfig: null
baseKVClientConfig:
workerThreads: 2
sslConfig: null
baseKVServerConfig:
host: "172.17.0.1"
port: 0
workerThreads: 4
sslConfig: null你可以把日志调成debug或trace看下有什么输出，或者remote debug尝试定位内存增长的路径。
standalone.yml 上面贴了，没搜到IP： host: "172.17.0.1"
帮忙看下是配置哪里不对？
对3节点集群部署(tls，宿主机&docker两模式)，能不能提供个完整配置参考？
光看各项说明，吃不准对不对
较高配置宿主机安装3.2.2(ssl)，3节点集群，完全空跑下仍占用极高内存：logs/gc-2024-08-26_18-40-24.log [2024-08-27T10:24:12.363+0800][2302][gc] GC(1174) Garbage Collection (Allocation Stall) 22408M(100%)->22320M(100%) 全部日志打包 logs_____node42.tgz standalone.yml见: standalone.tgz
你的环境里有多个NetworkInterface，需要在standalone.yml配置文件里把这两个内部的server地址明确指定下，不然发现的是错误的docker bridge地址172.17.0.1：
rpcServerConfig:
host: 192.168.0.42
baseKVServerConfig:
host: 192.168.0.42较高配置宿主机安装3.2.2(ssl)，3节点集群，完全空跑下仍占用极高内存：logs/gc-2024-08-26_18-40-24.log [2024-08-27T10:24:12.363+0800][2302][gc] GC(1174) Garbage Collection (Allocation Stall) 22408M(100%)->22320M(100%) 全部日志打包 logs_____node42.tgz standalone.yml见: standalone.tgz
你的环境里有多个NetworkInterface，需要在standalone.yml配置文件里把这两个内部的server地址明确指定下，不然发现的是错误的docker bridge地址172.17.0.1：
rpcServerConfig: host: 192.168.0.42 baseKVServerConfig: host: 192.168.0.42
我是3台宿主机部署的集群，standalone.yml补充这几个我再监视下
较高配置宿主机安装3.2.2(ssl)，3节点集群，完全空跑下仍占用极高内存：logs/gc-2024-08-26_18-40-24.log [2024-08-27T10:24:12.363+0800][2302][gc] GC(1174) Garbage Collection (Allocation Stall) 22408M(100%)->22320M(100%) 全部日志打包 logs_____node42.tgz standalone.yml见: standalone.tgz
你的环境里有多个NetworkInterface，需要在standalone.yml配置文件里把这两个内部的server地址明确指定下，不然发现的是错误的docker bridge地址172.17.0.1：
rpcServerConfig: host: 192.168.0.42 baseKVServerConfig: host: 192.168.0.42我是3台宿主机部署的集群，standalone.yml补充这几个我再监视下
增加了配置还是老样，info.log仍然出现： -DBIND_ADDR=172.17.0.1
warn.log仍然：2024-08-28 19:03:02.321 WARN [agent-host-scheduler] --- c.b.b.basecluster.messenger.Gossiper [Gossiper.java:143] Some gossips are too old to spread, confirm gossips in advance, currentPeriod=51561, elapsedPeriod=12
你们能不能提供下验证ok的配置文件？
standalone.yml文件内容会优先于-DBIND_ADDR=172.17.0.1，你确认下info.log里输出的最终生效的全量yaml内容中这两个地址是否正确，如果地址正确的情况下你说的内存问题有没有解决？
配置文件要根据你的部署环境的配置，我们测试就是用的默认配置，没有全量不全量的说法。
standalone.yml文件内容会优先于-DBIND_ADDR=172.17.0.1，你确认下info.log里输出的最终生效的全量yaml内容中这两个地址是否正确，如果地址正确的情况下你说的内存问题有没有解决？ 配置文件要根据你的部署环境的配置，我们测试就是用的默认配置，没有全量不全量的说法。
我把这个节点的logs目录打包： logs.tgz
info.log最开始打印172....后面无；
warn.log一直 [Gossiper.java:137] Too many elapsed periods, sweep。。。
gc-2024-08-28_16-11-10.log: [2024-08-28T22:44:04.995+0800][20353][gc] GC(594) Garbage Collection (Allocation Rate) 20006M(89%)->20186M(90%)
你把"com.baidu.bifromq"日志调到debug level，三个节点的日志全部传上来
昨天跑的其中1台冒出个文件：69G Aug 29 07:33 core.5611
刚把debug打开，debug文件很快几十G，狂报：
2024-08-29 09:55:11.942 DEBUG [basekv-client-executor] � c.b.b.baserpc.ManagedRequestPipeline [ManagedRequestPipeline.java:489] ReqPipeline@1985172618 of linearizedQuery internal stream@1245593290 error: state=Normal
io.grpc.StatusRuntimeException: UNAVAILABLE: server is unreachable now
at io.grpc.Status.asRuntimeException(Status.java:539)
at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:487)
at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:576)
at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:70)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:757)
at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:736)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
at io.micrometer.core.instrument.internal.TimedRunnable.run(TimedRunnable.java:49)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.base/java.lang.Thread.run(Thread.java:833)
2024-08-29 09:55:11.942 DEBUG [basekv-client-executor-1] � c.b.b.baserpc.ManagedRequestPipeline [ManagedRequestPipeline.java:127] ReqPipeline@596737142 of linearizedQuery targeting to server[668d7250-20ac-4a24-9dce-b03c75c68636/1128733310]
3台机器firewall开启，但clusterConfig.port: 28899打开了互通的。
info.log里生效的配置显示，内部rpc server发现了与传入集群配置不同的地址，不确定这个地址在集群间是否有连通性问题。
rpcServerConfig:
host: "172.17.0.1"
port: 0
workerThreads: null
sslConfig: null
baseKVClientConfig:
workerThreads: 2
sslConfig: null
baseKVServerConfig:
host: "172.17.0.1"
port: 0
workerThreads: 4
sslConfig: null你可以把日志调成debug或trace看下有什么输出，或者remote debug尝试定位内存增长的路径。
standalone.yml 上面贴了，没搜到IP： host: "172.17.0.1" 帮忙看下是配置哪里不对？
你打开的是集群通信端口，不是rpc server的端口。文档里说的很清楚，port: 0会随机选择可用端口，你能确认这个ip的随机端口全部放行了？
https://bifromq.io/docs/admin_guide/configuration/config_file_manual/
不是rpc server的端口。文档里说的很清楚，port: 0会随机选择可用端口:
我在conf/standalone.yml已经设置了clusterConfig.port: 28899 ，还会其他随机端口？这样也必须firewall全部关闭？
rpcServerConfig.port可以指定端口，firewall添加放行？
你在回复前能仔细看下文档吗？如果不愿意看文档可以考虑付费一对一咨询
baseKVServerConfig.port官方文档根本没提及