存算分离集群3.2.8升级3.3后slow lock量明显上升

[starrocks搬运工]

flink导入过程中，streamLoadPlanMs耗时上升明显。

查看fe日志

同时warn日志中大量slow lock

2024-07-03 08:19:23.639Z WARN (thrift-server-pool-106349|120725) [LockManager.logSlowLockTrace():398] LockManager detects slow lock : {"owners":[{"id":88782,"name":"thrift-server-pool-75227","heldFor":7766839,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88602,"name":"thrift-server-pool-75092","heldFor":7763295,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88752,"name":"thrift-server-pool-75197","heldFor":7766946,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":2510,"name":"thrift-server-pool-1621","heldFor":7766952,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":3277,"name":"thrift-server-pool-2152","heldFor":7766945,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88756,"name":"thrift-server-pool-75201","heldFor":7766794,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88121,"name":"thrift-server-pool-74745","heldFor":7766826,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":3313,"name":"thrift-server-pool-2188","heldFor":7766925,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":87095,"name":"thrift-server-pool-74122","heldFor":7766939,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":3843,"name":"thrift-server-pool-2640","heldFor":7766837,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88028,"name":"thrift-server-pool-74670","heldFor":7766948,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":2915,"name":"thrift-server-pool-1899","heldFor":7766940,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88860,"name":"thrift-server-pool-75295","heldFor":7766847,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88815,"name":"thrift-server-pool-75254","heldFor":7765132,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88799,"name":"thrift-server-pool-75238","heldFor":7766938,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":737,"name":"thrift-server-pool-213","heldFor":7766952,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88803,"name":"thrift-server-pool-75242","heldFor":7766849,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88841,"name":"thrift-server-pool-75278","heldFor":7766950,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":88873,"name":"thrift-server-pool-75308","heldFor":7766796,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]},{"id":59129,"name":"thrift-server-pool-53580","heldFor":7766851,"waitTime":0,"stack":["all stack frames trimmed, trimHeadLevels: 0"]}],"waiter":[{"id":39,"name":"tablet stat mgr","heldFor":"","waitTime":7761043,"locker":"TabletStatMgr.createPartitionSnapshot():250"},{"id":88949,"name":"starrocks-mysql-nio-pool-86","heldFor":"","waitTime":7759920,"locker":"PlannerMetaLocker.lock():106"},{"id":87301,"name":"thrift-server-pool-74226","heldFor":"","waitTime":7759519,"locker":"LocalMetastore.addPartitions():868"},{"id":604,"name":"autovacuum-pool1-t7","heldFor":"","waitTime":7759146,"locker":"AutovacuumDaemon.vacuumPartitionImpl():133"},{"id":88522,"name":"thrift-server-pool-75022","heldFor":"","waitTime":7758225,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":88889,"name":"lake-publish-task-12255","heldFor":"","waitTime":7757863,"locker":"DatabaseTransactionMgr.finishTransaction():1011"},{"id":88945,"name":"lake-publish-task-12283","heldFor":"","waitTime":7757468,"locker":"DatabaseTransactionMgr.finishTransaction():1011"},{"id":88901,"name":"lake-publish-task-12259","heldFor":"","waitTime":7756761,"locker":"DatabaseTransactionMgr.finishTransaction():1011"},{"id":36,"name":"AutoStatistic","heldFor":"","waitTime":7756523,"locker":"PlannerMetaLocker.lock():106"},{"id":113,"name":"COMPACTION_DISPATCH","heldFor":"","waitTime":7746095,"locker":"MetaUtils.isPartitionExist():277"},{"id":590,"name":"autovacuum-pool1-t3","heldFor":"","waitTime":7744313,"locker":"AutovacuumDaemon.vacuumPartitionImpl():133"},{"id":603,"name":"autovacuum-pool1-t6","heldFor":"","waitTime":7743647,"locker":"AutovacuumDaemon.vacuumPartitionImpl():133"},{"id":605,"name":"autovacuum-pool1-t8","heldFor":"","waitTime":7743519,"locker":"AutovacuumDaemon.vacuumPartitionImpl():133"},{"id":592,"name":"autovacuum-pool1-t5","heldFor":"","waitTime":7741207,"locker":"AutovacuumDaemon.vacuumPartitionImpl():133"},{"id":591,"name":"autovacuum-pool1-t4","heldFor":"","waitTime":7734530,"locker":"AutovacuumDaemon.vacuumPartitionImpl():133"},{"id":589,"name":"autovacuum-pool1-t2","heldFor":"","waitTime":7733645,"locker":"AutovacuumDaemon.vacuumPartitionImpl():133"},{"id":89003,"name":"thrift-server-pool-75407","heldFor":"","waitTime":7732637,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":588,"name":"autovacuum-pool1-t1","heldFor":"","waitTime":7731180,"locker":"AutovacuumDaemon.vacuumPartitionImpl():133"},{"id":3292,"name":"thrift-server-pool-2167","heldFor":"","waitTime":7729881,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":89119,"name":"lake-publish-task-12284","heldFor":"","waitTime":7720093,"locker":"PublishVersionDaemon.publishPartition():769"},{"id":89120,"name":"lake-publish-task-12285","heldFor":"","waitTime":7720093,"locker":"PublishVersionDaemon.publishPartition():769"},{"id":88519,"name":"thrift-server-pool-75019","heldFor":"","waitTime":7706877,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":3873,"name":"thrift-server-pool-2670","heldFor":"","waitTime":7706841,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":34,"name":"UpdateDbUsedDataQuota","heldFor":"","waitTime":7500221,"locker":"Database.getUsedDataQuotaWithLock():219"},{"id":54,"name":"DynamicPartitionScheduler","heldFor":"","waitTime":7232652,"locker":"DynamicPartitionScheduler.findSchedulableTables():693"},{"id":91279,"name":"thrift-server-pool-77678","heldFor":"","waitTime":7173097,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":92171,"name":"thrift-server-pool-78569","heldFor":"","waitTime":6956766,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":92732,"name":"starrocks-mysql-nio-pool-88","heldFor":"","waitTime":6950583,"locker":"PlannerMetaLocker.lock():106"},{"id":92782,"name":"starrocks-mysql-nio-pool-89","heldFor":"","waitTime":6939316,"locker":"PlannerMetaLocker.lock():106"},{"id":92789,"name":"starrocks-mysql-nio-pool-90","heldFor":"","waitTime":6936920,"locker":"PlannerMetaLocker.lock():106"},{"id":954,"name":"thrift-server-pool-415","heldFor":"","waitTime":6916282,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":89018,"name":"thrift-server-pool-75422","heldFor":"","waitTime":6507899,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":95735,"name":"thrift-server-pool-82113","heldFor":"","waitTime":6262097,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":89563,"name":"thrift-server-pool-75963","heldFor":"","waitTime":6222221,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":96069,"name":"thrift-server-pool-82446","heldFor":"","waitTime":6218942,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":96081,"name":"starrocks-mysql-nio-pool-95","heldFor":"","waitTime":6200630,"locker":"PlannerMetaLocker.lock():106"},{"id":96732,"name":"starrocks-mysql-nio-pool-96","heldFor":"","waitTime":6075624,"locker":"PlannerMetaLocker.lock():106"},{"id":91730,"name":"thrift-server-pool-78128","heldFor":"","waitTime":5930178,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":96871,"name":"thrift-server-pool-83234","heldFor":"","waitTime":5877107,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":96959,"name":"thrift-server-pool-83322","heldFor":"","waitTime":5654239,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":98215,"name":"thrift-server-pool-84570","heldFor":"","waitTime":5634771,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":98482,"name":"starrocks-mysql-nio-pool-97","heldFor":"","waitTime":5609961,"locker":"PlannerMetaLocker.lock():106"},{"id":98746,"name":"thrift-server-pool-85099","heldFor":"","waitTime":5267205,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":100229,"name":"starrocks-mysql-nio-pool-98","heldFor":"","waitTime":5205229,"locker":"PlannerMetaLocker.lock():106"},{"id":88509,"name":"thrift-server-pool-75011","heldFor":"","waitTime":5050979,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":100732,"name":"thrift-server-pool-87079","heldFor":"","waitTime":4877550,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":102873,"name":"thrift-server-pool-89212","heldFor":"","waitTime":4637269,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":90829,"name":"thrift-server-pool-77229","heldFor":"","waitTime":4455342,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":104999,"name":"thrift-server-pool-91332","heldFor":"","waitTime":4246027,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":97765,"name":"thrift-server-pool-84121","heldFor":"","waitTime":3997576,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":4241,"name":"thrift-server-pool-3023","heldFor":"","waitTime":3950637,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":679,"name":"thrift-server-pool-169","heldFor":"","waitTime":3918079,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":3262,"name":"thrift-server-pool-2137","heldFor":"","waitTime":3806064,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":96507,"name":"thrift-server-pool-82882","heldFor":"","waitTime":3780026,"locker":"FrontendServiceImpl.describeTable():986"},{"id":107866,"name":"thrift-server-pool-94183","heldFor":"","waitTime":3749668,"locker":"FrontendServiceImpl.describeTable():986"},{"id":78618,"name":"thrift-server-pool-68246","heldFor":"","waitTime":3602051,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":109041,"name":"thrift-server-pool-95356","heldFor":"","waitTime":3510380,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":109861,"name":"lake-publish-task-12286","heldFor":"","waitTime":3370049,"locker":"PublishVersionDaemon.publishPartition():769"},{"id":107900,"name":"thrift-server-pool-94217","heldFor":"","waitTime":3256368,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":110195,"name":"thrift-server-pool-96504","heldFor":"","waitTime":3204392,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":112240,"name":"thrift-server-pool-98537","heldFor":"","waitTime":2907153,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":111692,"name":"thrift-server-pool-97990","heldFor":"","waitTime":2895819,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":112593,"name":"starrocks-mysql-nio-pool-107","heldFor":"","waitTime":2858106,"locker":"PlannerMetaLocker.lock():106"},{"id":97438,"name":"thrift-server-pool-83797","heldFor":"","waitTime":2725758,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":3289,"name":"thrift-server-pool-2164","heldFor":"","waitTime":2497910,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":114026,"name":"thrift-server-pool-100318","heldFor":"","waitTime":2469705,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":1046,"name":"thrift-server-pool-473","heldFor":"","waitTime":2212408,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":115167,"name":"thrift-server-pool-101450","heldFor":"","waitTime":2058985,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":115765,"name":"starrocks-mysql-nio-pool-109","heldFor":"","waitTime":1922026,"locker":"PlannerMetaLocker.lock():106"},{"id":115770,"name":"starrocks-mysql-nio-pool-110","heldFor":"","waitTime":1913001,"locker":"PlannerMetaLocker.lock():106"},{"id":115772,"name":"starrocks-mysql-nio-pool-111","heldFor":"","waitTime":1911890,"locker":"PlannerMetaLocker.lock():106"},{"id":115858,"name":"starrocks-mysql-nio-pool-112","heldFor":"","waitTime":1814982,"locker":"PlannerMetaLocker.lock():106"},{"id":116478,"name":"starrocks-mysql-nio-pool-113","heldFor":"","waitTime":1784129,"locker":"PlannerMetaLocker.lock():106"},{"id":116217,"name":"thrift-server-pool-102401","heldFor":"","waitTime":1778126,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":116496,"name":"starrocks-mysql-nio-pool-114","heldFor":"","waitTime":1775465,"locker":"PlannerMetaLocker.lock():106"},{"id":116518,"name":"starrocks-mysql-nio-pool-115","heldFor":"","waitTime":1763936,"locker":"PlannerMetaLocker.lock():106"},{"id":116524,"name":"starrocks-mysql-nio-pool-116","heldFor":"","waitTime":1760511,"locker":"PlannerMetaLocker.lock():106"},{"id":116561,"name":"starrocks-mysql-nio-pool-117","heldFor":"","waitTime":1738457,"locker":"PlannerMetaLocker.lock():106"},{"id":116213,"name":"thrift-server-pool-102397","heldFor":"","waitTime":1663585,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":116451,"name":"thrift-server-pool-102452","heldFor":"","waitTime":1396981,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":116042,"name":"thrift-server-pool-102257","heldFor":"","waitTime":1387385,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":117675,"name":"starrocks-mysql-nio-pool-121","heldFor":"","waitTime":1137209,"locker":"PlannerMetaLocker.lock():106"},{"id":117876,"name":"starrocks-mysql-nio-pool-122","heldFor":"","waitTime":1037217,"locker":"PlannerMetaLocker.lock():106"},{"id":116678,"name":"thrift-server-pool-102671","heldFor":"","waitTime":1020150,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":118162,"name":"starrocks-mysql-nio-pool-123","heldFor":"","waitTime":883193,"locker":"PlannerMetaLocker.lock():106"},{"id":118180,"name":"starrocks-mysql-nio-pool-124","heldFor":"","waitTime":875640,"locker":"PlannerMetaLocker.lock():106"},{"id":118239,"name":"starrocks-mysql-nio-pool-125","heldFor":"","waitTime":834434,"locker":"PlannerMetaLocker.lock():106"},{"id":118273,"name":"starrocks-mysql-nio-pool-126","heldFor":"","waitTime":825970,"locker":"PlannerMetaLocker.lock():106"},{"id":116486,"name":"thrift-server-pool-102486","heldFor":"","waitTime":793001,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":118892,"name":"starrocks-mysql-nio-pool-128","heldFor":"","waitTime":414748,"locker":"PlannerMetaLocker.lock():106"},{"id":119012,"name":"thrift-server-pool-104699","heldFor":"","waitTime":409919,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":118757,"name":"starrocks-mysql-nio-pool-127","heldFor":"","waitTime":391563,"locker":"PlannerMetaLocker.lock():106"},{"id":121260,"name":"thrift-server-pool-106826","heldFor":"","waitTime":228050,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121920,"name":"starrocks-mysql-nio-pool-130","heldFor":"","waitTime":196792,"locker":"PlannerMetaLocker.lock():106"},{"id":121226,"name":"thrift-server-pool-106794","heldFor":"","waitTime":141241,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":122394,"name":"starrocks-mysql-nio-pool-131","heldFor":"","waitTime":131932,"locker":"PlannerMetaLocker.lock():106"},{"id":122502,"name":"starrocks-mysql-nio-pool-132","heldFor":"","waitTime":114983,"locker":"PlannerMetaLocker.lock():106"},{"id":121400,"name":"thrift-server-pool-106965","heldFor":"","waitTime":98009,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121786,"name":"thrift-server-pool-107343","heldFor":"","waitTime":84288,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121475,"name":"thrift-server-pool-107038","heldFor":"","waitTime":84057,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121474,"name":"thrift-server-pool-107037","heldFor":"","waitTime":83677,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121852,"name":"thrift-server-pool-107406","heldFor":"","waitTime":83496,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121683,"name":"thrift-server-pool-107244","heldFor":"","waitTime":83220,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121632,"name":"thrift-server-pool-107194","heldFor":"","waitTime":82891,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121455,"name":"thrift-server-pool-107019","heldFor":"","waitTime":72141,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121268,"name":"thrift-server-pool-106834","heldFor":"","waitTime":71574,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121270,"name":"thrift-server-pool-106836","heldFor":"","waitTime":71431,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":118986,"name":"thrift-server-pool-104673","heldFor":"","waitTime":56080,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":122950,"name":"starrocks-mysql-nio-pool-133","heldFor":"","waitTime":54138,"locker":"PlannerMetaLocker.lock():106"},{"id":122094,"name":"thrift-server-pool-107639","heldFor":"","waitTime":53420,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":122575,"name":"thrift-server-pool-108098","heldFor":"","waitTime":42257,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":122267,"name":"thrift-server-pool-107805","heldFor":"","waitTime":34422,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":121921,"name":"thrift-server-pool-107472","heldFor":"","waitTime":27329,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":123194,"name":"thrift-server-pool-108691","heldFor":"","waitTime":19712,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":119169,"name":"thrift-server-pool-104851","heldFor":"","waitTime":11250,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":123324,"name":"starrocks-mysql-nio-pool-134","heldFor":"","waitTime":7749,"locker":"PlannerMetaLocker.lock():106"},{"id":123115,"name":"thrift-server-pool-108613","heldFor":"","waitTime":6862,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"},{"id":120725,"name":"thrift-server-pool-106349","heldFor":"","waitTime":3000,"locker":"FrontendServiceImpl.streamLoadPutImpl():1736"}]}

