【元数据】FE服务meta源数据一直增长，节点重启回放时间久

starrocker · 2023年07月20日 11:44

为了更快的定位您的问题，请提供以下信息，谢谢
【详述】从2.3.0版本升级到2.5.4/2.5.8版本之后，meta元数据文件夹一直增长。没有降低。
【背景】重启FE节点。
【业务影响】
【StarRocks版本】2.5.4
【集群规模】例如：3fe（3 follower）+3be
【机器信息】CPU虚拟核/内存/网卡，例如：48C/64G/万兆
【联系方式】为了在解决问题过程中能及时联系到您获取一些日志信息，请补充下您的联系方式，例如：社区群4-小李或者邮箱，谢谢
【附件】
3个节点的FE元数据文件夹大小以及文件时间：

jvm配置：
JAVA_OPTS="-Dlog4j2.formatMsgNoLookups=true -Xmx16384m -Xms16384m -XX:+UseMembar -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=7 -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSClassUnloadingEnabled -XX:-CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=80 -XX:SoftRefLRUPolicyMSPerMB=0 -Xloggc:$STARROCKS_HOME/log/fe.gc.log.$DATE"

近期一个月的fe的内存使用情况：

每一次FE重启，日志的回放到好久。一直打印这样的日志：

导致FE服务节点启动缓慢。

dongquan · 2023年07月20日 11:59

看下fe /meta/image下文件的更新时间，可以将fe xmx调大一点，应该是fe meta checkpoint好久没做

starrocker · 2023年07月20日 12:06

这个另外一个集群的，看了下，我们的所有的集群，image的时间都不是最近的时间。fe的jvm的内存的使用率，一定要在60%一下吗？

dongquan · 2023年07月20日 12:25

是的，要不不会触发checkpoint,可以留意下集群中建表是否存在分桶特别多的情况，导致集群整体分桶数特别多。

starrocker · 2023年07月20日 12:30

这个是我们的大集群的：

节点32G内存，分16G给jvm。
images的时间

文件大小：

jvm内存使用率：

gengjun · 2023年07月20日 13:21

应该是checkpoint失败了，在leader的fe.warn.log里搜下 leaderCheckpoint

starrocker · 2023年07月24日 03:42

我们在版本2.5.4的集群上，原先是三节点的FE缩容到单节点，扩容内存到128G。给FE服务配置了60G的内存，目前服务占主机内存40%这样。目前主机内存使用率在43%。FE的堆内存使用率在70%。
但是依旧没有进行checkpoints的操作。
在fe.log日志搜索有提示：
2023-07-24 11:27:09,098 INFO (leaderCheckpointer|144) [Checkpoint.runAfterCatalogReady():82] checkpoint imageVersion 1662303, checkPointVersion 98641645
2023-07-24 11:27:09,098 INFO (leaderCheckpointer|144) [Checkpoint.replayAndGenerateGlobalStateMgrImage():197] begin to generate new image: image.98641645
2023-07-24 11:27:09,099 INFO (tablet checker|45) [TabletChecker.runAfterCatalogReady():187] TStat :

在fe.warn.log中有：
2023-07-24 11:41:32,892 WARN (leaderCheckpointer|144) [TaskManager.replayUpdateTaskRun():546] could not find query_id:e1c3dd3b-1a66-11ee-9810-02421c0e0842, taskId:167943, when replay update pendingTaskRun
2023-07-24 11:41:32,908 WARN (leaderCheckpointer|144) [TaskManager.replayUpdateTaskRun():546] could not find query_id:2fe479ab-1a67-11ee-9810-02421c0e0842, taskId:167943, when replay update pendingTaskRun
2023-07-24 11:41:32,916 WARN (leaderCheckpointer|144) [TaskManager.replayUpdateTaskRun():546] could not find query_id:566c8412-1a67-11ee-9810-02421c0e0842, taskId:167943, when replay update pendingTaskRun

其元数据依旧没有进行checkpoints的操作。文件还是很多。

starrocker · 2023年07月24日 04:32

