This is an automated email from the ASF dual-hosted git repository. tanxinyu pushed a commit to branch cluster_sync_leader_bug in repository https://gitbox.apache.org/repos/asf/iotdb.git
commit 06693755099251aef01d2940d548144b53b129e2 Author: LebronAl <[email protected]> AuthorDate: Tue Sep 7 16:03:32 2021 +0800 add log --- .../iotdb/cluster/log/applier/AsyncDataLogApplier.java | 11 +++++++---- .../org/apache/iotdb/cluster/log/manage/RaftLogManager.java | 12 +++++++++++- 2 files changed, 18 insertions(+), 5 deletions(-) diff --git a/cluster/src/main/java/org/apache/iotdb/cluster/log/applier/AsyncDataLogApplier.java b/cluster/src/main/java/org/apache/iotdb/cluster/log/applier/AsyncDataLogApplier.java index 65a5b2d..d0badaf 100644 --- a/cluster/src/main/java/org/apache/iotdb/cluster/log/applier/AsyncDataLogApplier.java +++ b/cluster/src/main/java/org/apache/iotdb/cluster/log/applier/AsyncDataLogApplier.java @@ -140,12 +140,10 @@ public class AsyncDataLogApplier implements LogApplier { /** * We can sure that the storage group of all InsertTabletPlans in InsertMultiTabletPlan are the - * same. this is done in {@link - * org.apache.iotdb.cluster.query.ClusterPlanRouter#splitAndRoutePlan(InsertMultiTabletPlan)} + * same. this is done in * * <p>We can also sure that the storage group of all InsertRowPlans in InsertRowsPlan are the - * same. this is done in {@link - * org.apache.iotdb.cluster.query.ClusterPlanRouter#splitAndRoutePlan(InsertRowsPlan)} + * same. this is done in * * @return the sg that the plan belongs to * @throws StorageGroupNotSetException if no sg found @@ -203,7 +201,12 @@ public class AsyncDataLogApplier implements LogApplier { private void applyInternal(Log log) { long startTime = Statistic.RAFT_SENDER_DATA_LOG_APPLY.getOperationStartTime(); + long start = System.nanoTime(); embeddedApplier.apply(log); + long time = (System.nanoTime() - start) / 1_000_000L; + if (time > 5000) { + logger.warn("{}:apply log {} slowly for {}ms", name, log, time); + } if (Timer.ENABLE_INSTRUMENTING) { Statistic.RAFT_SENDER_DATA_LOG_APPLY.calOperationCostTimeFromStart(startTime); } diff --git a/cluster/src/main/java/org/apache/iotdb/cluster/log/manage/RaftLogManager.java b/cluster/src/main/java/org/apache/iotdb/cluster/log/manage/RaftLogManager.java index 446eefc..f3476c1 100644 --- a/cluster/src/main/java/org/apache/iotdb/cluster/log/manage/RaftLogManager.java +++ b/cluster/src/main/java/org/apache/iotdb/cluster/log/manage/RaftLogManager.java @@ -943,16 +943,26 @@ public abstract class RaftLogManager { nextToCheckIndex); return; } + long start = System.nanoTime(); synchronized (log) { while (!log.isApplied() && maxHaveAppliedCommitIndex < log.getCurrLogIndex()) { // wait until the log is applied or a newer snapshot is installed log.wait(5); } } + long time = (System.nanoTime() - start) / 1_000_000L; + if (time > 5000) { + logger.warn("{}:wait log {} to apply slowly for {}ms", name, log, time); + } + start = System.nanoTime(); synchronized (changeApplyCommitIndexCond) { // maxHaveAppliedCommitIndex may change if a snapshot is applied concurrently maxHaveAppliedCommitIndex = Math.max(maxHaveAppliedCommitIndex, nextToCheckIndex); } + time = (System.nanoTime() - start) / 1_000_000L; + if (time > 10000) { + logger.warn("{}:wait snapshot slowly for {}ms", name, time); + } logger.debug( "{}: log={} is applied, nextToCheckIndex={}, commitIndex={}, maxHaveAppliedCommitIndex={}", name, @@ -968,7 +978,7 @@ public abstract class RaftLogManager { // maxHaveAppliedCommitIndex may change if a snapshot is applied concurrently maxHaveAppliedCommitIndex = Math.max(maxHaveAppliedCommitIndex, nextToCheckIndex); } - logger.debug( + logger.error( "{}: compacted log is assumed applied, nextToCheckIndex={}, commitIndex={}, " + "maxHaveAppliedCommitIndex={}", name,
