HDFS-15215. The Timestamp for longest write/read lock held log is wrong

hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/util/FakeTimer.java

@@ -29,17 +29,19 @@ import org.apache.hadoop.classification.InterfaceStability;
 @InterfaceAudience.Private
 @InterfaceStability.Unstable
 public class FakeTimer extends Timer {
+  private long now;
   private long nowNanos;
 
   /** Constructs a FakeTimer with a non-zero value */
   public FakeTimer() {
     // Initialize with a non-trivial value.
+    now = 1577836800000L; // 2020-01-01 00:00:00,000+0000
     nowNanos = TimeUnit.MILLISECONDS.toNanos(1000);
   }
 
   @Override
   public long now() {
-    return TimeUnit.NANOSECONDS.toMillis(nowNanos);
+    return now;
   }
 
   @Override
@@ -54,6 +56,7 @@ public class FakeTimer extends Timer {
 
   /** Increases the time by milliseconds */
   public void advance(long advMillis) {
+    now += advMillis;
     nowNanos += TimeUnit.MILLISECONDS.toNanos(advMillis);
   }
 
@@ -62,6 +65,7 @@ public class FakeTimer extends Timer {
    * @param advNanos Nanoseconds to advance by.
    */
   public void advanceNanos(long advNanos) {
+    now += TimeUnit.NANOSECONDS.toMillis(advNanos);
     nowNanos += advNanos;
   }
 }

hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/FSNamesystemLock.java

@@ -164,9 +164,9 @@ class FSNamesystemLock {
 
   public void readUnlock(String opName) {
     final boolean needReport = coarseLock.getReadHoldCount() == 1;
-    final long currentTimeStampNanos = timer.monotonicNowNanos();
     final long readLockIntervalNanos =
-        currentTimeStampNanos - readLockHeldTimeStampNanos.get();
+        timer.monotonicNowNanos() - readLockHeldTimeStampNanos.get();
+    final long currentTimeMs = timer.now();
     coarseLock.readLock().unlock();
 
     if (needReport) {
@@ -175,8 +175,6 @@ class FSNamesystemLock {
     }
     final long readLockIntervalMs =
         TimeUnit.NANOSECONDS.toMillis(readLockIntervalNanos);
-    final long currentTimeMs =
-        TimeUnit.NANOSECONDS.toMillis(currentTimeStampNanos);
     if (needReport && readLockIntervalMs >= this.readLockReportingThresholdMs) {
       LockHeldInfo localLockHeldInfo;
       do {
@@ -246,10 +244,9 @@ class FSNamesystemLock {
   public void writeUnlock(String opName, boolean suppressWriteLockReport) {
     final boolean needReport = !suppressWriteLockReport && coarseLock
         .getWriteHoldCount() == 1 && coarseLock.isWriteLockedByCurrentThread();
-    final long currentTimeNanos = timer.monotonicNowNanos();
     final long writeLockIntervalNanos =
-        currentTimeNanos - writeLockHeldTimeStampNanos;
-    final long currentTimeMs = TimeUnit.NANOSECONDS.toMillis(currentTimeNanos);
+        timer.monotonicNowNanos() - writeLockHeldTimeStampNanos;
+    final long currentTimeMs = timer.now();
     final long writeLockIntervalMs =
         TimeUnit.NANOSECONDS.toMillis(writeLockIntervalNanos);
 

hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/TestFSNamesystemLock.java

@@ -210,7 +210,7 @@ public class TestFSNamesystemLock {
     assertTrue(pattern.matcher(logs.getOutput()).find());
     // only keep the "yyyy-MM-dd" part of date
     String startTimeStr =
-        "held at " + Time.formatTime(timer.monotonicNow()).substring(0, 10);
+        "held at " + Time.formatTime(timer.now()).substring(0, 10);
     assertTrue(logs.getOutput().contains(startTimeStr));
     assertTrue(logs.getOutput().contains(
         "Number of suppressed write-lock reports: 2"));
@@ -301,7 +301,7 @@ public class TestFSNamesystemLock {
     assertTrue(tLongPattern.matcher(logs.getOutput()).find());
     // only keep the "yyyy-MM-dd" part of date
     String startTimeStr =
-        "held at " + Time.formatTime(timer.monotonicNow()).substring(0, 10);
+        "held at " + Time.formatTime(timer.now()).substring(0, 10);
     assertTrue(logs.getOutput().contains(startTimeStr));
     assertTrue(logs.getOutput().contains(
         "Number of suppressed read-lock reports: 3"));