FS: use binary search to determine filesystem timestamp resolution

Previous code used a minimum granularity of 1 microsecond and would
iterate 233 times on a system where the resolution is 1 second (for
instance, Java 8 on Mac APFS).

New code uses a binary search between the maximum we care about (2
seconds) and zero, with a minimum granularity of also 1 microsecond.
This takes at most 19 iterations (guaranteed). For a file system with 1
second resolution, it takes 4 iterations (1s, 0.5s, 0.8s, 0.9s). With
an up-front check at 1 microsecond and at 1 millisecond this performs
equally well as the old code on file systems with a fine resolution.
(For instance, Java 11 on Mac APFS.)

Also handle obscure cases where the file timestamp implementation may
yield bogus values (as observed on HP NonStop). If such an error case
occurs, log a warning and abort the measurement at the last good value.

Bug: 565707
Change-Id: I82a96729b50c284be7c23fbdf3d0df1bddf60e41
Signed-off-by: Thomas Wolf <thomas.wolf@paranor.ch>

3 files changed, 127 insertions, 13 deletions

diff --git a/org.eclipse.jgit/resources/org/eclipse/jgit/internal/JGitText.properties b/org.eclipse.jgit/resources/org/eclipse/jgit/internal/JGitText.properties
index 4eee09faff..beafff3811 100644
--- a/org.eclipse.jgit/resources/org/eclipse/jgit/internal/JGitText.properties
+++ b/org.eclipse.jgit/resources/org/eclipse/jgit/internal/JGitText.properties
@@ -408,6 +408,9 @@ lockError=lock error: {0}
 lockFailedRetry=locking {0} failed after {1} retries
 lockOnNotClosed=Lock on {0} not closed.
 lockOnNotHeld=Lock on {0} not held.