这个日志是否说明已经在执行checkpoints了。
2023-07-24 12:26:58,990 INFO (leaderCheckpointer|144) [Checkpoint.runAfterCatalogReady():82] checkpoint imageVersion 1662303, checkPointVersion 98641645
2023-07-24 12:26:58,990 INFO (leaderCheckpointer|144) [Checkpoint.replayAndGenerateGlobalStateMgrImage():197] begin to generate new image: image.98641645
2023-07-24 12:26:58,995 INFO (leaderCheckpointer|144) [Auth.grantRoleInternal():779] grant operator to ‘root’@’%’, isReplay = true
2023-07-24 12:26:58,995 INFO (leaderCheckpointer|144) [GlobalStateMgr.loadImage():1261] start load image from /data/server/fe/meta/image/image.1662303. is ckpt: true
2023-07-24 12:26:58,996 INFO (leaderCheckpointer|144) [GlobalStateMgr.loadHeader():1434] finished replay header from image
2023-07-24 12:26:58,997 INFO (leaderCheckpointer|144) [NodeMgr.loadLeaderInfo():1133] finished replay masterInfo from image
2023-07-24 12:26:59,016 INFO (leaderCheckpointer|144) [LocalMetastore.loadDb():331] finished replay databases from image
2023-07-24 12:26:59,017 INFO (leaderCheckpointer|144) [Load.loadLoadJob():986] finished replay loadJob from image
2023-07-24 12:26:59,017 INFO (leaderCheckpointer|144) [GlobalStateMgr.loadAlterJob():1449] finished replay alterJob from image
2023-07-24 12:26:59,017 INFO (leaderCheckpointer|144) [CatalogRecycleBin.loadRecycleBin():1148] finished replay recycleBin from image
2023-07-24 12:26:59,018 INFO (leaderCheckpointer|144) [VariableMgr.loadGlobalVariable():559] finished replay globalVariable from image
2023-07-24 12:26:59,018 INFO (leaderCheckpointer|144) [LocalMetastore.loadCluster():4308] finished replay cluster from image
2023-07-24 12:26:59,018 INFO (leaderCheckpointer|144) [NodeMgr.loadBrokers():1101] finished replay brokerMgr from image
2023-07-24 12:26:59,018 INFO (leaderCheckpointer|144) [GlobalStateMgr.loadResources():1536] finished replay resources from image
2023-07-24 12:26:59,018 INFO (leaderCheckpointer|144) [GlobalStateMgr.loadResources():1538] start to replay resource mapping catalog
2023-07-24 12:26:59,018 INFO (leaderCheckpointer|144) [GlobalStateMgr.loadResources():1540] finished replaying resource mapping catalogs from resources
2023-07-24 12:26:59,018 INFO (leaderCheckpointer|144) [ExportMgr.loadExportJob():385] finished replay exportJob from image
2023-07-24 12:26:59,018 INFO (leaderCheckpointer|144) [BackupHandler.readFields():673] finished replay 0 backup/store jobs from image
2023-07-24 12:26:59,018 INFO (leaderCheckpointer|144) [BackupHandler.loadBackupHandler():686] finished replay backupHandler from image
2023-07-24 12:26:59,019 INFO (leaderCheckpointer|144) [Auth.loadAuth():1890] finished replay auth from image

但是bdb的文件依旧没有减少。目前image文件夹内：
-rw-rw-r-- 1 1000 1000 951M Apr 27 09:28 image.1662303
-rw-r–r-- 1 1000 1000 3.5M Jul 24 12:25 image.ckpt
-rw-rw-r-- 1 1000 1000 91 Jul 24 11:27 ROLE
-rw-rw-r-- 1 1000 1000 93 Apr 27 09:27 VERSION
image文件没有更新。bdb文件持续上升。

Doni · 2023年07月24日 06:20

这个内容后面还有啥日志么

starrocker · 2023年07月24日 06:33

