HDDS-12060. Replace System.currentTimeMillis() with Time.monotonicNow() for duration calculation (apache#8096)

Author: chiacyu

hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/XceiverClientGrpc.java

@@ -60,6 +60,7 @@
 import org.apache.hadoop.ozone.ClientVersion;
 import org.apache.hadoop.ozone.OzoneConfigKeys;
 import org.apache.hadoop.ozone.OzoneConsts;
+import org.apache.hadoop.util.Time;
 import org.apache.ratis.thirdparty.io.grpc.ManagedChannel;
 import org.apache.ratis.thirdparty.io.grpc.Status;
 import org.apache.ratis.thirdparty.io.grpc.netty.GrpcSslContexts;
@@ -571,7 +572,7 @@ public XceiverClientReply sendCommandAsync(
     final CompletableFuture<ContainerCommandResponseProto> replyFuture =
         new CompletableFuture<>();
     semaphore.acquire();
-    long requestTime = System.currentTimeMillis();
+    long requestTime = Time.monotonicNow();
     metrics.incrPendingContainerOpsMetrics(request.getCmdType());
 
     // create a new grpc message stream pair for each call.
@@ -601,7 +602,7 @@ public void onCompleted() {
 
               private void decreasePendingMetricsAndReleaseSemaphore() {
                 metrics.decrPendingContainerOpsMetrics(request.getCmdType());
-                long cost = System.currentTimeMillis() - requestTime;
+                long cost = Time.monotonicNow() - requestTime;
                 metrics.addContainerOpsLatency(request.getCmdType(), cost);
                 if (LOG.isDebugEnabled()) {
                   LOG.debug("Executed command {} on datanode {}, cost = {}, cmdType = {}",

hadoop-hdds/client/src/main/java/org/apache/hadoop/hdds/scm/XceiverClientRatis.java

@@ -47,6 +47,7 @@
 import org.apache.hadoop.hdds.scm.pipeline.Pipeline;
 import org.apache.hadoop.hdds.security.SecurityConfig;
 import org.apache.hadoop.hdds.tracing.TracingUtil;
+import org.apache.hadoop.util.Time;
 import org.apache.ratis.client.RaftClient;
 import org.apache.ratis.client.api.DataStreamApi;
 import org.apache.ratis.grpc.GrpcTlsConfig;
@@ -363,7 +364,7 @@ private XceiverClientReply handleFailedAllCommit(long index, Collection<CommitIn
   public XceiverClientReply sendCommandAsync(
       ContainerCommandRequestProto request) {
     XceiverClientReply asyncReply = new XceiverClientReply(null);
-    long requestTime = System.currentTimeMillis();
+    long requestTime = Time.monotonicNow();
     CompletableFuture<RaftClientReply> raftClientReply =
         sendRequestAsync(request);
     metrics.incrPendingContainerOpsMetrics(request.getCmdType());
@@ -376,7 +377,7 @@ public XceiverClientReply sendCommandAsync(
           }
           metrics.decrPendingContainerOpsMetrics(request.getCmdType());
           metrics.addContainerOpsLatency(request.getCmdType(),
-              System.currentTimeMillis() - requestTime);
+              Time.monotonicNow() - requestTime);
         }).thenApply(reply -> {
           try {
             if (!reply.isSuccess()) {

hadoop-hdds/common/src/main/java/org/apache/hadoop/ozone/util/ShutdownHookManager.java

@@ -39,6 +39,7 @@
 import org.apache.hadoop.hdds.annotation.InterfaceStability;
 import org.apache.hadoop.hdds.conf.ConfigurationSource;
 import org.apache.hadoop.hdds.conf.OzoneConfiguration;
+import org.apache.hadoop.util.Time;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -95,9 +96,9 @@ public void run() {
                 LOG.info("Shutdown process invoked a second time: ignoring");
                 return;
               }
-              long started = System.currentTimeMillis();
+              long started = Time.monotonicNow();
               int timeoutCount = MGR.executeShutdown();
-              long ended = System.currentTimeMillis();
+              long ended = Time.monotonicNow();
               LOG.debug(String.format(
                   "Completed shutdown in %.3f seconds; Timeouts: %d",
                   (ended - started) / 1000.0, timeoutCount));

hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/common/utils/HddsVolumeUtil.java

@@ -33,6 +33,7 @@
 import org.apache.hadoop.ozone.container.common.volume.MutableVolumeSet;
 import org.apache.hadoop.ozone.container.keyvalue.helpers.BlockUtils;
 import org.apache.hadoop.ozone.container.metadata.DatanodeStore;
+import org.apache.hadoop.util.Time;
 import org.slf4j.Logger;
 
 /**
@@ -89,7 +90,7 @@ public static void loadAllHddsVolumeDbStore(MutableVolumeSet hddsVolumeSet,
     List<CompletableFuture<Void>> futures = new ArrayList<>();
     List<HddsVolume> hddsVolumes = StorageVolumeUtil.getHddsVolumesList(
         hddsVolumeSet.getVolumesList());
-    long start = System.currentTimeMillis();
+    long start = Time.monotonicNow();
     for (HddsVolume volume : hddsVolumes) {
       futures.add(CompletableFuture.runAsync(
           () -> loadVolume(volume, readOnly, logger)));
@@ -99,7 +100,7 @@ public static void loadAllHddsVolumeDbStore(MutableVolumeSet hddsVolumeSet,
     }
     if (logger != null) {
       logger.info("Load {} volumes DbStore cost: {}ms", hddsVolumes.size(),
-          System.currentTimeMillis() - start);
+          Time.monotonicNow() - start);
     }
   }
 

hadoop-hdds/container-service/src/main/java/org/apache/hadoop/ozone/container/ozoneimpl/OzoneContainer.java

@@ -96,6 +96,7 @@
 import org.apache.hadoop.ozone.container.replication.ReplicationServer.ReplicationConfig;
 import org.apache.hadoop.ozone.container.upgrade.VersionedDatanodeFeatures.SchemaV3;
 import org.apache.hadoop.util.DiskChecker.DiskOutOfSpaceException;
+import org.apache.hadoop.util.Time;
 import org.apache.hadoop.util.Timer;
 import org.apache.ratis.grpc.GrpcTlsConfig;
 import org.slf4j.Logger;
@@ -318,7 +319,7 @@ public void buildContainerSet() throws IOException {
     Iterator<StorageVolume> volumeSetIterator = volumeSet.getVolumesList()
         .iterator();
     ArrayList<Thread> volumeThreads = new ArrayList<>();
-    long startTime = System.currentTimeMillis();
+    long startTime = Time.monotonicNow();
 
     // Load container inspectors that may be triggered at startup based on
     // system properties set. These can inspect and possibly repair
@@ -360,7 +361,7 @@ public void buildContainerSet() throws IOException {
     ContainerInspectorUtil.unload();
 
     LOG.info("Build ContainerSet costs {}s",
-        (System.currentTimeMillis() - startTime) / 1000);
+        (Time.monotonicNow() - startTime) / 1000);
   }
 
   /**

hadoop-hdds/container-service/src/test/java/org/apache/hadoop/ozone/container/keyvalue/TestKeyValueHandler.java

@@ -68,6 +68,7 @@
 import org.apache.hadoop.ozone.container.common.volume.MutableVolumeSet;
 import org.apache.hadoop.ozone.container.common.volume.StorageVolume;
 import org.apache.hadoop.ozone.container.common.volume.VolumeSet;
+import org.apache.hadoop.util.Time;
 import org.apache.ozone.test.GenericTestUtils.LogCapturer;
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
@@ -442,7 +443,7 @@ public void testDeleteContainerTimeout() throws IOException {
     final ContainerSet containerSet = newContainerSet();
     final MutableVolumeSet volumeSet = mock(MutableVolumeSet.class);
     final Clock clock = mock(Clock.class);
-    long startTime = System.currentTimeMillis();
+    long startTime = Time.monotonicNow();
 
     DatanodeConfiguration dnConf = conf.getObject(DatanodeConfiguration.class);
     when(clock.millis())

hadoop-hdds/container-service/src/test/java/org/apache/hadoop/ozone/container/ozoneimpl/TestContainerReader.java

@@ -68,6 +68,7 @@
 import org.apache.hadoop.ozone.container.keyvalue.KeyValueContainerData;
 import org.apache.hadoop.ozone.container.keyvalue.helpers.BlockUtils;
 import org.apache.hadoop.ozone.container.metadata.DatanodeStoreSchemaThreeImpl;
+import org.apache.hadoop.util.Time;
 import org.apache.ozone.test.GenericTestUtils.LogCapturer;
 import org.apache.ratis.util.FileUtils;
 import org.junit.jupiter.api.AfterEach;
@@ -450,15 +451,15 @@ public void testMultipleContainerReader(ContainerTestVersionInfo versionInfo)
           (HddsVolume) volumes.get(i), containerSet, conf, true);
       threads[i] = new Thread(containerReaders[i]);
     }
-    long startTime = System.currentTimeMillis();
+    long startTime = Time.monotonicNow();
     for (int i = 0; i < volumeNum; i++) {
       threads[i].start();
     }
     for (int i = 0; i < volumeNum; i++) {
       threads[i].join();
     }
     System.out.println("Open " + volumeNum + " Volume with " + containerCount +
-        " costs " + (System.currentTimeMillis() - startTime) / 1000 + "s");
+        " costs " + (Time.monotonicNow() - startTime) / 1000 + "s");
     assertEquals(containerCount,
         containerSet.getContainerMap().entrySet().size());
     assertEquals(volumeSet.getFailedVolumesList().size(), 0);

hadoop-hdds/container-service/src/test/java/org/apache/hadoop/ozone/container/replication/ReplicationSupervisorScheduling.java

@@ -28,6 +28,7 @@
 import java.util.UUID;
 import org.apache.hadoop.hdds.protocol.DatanodeDetails;
 import org.apache.hadoop.hdds.protocol.MockDatanodeDetails;
+import org.apache.hadoop.util.Time;
 import org.junit.jupiter.api.Test;
 
 /**
@@ -104,7 +105,7 @@ public void test() throws InterruptedException {
 
     ReplicationSupervisor rs = ReplicationSupervisor.newBuilder().build();
 
-    final long start = System.currentTimeMillis();
+    final long start = Time.monotonicNow();
 
     //schedule 100 container replication
     for (int i = 0; i < 100; i++) {
@@ -114,7 +115,7 @@ public void test() throws InterruptedException {
       rs.addTask(new ReplicationTask(fromSources(i, sources), replicator));
     }
     rs.shutdownAfterFinish();
-    final long executionTime = System.currentTimeMillis() - start;
+    final long executionTime = Time.monotonicNow() - start;
     System.out.println(executionTime);
     assertThat(executionTime)
         .withFailMessage("Execution was too slow : " + executionTime + " ms")

hadoop-hdds/framework/src/main/java/org/apache/hadoop/hdds/server/events/EventWatcher.java

@@ -33,6 +33,7 @@
 import org.apache.hadoop.ozone.lease.LeaseExpiredException;
 import org.apache.hadoop.ozone.lease.LeaseManager;
 import org.apache.hadoop.ozone.lease.LeaseNotFoundException;
+import org.apache.hadoop.util.Time;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 
@@ -116,7 +117,7 @@ private synchronized void handleStartEvent(TIMEOUT_PAYLOAD payload,
                                              EventPublisher publisher) {
     metrics.incrementTrackedEvents();
     long identifier = payload.getId();
-    startTrackingTimes.put(identifier, System.currentTimeMillis());
+    startTrackingTimes.put(identifier, Time.monotonicNow());
 
     trackedEventsByID.put(identifier, payload);
     trackedEvents.add(payload);
@@ -139,7 +140,7 @@ protected synchronized void handleCompletion(COMPLETION_PAYLOAD
     if (trackedEvents.remove(payload)) {
       metrics.incrementCompletedEvents();
       long originalTime = startTrackingTimes.remove(id);
-      metrics.updateFinishingTime(System.currentTimeMillis() - originalTime);
+      metrics.updateFinishingTime(Time.monotonicNow() - originalTime);
       onFinished(publisher, payload);
     }
   }

hadoop-hdds/framework/src/main/java/org/apache/hadoop/hdds/utils/ProtocolMessageMetrics.java

@@ -28,6 +28,7 @@
 import org.apache.hadoop.metrics2.MetricsTag;
 import org.apache.hadoop.metrics2.lib.DefaultMetricsSystem;
 import org.apache.hadoop.metrics2.lib.Interns;
+import org.apache.hadoop.util.Time;
 import org.apache.ratis.util.UncheckedAutoCloseable;
 
 /**
@@ -68,12 +69,12 @@ public void increment(KEY key, long duration) {
   }
 
   public UncheckedAutoCloseable measure(KEY key) {
-    final long startTime = System.currentTimeMillis();
+    final long startTime = Time.monotonicNow();
     concurrency.incrementAndGet();
     return () -> {
       concurrency.decrementAndGet();
       counters.get(key).incrementAndGet();
-      elapsedTimes.get(key).addAndGet(System.currentTimeMillis() - startTime);
+      elapsedTimes.get(key).addAndGet(Time.monotonicNow() - startTime);
     };
   }