diff --git a/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/CSMMetrics.java b/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/CSMMetrics.java index 6bd15946184e..3634ae34ac8d 100644 --- a/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/CSMMetrics.java +++ b/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/CSMMetrics.java @@ -39,6 +39,7 @@ public class CSMMetrics { public static final String SOURCE_NAME = CSMMetrics.class.getSimpleName(); + private RaftGroupId gid; // ratis op metrics metrics private @Metric MutableCounterLong numWriteStateMachineOps; @@ -50,6 +51,7 @@ public class CSMMetrics { private @Metric MutableRate transactionLatencyMs; private final EnumMap opsLatencyMs; + private final EnumMap opsQueueingDelay; private MetricsRegistry registry = null; // Failure Metrics @@ -64,15 +66,22 @@ public class CSMMetrics { private @Metric MutableCounterLong numDataCacheMiss; private @Metric MutableCounterLong numDataCacheHit; private @Metric MutableCounterLong numEvictedCacheCount; + private @Metric MutableCounterLong pendingApplyTransactions; private @Metric MutableRate applyTransactionNs; private @Metric MutableRate writeStateMachineDataNs; + private @Metric MutableRate writeStateMachineQueueingLatencyNs; + private @Metric MutableRate untilApplyTransactionNs; + private @Metric MutableRate startTransactionCompleteNs; - public CSMMetrics() { + public CSMMetrics(RaftGroupId gid) { + this.gid = gid; this.opsLatencyMs = new EnumMap<>(ContainerProtos.Type.class); + this.opsQueueingDelay = new EnumMap<>(ContainerProtos.Type.class); this.registry = new MetricsRegistry(CSMMetrics.class.getSimpleName()); for (ContainerProtos.Type type : ContainerProtos.Type.values()) { opsLatencyMs.put(type, registry.newRate(type.toString() + "Ms", type + " op")); + opsQueueingDelay.put(type, registry.newRate("queueingDelay" + type.toString() + "Ns", type + " op")); } } @@ -80,7 +89,12 @@ public static CSMMetrics create(RaftGroupId gid) { MetricsSystem ms = DefaultMetricsSystem.instance(); return ms.register(SOURCE_NAME + gid.toString(), "Container State Machine", - new CSMMetrics()); + new CSMMetrics(gid)); + } + + @Metric + public String getRaftGroupId() { + return gid.toString(); } public void incNumWriteStateMachineOps() { @@ -189,6 +203,11 @@ public void incPipelineLatencyMs(ContainerProtos.Type type, transactionLatencyMs.add(latencyMillis); } + public void recordQueueingDelay(ContainerProtos.Type type, + long latencyNanos) { + opsQueueingDelay.get(type).add(latencyNanos); + } + public void incNumStartTransactionVerifyFailures() { numStartTransactionVerifyFailures.incr(); } @@ -205,6 +224,19 @@ public void recordWriteStateMachineCompletionNs(long latencyNanos) { writeStateMachineDataNs.add(latencyNanos); } + + public void recordWriteStateMachineQueueingLatencyNs(long latencyNanos) { + writeStateMachineQueueingLatencyNs.add(latencyNanos); + } + + public void recordUntilApplyTransactionNs(long latencyNanos) { + untilApplyTransactionNs.add(latencyNanos); + } + + public void recordStartTransactionCompleteNs(long latencyNanos) { + startTransactionCompleteNs.add(latencyNanos); + } + public void incNumDataCacheMiss() { numDataCacheMiss.incr(); } @@ -216,8 +248,16 @@ public void incNumEvictedCacheCount() { numEvictedCacheCount.incr(); } + public void incPendingApplyTransactions() { + pendingApplyTransactions.incr(); + } + + public void decPendingApplyTransactions() { + pendingApplyTransactions.incr(-1); + } + public void unRegister() { MetricsSystem ms = DefaultMetricsSystem.instance(); - ms.unregisterSource(SOURCE_NAME); + ms.unregisterSource(SOURCE_NAME + gid.toString()); } } diff --git a/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/ContainerStateMachine.java b/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/ContainerStateMachine.java index 6351c746fe5c..f583eadd7ea9 100644 --- a/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/ContainerStateMachine.java +++ b/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/ContainerStateMachine.java @@ -402,6 +402,7 @@ public TransactionContext startTransaction(LogEntryProto entry, RaftPeerRole rol @Override public TransactionContext startTransaction(RaftClientRequest request) throws IOException { + long startTime = Time.monotonicNowNanos(); final ContainerCommandRequestProto proto = message2ContainerCommandRequestProto(request.getMessage()); Preconditions.checkArgument(request.getRaftGroupId().equals(gid)); @@ -411,6 +412,8 @@ public TransactionContext startTransaction(RaftClientRequest request) .setStateMachine(this) .setServerRole(RaftPeerRole.LEADER); + metrics.incPendingApplyTransactions(); + try { dispatcher.validateContainerCommand(proto); } catch (IOException ioe) { @@ -440,9 +443,11 @@ public TransactionContext startTransaction(RaftClientRequest request) builder.setStateMachineData(write.getData()); } final ContainerCommandRequestProto containerCommandRequestProto = protoBuilder.build(); - return builder.setStateMachineContext(new Context(proto, containerCommandRequestProto)) + TransactionContext txnContext = builder.setStateMachineContext(new Context(proto, containerCommandRequestProto)) .setLogData(containerCommandRequestProto.toByteString()) .build(); + metrics.recordStartTransactionCompleteNs(Time.monotonicNowNanos() - startTime); + return txnContext; } private static ContainerCommandRequestProto getContainerCommandRequestProto( @@ -521,6 +526,8 @@ private CompletableFuture writeStateMachineData( CompletableFuture writeChunkFuture = CompletableFuture.supplyAsync(() -> { try { + metrics.recordWriteStateMachineQueueingLatencyNs( + Time.monotonicNowNanos() - startTime); return dispatchCommand(requestProto, context); } catch (Exception e) { LOG.error("{}: writeChunk writeStateMachineData failed: blockId" + @@ -884,6 +891,11 @@ private CompletableFuture applyTransaction( final CheckedSupplier task = () -> { try { + long timeNow = Time.monotonicNowNanos(); + long queueingDelay = timeNow - context.getStartTime(); + metrics.recordQueueingDelay(request.getCmdType(), queueingDelay); + // TODO: add a counter to track number of executing applyTransaction + // and queue size return dispatchCommand(request, context); } catch (Exception e) { exceptionHandler.accept(e); @@ -932,11 +944,13 @@ public CompletableFuture applyTransaction(TransactionContext trx) { .setTerm(trx.getLogEntry().getTerm()) .setLogIndex(index); + final Context context = (Context) trx.getStateMachineContext(); long applyTxnStartTime = Time.monotonicNowNanos(); + metrics.recordUntilApplyTransactionNs(applyTxnStartTime - context.getStartTime()); applyTransactionSemaphore.acquire(); metrics.incNumApplyTransactionsOps(); - final Context context = (Context) trx.getStateMachineContext(); + Objects.requireNonNull(context, "context == null"); final ContainerCommandRequestProto requestProto = context.getLogProto(); final Type cmdType = requestProto.getCmdType(); @@ -1021,6 +1035,9 @@ public CompletableFuture applyTransaction(TransactionContext trx) { applyTransactionSemaphore.release(); metrics.recordApplyTransactionCompletionNs( Time.monotonicNowNanos() - applyTxnStartTime); + if (trx.getServerRole() == RaftPeerRole.LEADER) { + metrics.decPendingApplyTransactions(); + } }); return applyTransactionFuture; } catch (InterruptedException e) { diff --git a/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/DispatcherContext.java b/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/DispatcherContext.java index d6c976cb389e..15af26453524 100644 --- a/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/DispatcherContext.java +++ b/hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/transport/server/ratis/DispatcherContext.java @@ -19,6 +19,7 @@ import org.apache.hadoop.hdds.annotation.InterfaceAudience; import org.apache.hadoop.hdds.annotation.InterfaceStability; +import org.apache.hadoop.util.Time; import org.apache.ratis.server.protocol.TermIndex; import java.util.Map; @@ -118,12 +119,15 @@ public static Op op(DispatcherContext context) { private final Map container2BCSIDMap; + private long startTime; + private DispatcherContext(Builder b) { this.op = Objects.requireNonNull(b.op, "op == null"); this.term = b.term; this.logIndex = b.logIndex; this.stage = b.stage; this.container2BCSIDMap = b.container2BCSIDMap; + this.startTime = Time.monotonicNowNanos(); } /** Use {@link DispatcherContext#op(DispatcherContext)} for handling null. */ @@ -147,6 +151,10 @@ public Map getContainer2BCSIDMap() { return container2BCSIDMap; } + public long getStartTime() { + return startTime; + } + @Override public String toString() { return op + "-" + stage + TermIndex.valueOf(term, logIndex);