2023-07-24 14:26:42,385 INFO (leaderCheckpointer|144) [BackupHandler.readFields():673] finished replay 0 backup/store jobs from image
2023-07-24 14:26:42,385 INFO (leaderCheckpointer|144) [BackupHandler.loadBackupHandler():686] finished replay backupHandler from image
2023-07-24 14:26:42,386 INFO (leaderCheckpointer|144) [Auth.loadAuth():1890] finished replay auth from image
2023-07-24 14:26:42,386 INFO (leaderCheckpointer|144) [GlobalTransactionMgr.readFields():711] discard expired transaction state: TransactionState. txn_id: 13404, label: insert_83603d17-daa3-11ed-9f1b-0242ffa99e51, db id: 10002, table id list: 10530, callback id: -1, coordinator: FE: 10.9.2.217, transaction status: VISIBLE, error replicas num: 0, replica ids: , prepare time: 1681463133701, commit time: 1681463133729, finish time: 1681463133743, write cost: 28ms, publish total cost: 14ms, total cost: 42ms, reason: attachment: com.starrocks.transaction.InsertTxnCommitAttachment@45bff2d4
2023-07-24 14:26:42,386 INFO (leaderCheckpointer|144) [GlobalTransactionMgr.readFields():711] discard expired transaction state: TransactionState. txn_id: 13405, label: insert_8368a188-daa3-11ed-9f1b-0242ffa99e51, db id: 10002, table id list: 10530, callback id: -1, coordinator: FE: 10.9.2.217, transaction status: VISIBLE, error replicas num: 0, replica ids: , prepare time: 1681463133757, commit time: 1681463133777, finish time: 1681463133791, write cost: 20ms, publish total cost: 14ms, total cost: 34ms, reason: attachment: com.starrocks.transaction.InsertTxnCommitAttachment@1a2d201a
2023-07-24 14:26:42,386 INFO (leaderCheckpointer|144) [GlobalTransactionMgr.readFields():711] discard expired transaction state: TransactionState. txn_id: 13406, label: insert_836ff489-daa3-11ed-9f1b-0242ffa99e51, db id: 10002, table id list: 10530, callback id: -1, coordinator: FE: 10.9.2.217, transaction status: VISIBLE, error replicas num: 0, replica ids: , prepare time: 1681463133804, commit time: 1681463133825, finish time: 1681463133839, write cost: 21ms, publish total cost: 14ms, total cost: 35ms, reason: attachment: com.starrocks.transaction.InsertTxnCommitAttachment@405aa875

不断打印expired transaction state这个。

starrocker · 2023年07月24日 06:47

10.9.2.217这些节点是已经下线drop掉了的。目前只有一个FE节点。

gengjun · 2023年07月25日 02:57

fe.warn能发下文件吗

starrocker · 2023年07月25日 03:00

fe.warn.log.tar.gz (11.9 MB)
我们目前已经调试到90G的jvm内存了。设置启动参数：
JAVA_OPTS="-Dlog4j2.formatMsgNoLookups=true -Xmx90g -XX:+UseMembar -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=7 -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSClassUnloadingEnabled -XX:-CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=80 -XX:SoftRefLRUPolicyMSPerMB=0 -Xloggc:$STARROCKS_HOME/log/fe.gc.log.$DATE"
但是启动起来之后，jvm的内存就到了50%多了。但是集群其实没有大的请求进来的。

gengjun · 2023年07月25日 03:26

fe.log发下吧再

gengjun · 2023年07月25日 03:31

不用发了，找到原因了

starrocker · 2023年07月25日 03:31

fe.log.tar.gz (13.3 MB)
目前jvm的堆内存使用率在50这样了：

gengjun · 2023年07月25日 03:31