[LIANGCHAOHUA]

麻烦发一下完整的 fe leader fe.log，还有对fe leader打个jstack吧

[liuhangyuan]

3.3.0版本吗？

[liuhangyuan]

打印slow lock只是无法获得锁的结果。核心原因在于为什么stream load plan的耗时很长

[redscarf]

我这边集群从3.2.7版本升级到3.3.0 版本之后，出现死锁现象，当时看了线程信息，【thrift-server-pool】线程疯涨，达到接近2000个，日志中出现如下日志

2024-07-12 00:21:31.005+08:00 WARN (starrocks-mysql-nio-pool-439|584154) [LockManager.checkAndHandleDeadLock():417] LockManager detects dead lock.
2024-07-12 00:21:31.006+08:00 WARN (thrift-server-pool-581664|584139) [LockManager.logSlowLockTrace():398] LockManager detects slow lock : {"owners":[{"id":584154,"name":"starrocks-mysql-nio-pool-439","heldFor":3002,"waitTime":0,"stack":["java.base@11.0.23/java.lang.invoke.MemberName$Factory.resolveOrFail(MemberName.java:1098)","java.base@11.0.23/java.lang.invoke.MethodHandles$Lookup.resolveOrFail(MethodHandles.java:2038)","java.base@11.0.23/java.lang.invoke.MethodHandles$Lookup.linkMethodHandleConstant(MethodHandles.java:2465)","java.base@11.0.23/java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(MethodHandleNatives.java:592)","app//com.starrocks.common.util.LogUtil.getStackTraceToList(LogUtil.java:115)","app//com.starrocks.common.util.LogUtil.getStackTraceToList(LogUtil.java:93)","app//com.starrocks.common.util.LogUtil.getStackTraceToJsonArray(LogUtil.java:97)","app//com.starrocks.common.util.concurrent.lock.LockManager.logSlowLockTrace(LockManager.java:377)","app//com.starrocks.common.util.concurrent.lock.LockManager.lock(LockManager.java:134)","app//com.starrocks.common.util.concurrent.lock.Locker.lock(Locker.java:85)","app//com.starrocks.common.util.concurrent.lock.Locker.lockDatabase(Locker.java:112)","app//com.starrocks.sql.analyzer.CreateTableAnalyzer.analyze(CreateTableAnalyzer.java:179)","app//com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableStatement(Analyzer.java:198)","app//com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableStatement(Analyzer.java:166)","app//com.starrocks.sql.ast.CreateTableStmt.accept(CreateTableStmt.java:308)","app//com.starrocks.sql.ast.AstVisitor.visit(AstVisitor.java:71)","app//com.starrocks.sql.analyzer.Analyzer.analyze(Analyzer.java:163)","app//com.starrocks.sql.analyzer.CTASAnalyzer.analyze(CTASAnalyzer.java:163)","app//com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableAsSelectStatement(Analyzer.java:309)","app//com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableAsSelectStatement(Analyzer.java:166)"]}],"waiter":[{"id":584155,"name":"thrift-server-pool-581676","heldFor":"","waitTime":3002,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584136,"name":"thrift-server-pool-581661","heldFor":"","waitTime":3002,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":584154,"name":"starrocks-mysql-nio-pool-439","heldFor":"","waitTime":3002,"locker":"CreateTableAnalyzer.analyze():171"},{"id":24,"name":"PUBLISH_VERSION","heldFor":"","waitTime":3001,"locker":"DatabaseTransactionMgr.canTxnFinished():885"},{"id":584138,"name":"thrift-server-pool-581663","heldFor":"","waitTime":3000,"locker":"LocalMetastore.onCreate():2288"},{"id":584139,"name":"thrift-server-pool-581664","heldFor":"","waitTime":3000,"locker":"LocalMetastore.onCreate():2288"},{"id":584135,"name":"thrift-server-pool-581660","heldFor":"","waitTime":2989,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":584141,"name":"starrocks-mysql-nio-pool-437","heldFor":"","waitTime":2987,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584152,"name":"thrift-server-pool-581675","heldFor":"","waitTime":2986,"locker":"PlannerMetaLocker.lock():106"},{"id":584147,"name":"thrift-server-pool-581670","heldFor":"","waitTime":2986,"locker":"PlannerMetaLocker.lock():106"},{"id":582783,"name":"starrocks-mysql-nio-pool-435","heldFor":"","waitTime":2982,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":584134,"name":"thrift-server-pool-581659","heldFor":"","waitTime":2975,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":584137,"name":"thrift-server-pool-581662","heldFor":"","waitTime":2950,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":584156,"name":"thrift-server-pool-581677","heldFor":"","waitTime":2918,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584157,"name":"thrift-server-pool-581678","heldFor":"","waitTime":2902,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584140,"name":"starrocks-mysql-nio-pool-436","heldFor":"","waitTime":2889,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584158,"name":"thrift-server-pool-581679","heldFor":"","waitTime":2872,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584159,"name":"thrift-server-pool-581680","heldFor":"","waitTime":2822,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584153,"name":"starrocks-mysql-nio-pool-438","heldFor":"","waitTime":1989,"locker":"ShowExecutor$ShowExecutorVisitor.showCreateInternalCatalogTable():699"},{"id":584132,"name":"thrift-server-pool-581657","heldFor":"","waitTime":993,"locker":"InformationSchemaDataSource.generateTablesInfoResponse():401"}]}
2024-07-12 00:21:31.007+08:00 WARN (thrift-server-pool-581660|584135) [LockManager.logSlowLockTrace():398] LockManager detects slow lock : {"owners":[{"id":584154,"name":"starrocks-mysql-nio-pool-439","heldFor":3013,"waitTime":0,"stack":["java.base@11.0.23/java.lang.Object.wait(Native Method)","app//com.starrocks.common.util.concurrent.lock.LockManager.lock(LockManager.java:153)","app//com.starrocks.common.util.concurrent.lock.Locker.lock(Locker.java:85)","app//com.starrocks.common.util.concurrent.lock.Locker.lockDatabase(Locker.java:112)","app//com.starrocks.sql.analyzer.CreateTableAnalyzer.analyze(CreateTableAnalyzer.java:179)","app//com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableStatement(Analyzer.java:198)","app//com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableStatement(Analyzer.java:166)","app//com.starrocks.sql.ast.CreateTableStmt.accept(CreateTableStmt.java:308)","app//com.starrocks.sql.ast.AstVisitor.visit(AstVisitor.java:71)","app//com.starrocks.sql.analyzer.Analyzer.analyze(Analyzer.java:163)","app//com.starrocks.sql.analyzer.CTASAnalyzer.analyze(CTASAnalyzer.java:163)","app//com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableAsSelectStatement(Analyzer.java:309)","app//com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableAsSelectStatement(Analyzer.java:166)","app//com.starrocks.sql.ast.CreateTableAsSelectStmt.accept(CreateTableAsSelectStmt.java:79)","app//com.starrocks.sql.ast.AstVisitor.visit(AstVisitor.java:71)","app//com.starrocks.sql.analyzer.Analyzer.analyze(Analyzer.java:163)","app//com.starrocks.sql.StatementPlanner.plan(StatementPlanner.java:114)","app//com.starrocks.sql.StatementPlanner.plan(StatementPlanner.java:92)","app//com.starrocks.qe.StmtExecutor.execute(StmtExecutor.java:537)","app//com.starrocks.qe.ConnectProcessor.handleQuery(ConnectProcessor.java:390)"]}],"waiter":[{"id":584155,"name":"thrift-server-pool-581676","heldFor":"","waitTime":3013,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584136,"name":"thrift-server-pool-581661","heldFor":"","waitTime":3013,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":584154,"name":"starrocks-mysql-nio-pool-439","heldFor":"","waitTime":3013,"locker":"CreateTableAnalyzer.analyze():171"},{"id":24,"name":"PUBLISH_VERSION","heldFor":"","waitTime":3012,"locker":"DatabaseTransactionMgr.canTxnFinished():885"},{"id":584138,"name":"thrift-server-pool-581663","heldFor":"","waitTime":3011,"locker":"LocalMetastore.onCreate():2288"},{"id":584139,"name":"thrift-server-pool-581664","heldFor":"","waitTime":3011,"locker":"LocalMetastore.onCreate():2288"},{"id":584135,"name":"thrift-server-pool-581660","heldFor":"","waitTime":3000,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":584141,"name":"starrocks-mysql-nio-pool-437","heldFor":"","waitTime":2998,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584152,"name":"thrift-server-pool-581675","heldFor":"","waitTime":2997,"locker":"PlannerMetaLocker.lock():106"},{"id":584147,"name":"thrift-server-pool-581670","heldFor":"","waitTime":2997,"locker":"PlannerMetaLocker.lock():106"},{"id":582783,"name":"starrocks-mysql-nio-pool-435","heldFor":"","waitTime":2993,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":584134,"name":"thrift-server-pool-581659","heldFor":"","waitTime":2986,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":584137,"name":"thrift-server-pool-581662","heldFor":"","waitTime":2961,"locker":"GlobalTransactionMgr.commitTransactionUnderDatabaseWLock():432"},{"id":584156,"name":"thrift-server-pool-581677","heldFor":"","waitTime":2929,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584157,"name":"thrift-server-pool-581678","heldFor":"","waitTime":2913,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584140,"name":"starrocks-mysql-nio-pool-436","heldFor":"","waitTime":2900,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584158,"name":"thrift-server-pool-581679","heldFor":"","waitTime":2883,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584159,"name":"thrift-server-pool-581680","heldFor":"","waitTime":2833,"locker":"DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"},{"id":584153,"name":"starrocks-mysql-nio-pool-438","heldFor":"","waitTime":2000,"locker":"ShowExecutor$ShowExecutorVisitor.showCreateInternalCatalogTable():699"},{"id":584132,"name":"thrift-server-pool-581657","heldFor":"","waitTime":1004,"locker":"InformationSchemaDataSource.generateTablesInfoResponse():401"}]}

[redscarf]

从我这边fe的日志来看，单纯从性能的角度来看slow lock的日志是不合理的，越是慢的时候，越要打印日志，越耗时间，我这边fe的日志中，有大量如下的日志

{
    "owners": [
        {
            "id": 584154,
            "name": "starrocks-mysql-nio-pool-439",
            "heldFor": 3002,
            "waitTime": 0,
            "stack": [
                "java.base@11.0.23/java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(MethodHandleNatives.java:590)",
                "app//com.starrocks.common.util.LogUtil.getStackTraceToList(LogUtil.java:115)",
                "app //com.starrocks.common.util.LogUtil.getStackTraceToList(LogUtil.java:93)",
                "app//com.starrocks.common.util.LogUtil.getStackTraceToJsonArray(LogUtil.java:97)",
                "app//com.starrocks.common.util.concurrent.lock.LockManager.logSlowLockTrace(LockManager.java: 377)",
                "app //com.starrocks.common.util.concurrent.lock.LockManager.lock(LockManager.java:134)",
                "app//com.starrocks.common.util.concurrent.lock.Locker.lock(Locker.java: 85)",
                "app //com.starrocks.common.util.concurrent.lock.Locker.lockDatabase(Locker.java:112)",
                "app//com.starrocks.sql.analyzer.CreateTableAnalyzer.analyze(CreateTableAnalyzer.java:179)",
                "app//com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableStatement(Analyzer.java: 198)",
                "app //com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableStatement(Analyzer.java:166)",
                "app//com.starrocks.sql.ast.CreateTableStmt.accept(CreateTableStmt.java: 308)",
                "app //com.starrocks.sql.ast.AstVisitor.visit(AstVisitor.java:71)",
                "app//com.starrocks.sql.analyzer.Analyzer.analyze(Analyzer.java:163)",
                "app//com.starrocks.sql.analyzer.CTASAnalyzer.analyze(CTASAnalyzer.java: 163)",
                "app //com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableAsSelectStatement(Analyzer.java:309)",
                "app//com.starrocks.sql.analyzer.Analyzer$AnalyzerVisitor.visitCreateTableAsSelectStatement(Analyzer.java: 166)",
                "app //com.starrocks.sql.ast.CreateTableAsSelectStmt.accept(CreateTableAsSelectStmt.java:79)",
                "app//com.starrocks.sql.ast.AstVisitor.visit(AstVisitor.java: 71)",
                "app //com.starrocks.sql.analyzer.Analyzer.analyze(Analyzer.java:163)"
            ]
        }
    ],
    "waiter": [
        {
            "id": 584155,
            "name": "thrift-server-pool-581676",
            "heldFor": "",
            "waitTime": 3002,
            "locker": "DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement(): 86"
        },
        {
            "id": 584136,
            "name": "thrift-server-pool-581661",
            "heldFor": "",
            "waitTime": 3002,
            "locker": "GlobalTransactionMgr.commitTransactionUnderDatabaseWLock(): 432"
        },
        {
            "id": 584154,
            "name": "starrocks-mysql-nio-pool-439",
            "heldFor": "",
            "waitTime": 3002,
            "locker": "CreateTableAnalyzer.analyze(): 171"
        },
        {
            "id": 24,
            "name": "PUBLISH_VERSION",
            "heldFor": "",
            "waitTime": 3001,
            "locker": "DatabaseTransactionMgr.canTxnFinished(): 885"
        },
        {
            "id": 584138,
            "name": "thrift-server-pool-581663",
            "heldFor": "",
            "waitTime": 3000,
            "locker": "LocalMetastore.onCreate(): 2288"
        },
        {
            "id": 584139,
            "name": "thrift-server-pool-581664",
            "heldFor": "",
            "waitTime": 3000,
            "locker": "LocalMetastore.onCreate(): 2288"
        },
        {
            "id": 584135,
            "name": "thrift-server-pool-581660",
            "heldFor": "",
            "waitTime": 2989,
            "locker": "GlobalTransactionMgr.commitTransactionUnderDatabaseWLock(): 432"
        },
        {
            "id": 584141,
            "name": "starrocks-mysql-nio-pool-437",
            "heldFor": "",
            "waitTime": 2987,
            "locker": "DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement(): 86"
        },
        {
            "id": 584152,
            "name": "thrift-server-pool-581675",
            "heldFor": "",
            "waitTime": 2986,
            "locker": "PlannerMetaLocker.lock(): 106"
        },
        {
            "id": 584147,
            "name": "thrift-server-pool-581670",
            "heldFor": "",
            "waitTime": 2986,
            "locker": "PlannerMetaLocker.lock():106"
        },
        {
            "id": 582783,
            "name": "starrocks-mysql-nio-pool-435",
            "heldFor": "",
            "waitTime": 2982,
            "locker": "GlobalTransactionMgr.commitTransactionUnderDatabaseWLock(): 432"
        },
        {
            "id": 584134,
            "name": "thrift-server-pool-581659",
            "heldFor": "",
            "waitTime": 2975,
            "locker": "GlobalTransactionMgr.commitTransactionUnderDatabaseWLock(): 432"
        },
        {
            "id": 584137,
            "name": "thrift-server-pool-581662",
            "heldFor": "",
            "waitTime": 2950,
            "locker": "GlobalTransactionMgr.commitTransactionUnderDatabaseWLock(): 432"
        },
        {
            "id": 584156,
            "name": "thrift-server-pool-581677",
            "heldFor": "",
            "waitTime": 2918,
            "locker": "DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"
        },
        {
            "id": 584157,
            "name": "thrift-server-pool-581678",
            "heldFor": "",
            "waitTime": 2902,
            "locker": "DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement(): 86"
        },
        {
            "id": 584140,
            "name": "starrocks-mysql-nio-pool-436",
            "heldFor": "",
            "waitTime": 2889,
            "locker": "DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement(): 86"
        },
        {
            "id": 584158,
            "name": "thrift-server-pool-581679",
            "heldFor": "",
            "waitTime": 2872,
            "locker": "DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement(): 86"
        },
        {
            "id": 584159,
            "name": "thrift-server-pool-581680",
            "heldFor": "",
            "waitTime": 2822,
            "locker": "DropStmtAnalyzer$DropStmtAnalyzerVisitor.visitDropTableStatement():86"
        },
        {
            "id": 584153,
            "name": "starrocks-mysql-nio-pool-438",
            "heldFor": "",
            "waitTime": 1989,
            "locker": "ShowExecutor$ShowExecutorVisitor.showCreateInternalCatalogTable(): 699"
        },
        {
            "id": 584132,
            "name": "thrift-server-pool-581657",
            "heldFor": "",
            "waitTime": 993,
            "locker": "InformationSchemaDataSource.generateTablesInfoResponse(): 401"
        }
    ]
}

[zhanglistar]

我们在3.3.0复现了这个bug，看起来0x00007f031a50ea58这个对象已经无了，但是有很多线程在wait，因而导致了死锁。附件里是完整的jstack输出。jstack_log.txt (1.2 MB)

日志里有很多类似的输出：
- waiting on <no object reference available>

[redscarf]

我和社区的大佬联系了一下，说是他们之后的版本会修复，不过具体啥版本修复还不清楚，有个临时处理措施，修改FE配置：lock_manager_enable_using_fine_granularity_lock=false