+logInconsistentFiletimeDiff={}: inconsistent duration from file timestamps on {}, {}: {} > {}, but diff = {}. Aborting measurement at resolution {}.
+logLargerFiletimeDiff={}: inconsistent duration from file timestamps on {}, {}: diff = {} > {} (last good value). Aborting measurement.
+logSmallerFiletime={}: got smaller file timestamp on {}, {}: {} < {}. Aborting measurement at resolution {}.
 logXDGConfigHomeInvalid=Environment variable XDG_CONFIG_HOME contains an invalid path {}
 maxCountMustBeNonNegative=max count must be >= 0
 mergeConflictOnNonNoteEntries=Merge conflict on non-note entries: base = {0}, ours = {1}, theirs = {2}
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/internal/JGitText.java b/org.eclipse.jgit/src/org/eclipse/jgit/internal/JGitText.java
index 583a386f14..3f2565fdde 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/internal/JGitText.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/internal/JGitText.java
@@ -436,6 +436,9 @@ public class JGitText extends TranslationBundle {
 	/***/ public String lockFailedRetry;
 	/***/ public String lockOnNotClosed;
 	/***/ public String lockOnNotHeld;
+	/***/ public String logInconsistentFiletimeDiff;
+	/***/ public String logLargerFiletimeDiff;
+	/***/ public String logSmallerFiletime;
 	/***/ public String logXDGConfigHomeInvalid;
 	/***/ public String maxCountMustBeNonNegative;
 	/***/ public String mergeConflictOnNonNoteEntries;
diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/util/FS.java b/org.eclipse.jgit/src/org/eclipse/jgit/util/FS.java
index c645ba927a..bf7b753693 100644
--- a/org.eclipse.jgit/src/org/eclipse/jgit/util/FS.java
+++ b/org.eclipse.jgit/src/org/eclipse/jgit/util/FS.java
@@ -186,12 +186,18 @@ public abstract class FS {
 	 */
 	public static final class FileStoreAttributes {
 
+		/**
+		 * Marker to detect undefined values when reading from the config file.
+		 */
 		private static final Duration UNDEFINED_DURATION = Duration
 				.ofNanos(Long.MAX_VALUE);
 
 		/**
 		 * Fallback filesystem timestamp resolution. The worst case timestamp
 		 * resolution on FAT filesystems is 2 seconds.
+		 * <p>
+		 * Must be at least 1 second.
+		 * </p>
 		 */
 		public static final Duration FALLBACK_TIMESTAMP_RESOLUTION = Duration
 				.ofMillis(2000);
@@ -204,6 +210,25 @@ public abstract class FS {
 		public static final FileStoreAttributes FALLBACK_FILESTORE_ATTRIBUTES = new FileStoreAttributes(
 				FALLBACK_TIMESTAMP_RESOLUTION);
 
+		private static final long ONE_MICROSECOND = TimeUnit.MICROSECONDS
+				.toNanos(1);
+
+		private static final long ONE_MILLISECOND = TimeUnit.MILLISECONDS
+				.toNanos(1);
+
+		private static final long ONE_SECOND = TimeUnit.SECONDS.toNanos(1);
+
+		/**
+		 * Minimum file system timestamp resolution granularity to check, in
+		 * nanoseconds. Should be a positive power of ten smaller than
+		 * {@link #ONE_SECOND}. Must be strictly greater than zero, i.e.,
+		 * minimum value is 1 nanosecond.
+		 * <p>
+		 * Currently set to 1 microsecond, but could also be lower still.
+		 * </p>
+		 */
+		private static final long MINIMUM_RESOLUTION_NANOS = ONE_MICROSECOND;
+
 		private static final String JAVA_VERSION_PREFIX = System
 				.getProperty("java.vendor") + '|' //$NON-NLS-1$
 				+ System.getProperty("java.version") + '|'; //$NON-NLS-1$
@@ -500,24 +525,21 @@ public abstract class FS {
 
 		private static Optional<Duration> measureFsTimestampResolution(
 			FileStore s, Path dir) {
-			LOG.debug("{}: start measure timestamp resolution {} in {}", //$NON-NLS-1$
-					Thread.currentThread(), s, dir);
+			if (LOG.isDebugEnabled()) {
+				LOG.debug("{}: start measure timestamp resolution {} in {}", //$NON-NLS-1$
+						Thread.currentThread(), s, dir);
+			}
 			Path probe = dir.resolve(".probe-" + UUID.randomUUID()); //$NON-NLS-1$
 			try {
 				Files.createFile(probe);
-				FileTime t1 = Files.getLastModifiedTime(probe);
-				FileTime t2 = t1;
-				Instant t1i = t1.toInstant();
-				for (long i = 1; t2.compareTo(t1) <= 0; i += 1 + i / 20) {
-					Files.setLastModifiedTime(probe,
-							FileTime.from(t1i.plusNanos(i * 1000)));
-					t2 = Files.getLastModifiedTime(probe);
-				}
-				Duration fsResolution = Duration.between(t1.toInstant(), t2.toInstant());
+				Duration fsResolution = getFsResolution(s, dir, probe);
 				Duration clockResolution = measureClockResolution();
 				fsResolution = fsResolution.plus(clockResolution);
-				LOG.debug("{}: end measure timestamp resolution {} in {}", //$NON-NLS-1$
-						Thread.currentThread(), s, dir);
+				if (LOG.isDebugEnabled()) {
+					LOG.debug(
+							"{}: end measure timestamp resolution {} in {}; got {}", //$NON-NLS-1$
+							Thread.currentThread(), s, dir, fsResolution);
+				}
 				return Optional.of(fsResolution);
 			} catch (SecurityException e) {
 				// Log it here; most likely deleteProbe() below will also run
@@ -534,6 +556,92 @@ public abstract class FS {
 			return Optional.empty();
 		}
 
+		private static Duration getFsResolution(FileStore s, Path dir,
+				Path probe) throws IOException {
+			File probeFile = probe.toFile();
+			FileTime t1 = Files.getLastModifiedTime(probe);
+			Instant t1i = t1.toInstant();
+			FileTime t2;
+			Duration last = FALLBACK_TIMESTAMP_RESOLUTION;
+			long minScale = MINIMUM_RESOLUTION_NANOS;
+			long scale = ONE_SECOND;
+			long high = TimeUnit.MILLISECONDS.toSeconds(last.toMillis());
+			long low = 0;
+			// Try up-front at microsecond and millisecond
+			long[] tries = { ONE_MICROSECOND, ONE_MILLISECOND };
+			for (long interval : tries) {
+				if (interval >= ONE_MILLISECOND) {
+					probeFile.setLastModified(
+							t1i.plusNanos(interval).toEpochMilli());
+				} else {
+					Files.setLastModifiedTime(probe,
+							FileTime.from(t1i.plusNanos(interval)));
+				}
+				t2 = Files.getLastModifiedTime(probe);
+				if (t2.compareTo(t1) > 0) {
+					Duration diff = Duration.between(t1i, t2.toInstant());
+					if (!diff.isZero() && !diff.isNegative()
+							&& diff.compareTo(last) < 0) {
+						scale = interval;
+						high = 1;
+						last = diff;
+						break;
+					}
+				} else {
+					// Makes no sense going below
+					minScale = Math.max(minScale, interval);
+				}
+			}
+			// Binary search loop
+			while (high > low) {
+				long mid = (high + low) / 2;
+				if (mid == 0) {
+					// Smaller than current scale. Adjust scale.
+					long newScale = scale / 10;
+					if (newScale < minScale) {
+						break;
+					}
+					high *= scale / newScale;
+					low *= scale / newScale;
+					scale = newScale;
+					mid = (high + low) / 2;
+				}
+				long delta = mid * scale;
+				if (scale >= ONE_MILLISECOND) {
+					probeFile.setLastModified(
+							t1i.plusNanos(delta).toEpochMilli());
+				} else {
+					Files.setLastModifiedTime(probe,
+							FileTime.from(t1i.plusNanos(delta)));
+				}
+				t2 = Files.getLastModifiedTime(probe);
+				int cmp = t2.compareTo(t1);
+				if (cmp > 0) {
+					high = mid;
+					Duration diff = Duration.between(t1i, t2.toInstant());
+					if (diff.isZero() || diff.isNegative()) {
+						LOG.warn(JGitText.get().logInconsistentFiletimeDiff,
+								Thread.currentThread(), s, dir, t2, t1, diff,
+								last);
+						break;
+					} else if (diff.compareTo(last) > 0) {
+						LOG.warn(JGitText.get().logLargerFiletimeDiff,
+								Thread.currentThread(), s, dir, diff, last);
+						break;
+					}
+					last = diff;
+				} else if (cmp < 0) {
+					LOG.warn(JGitText.get().logSmallerFiletime,
+							Thread.currentThread(), s, dir, t2, t1, last);
+					break;
+				} else {
+					// No discernible difference
+					low = mid + 1;
+				}
+			}
+			return last;
+		}
+
 		private static Duration measureClockResolution() {
 			Duration clockResolution = Duration.ZERO;
 			for (int i = 0; i < 10; i++) {