2023-07-25 00:13:29,592 ERROR (leaderCheckpointer|144) [Daemon.run():117] daemon thread got exception. name: leaderCheckpointer
java.lang.OutOfMemoryError: null
at java.lang.AbstractStringBuilder.hugeCapacity(AbstractStringBuilder.java:161) ~[?:1.8.0_291]
at java.lang.AbstractStringBuilder.newCapacity(AbstractStringBuilder.java:155) ~[?:1.8.0_291]
at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:125) ~[?:1.8.0_291]
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:448) ~[?:1.8.0_291]
at java.lang.StringBuffer.append(StringBuffer.java:270) ~[?:1.8.0_291]
at java.io.StringWriter.write(StringWriter.java:112) ~[?:1.8.0_291]
at com.google.gson.stream.JsonWriter.string(JsonWriter.java:584) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.stream.JsonWriter.value(JsonWriter.java:418) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.internal.bind.TypeAdapters$15.write(TypeAdapters.java:384) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.internal.bind.TypeAdapters$15.write(TypeAdapters.java:368) ~[spark-dpp-1.0.0.jar:?]
at com.starrocks.persist.gson.GsonUtils$ProcessHookTypeAdapterFactory$1.write(GsonUtils.java:503) ~[starrocks-fe.jar:?]
at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.write(TypeAdapterRuntimeTypeWrapper.java:69) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.write(ReflectiveTypeAdapterFactory.java:127) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.write(ReflectiveTypeAdapterFactory.java:245) ~[spark-dpp-1.0.0.jar:?]
at com.starrocks.persist.gson.GsonUtils$ProcessHookTypeAdapterFactory$1.write(GsonUtils.java:503) ~[starrocks-fe.jar:?]
at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.write(TypeAdapterRuntimeTypeWrapper.java:69) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.write(CollectionTypeAdapterFactory.java:97) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.internal.bind.CollectionTypeAdapterFactory$Adapter.write(CollectionTypeAdapterFactory.java:61) ~[spark-dpp-1.0.0.jar:?]
at com.starrocks.persist.gson.GsonUtils$ProcessHookTypeAdapterFactory$1.write(GsonUtils.java:503) ~[starrocks-fe.jar:?]
at com.google.gson.internal.bind.TypeAdapterRuntimeTypeWrapper.write(TypeAdapterRuntimeTypeWrapper.java:69) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$1.write(ReflectiveTypeAdapterFactory.java:127) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.internal.bind.ReflectiveTypeAdapterFactory$Adapter.write(ReflectiveTypeAdapterFactory.java:245) ~[spark-dpp-1.0.0.jar:?]
at com.starrocks.persist.gson.GsonUtils$ProcessHookTypeAdapterFactory$1.write(GsonUtils.java:503) ~[starrocks-fe.jar:?]
at com.google.gson.Gson.toJson(Gson.java:735) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.Gson.toJson(Gson.java:714) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.Gson.toJson(Gson.java:669) ~[spark-dpp-1.0.0.jar:?]
at com.google.gson.Gson.toJson(Gson.java:649) ~[spark-dpp-1.0.0.jar:?]
at com.starrocks.scheduler.TaskManager.saveTasks(TaskManager.java:453) ~[starrocks-fe.jar:?]
at com.starrocks.server.GlobalStateMgr.saveImage(GlobalStateMgr.java:1617) ~[starrocks-fe.jar:?]
at com.starrocks.server.GlobalStateMgr.saveImage(GlobalStateMgr.java:1568) ~[starrocks-fe.jar:?]
at com.starrocks.leader.Checkpoint.replayAndGenerateGlobalStateMgrImage(Checkpoint.java:204) ~[starrocks-fe.jar:?]
at com.starrocks.leader.Checkpoint.runAfterCatalogReady(Checkpoint.java:93) ~[starrocks-fe.jar:?]
at com.starrocks.common.util.LeaderDaemon.runOneCycle(LeaderDaemon.java:60) ~[starrocks-fe.jar:?]
at com.starrocks.common.util.Daemon.run(Daemon.java:115) [starrocks-fe.jar:?]

gengjun · 2023年07月25日 03:32

现在的版本是2.5.8哈？

starrocker · 2023年07月25日 03:32

[quote=“gengjun, post:17, topic:7976”]
OutOfMemoryError
[/quote]是2.5.4版本。

gengjun · 2023年07月25日 03:33

升级到2.5.8试试，这个问题修复过了