Measure minimum racy interval to auto-configure FileSnapshot

By running FileSnapshotTest#detectFileModified we found that the sum of
measured filesystem timestamp resolution and measured clock resolution
may yield a too small interval after a file has been modified which we
need to consider racily clean. In our tests we didn't find this behavior
on all systems we tested on, e.g. on MacOS using APFS and Java 8 and 11
this effect was not observed.

On Linux (SLES 15, kernel 4.12.14-150.22-default) we collected the
following test results using Java 8 and 11:

In 23-98% of 10000 test runs (depending on filesystem type and Java
version) the test failed, which means the effective interval which needs
to be considered racily clean after a file was modified is larger than
the measured file timestamp resolution.

"delta" is the observed interval after a file has been modified but
FileSnapshot did not yet detect the modification:

"resolution" is the measured sum of file timestamp resolution and clock
resolution seen in Java.

Java version    filesystem  failures resolution  min delta   max delta
1.8.0_212-b04   btrfs	    98.6%       1 ms        3.6 ms      6.6 ms
1.8.0_212-b04   ext4        82.6%       3 ms        1.1 ms      4.1 ms
1.8.0_212-b04   xfs         23.8%       4 ms        3.7 ms      3.9 ms
1.8.0_212-b04   zfs         23.1%       3 ms        4.8 ms      5.0 ms
11.0.3+7        btrfs       98.1%       3 us        0.7 ms      4.7 ms
11.0.3+7        ext4        98.1%       6 us        0.7 ms      4.7 ms
11.0.3+7        xfs         98.5%       7 us        0.1 ms      8.0 ms
11.0.3+7        zfs         98.4%       7 us        0.7 ms      5.2 ms

Mac OS
1.8.0_212       APFS        0%          1 s
11.0.3+7        APFS        0%          6 us

The observed delta is not distributed according to a normal gaussian
distribution but rather random in the observed range between "min delta"
and "max delta".

Run this test after measuring file timestamp resolution in
FS.FileAttributeCache to auto-configure JGit since it's unclear what
mechanism is causing this effect.

In FileSnapshot#isRacyClean use the maximum of the measured timestamp
resolution and the measured "delta" as explained above to decide if a
given FileSnapshot is to be considered racily clean. Add a 30% safety
margin to ensure we are on the safe side.

Change-Id: I1c8bb59f6486f174b7bbdc63072777ddbe06694d
Signed-off-by: Matthias Sohn <matthias.sohn@sap.com>

4 files changed, 27 insertions, 11 deletions

diff --git a/org.eclipse.jgit.test/tst-rsrc/log4j.properties b/org.eclipse.jgit.test/tst-rsrc/log4j.properties
index a48a4022ff..ee1ac35158 100644
--- a/org.eclipse.jgit.test/tst-rsrc/log4j.properties
+++ b/org.eclipse.jgit.test/tst-rsrc/log4j.properties
@@ -8,4 +8,7 @@ log4j.appender.stdout.Target=System.out
 log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
 log4j.appender.stdout.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n
 #log4j.appender.fileLogger.bufferedIO = true
-#log4j.appender.fileLogger.bufferSize = 1024
\ No newline at end of file
+#log4j.appender.fileLogger.bufferSize = 4096
+
+#log4j.logger.org.eclipse.jgit.util.FS = DEBUG
+#log4j.logger.org.eclipse.jgit.internal.storage.file.FileSnapshot = DEBUG
diff --git a/org.eclipse.jgit.test/tst/org/eclipse/jgit/internal/storage/file/FileSnapshotTest.java b/org.eclipse.jgit.test/tst/org/eclipse/jgit/internal/storage/file/FileSnapshotTest.java
index 9eb55db09c..012407f715 100644
--- a/org.eclipse.jgit.test/tst/org/eclipse/jgit/internal/storage/file/FileSnapshotTest.java
+++ b/org.eclipse.jgit.test/tst/org/eclipse/jgit/internal/storage/file/FileSnapshotTest.java
@@ -62,6 +62,7 @@ import java.util.ArrayList;
 import java.util.concurrent.TimeUnit;
 
 import org.eclipse.jgit.util.FS;
+import org.eclipse.jgit.util.FS.FileStoreAttributeCache;
 import org.eclipse.jgit.util.FileUtils;
 import org.eclipse.jgit.util.Stats;
 import org.eclipse.jgit.util.SystemReader;
@@ -78,14 +79,15 @@ public class FileSnapshotTest {
 
 	private Path trash;
 
-	private Duration fsTimerResolution;
+	private FileStoreAttributeCache fsAttrCache;
 
 	@Before
 	public void setUp() throws Exception {
 		trash = Files.createTempDirectory("tmp_");
 		// measure timer resolution before the test to avoid time critical tests
 		// are affected by time needed for measurement
-		fsTimerResolution = FS.getFsTimerResolution(trash.getParent());
+		fsAttrCache = FS
+				.getFileStoreAttributeCache(trash.getParent());
 	}
 
 	@Before
@@ -131,11 +133,13 @@ public class FileSnapshotTest {
 		// if filesystem timestamp resolution is high the snapshot won't be
 		// racily clean
 		Assume.assumeTrue(
-				fsTimerResolution.compareTo(Duration.ofMillis(10)) > 0);
+				fsAttrCache.getFsTimestampResolution()
+						.compareTo(Duration.ofMillis(10)) > 0);
 		Path f1 = createFile("newfile");
 		waitNextTick(f1);
 		FileSnapshot save = FileSnapshot.save(f1.toFile());
-		TimeUnit.NANOSECONDS.sleep(fsTimerResolution.dividedBy(2).toNanos());
+		TimeUnit.NANOSECONDS.sleep(
+				fsAttrCache.getFsTimestampResolution().dividedBy(2).toNanos());
 		assertTrue(save.isModified(f1.toFile()));
 	}
 
@@ -149,7 +153,8 @@ public class FileSnapshotTest {
 		// if filesystem timestamp resolution is high the snapshot won't be
 		// racily clean
 		Assume.assumeTrue(
-				fsTimerResolution.compareTo(Duration.ofMillis(10)) > 0);
+				fsAttrCache.getFsTimestampResolution()
+						.compareTo(Duration.ofMillis(10)) > 0);
 		Path f1 = createFile("newfile");
 		FileSnapshot save = FileSnapshot.save(f1.toFile());
 		assertTrue(save.isModified(f1.toFile()));
@@ -230,7 +235,7 @@ public class FileSnapshotTest {
 			write(f, "b");
 			if (!snapshot.isModified(f)) {
 				deltas.add(snapshot.lastDelta());
-				racyNanos = snapshot.lastRacyNanos();
+				racyNanos = snapshot.lastRacyThreshold();
 				failures++;
 			}
 			assertEquals("file should contain 'b'", "b", read(f));
@@ -244,7 +249,7 @@ public class FileSnapshotTest {
 				LOG.debug(String.format("%,d", d));
 			}
 			LOG.error(
-					"count, failures, racy limit [ns], delta min [ns],"
+					"count, failures, eff. racy threshold [ns], delta min [ns],"
 							+ " delta max [ns], delta avg [ns],"
 							+ " delta stddev [ns]");
 			LOG.error(String.format(
@@ -253,7 +258,14 @@ public class FileSnapshotTest {
 					stats.avg(), stats.stddev()));
 		}
 		assertTrue(
-				"FileSnapshot: number of failures to detect file modifications should be 0",
+				String.format(
+						"FileSnapshot: failures to detect file modifications"
+								+ " %d out of %d\n"
+								+ "timestamp resolution %d µs"
+								+ " min racy threshold %d µs"
+						, failures, COUNT,
+						fsAttrCache.getFsTimestampResolution().toNanos() / 1000,
+						fsAttrCache.getMinimalRacyInterval().toNanos() / 1000),
 				failures == 0);
 	}
 
diff --git a/org.eclipse.jgit.test/tst/org/eclipse/jgit/storage/file/FileBasedConfigTest.java b/org.eclipse.jgit.test/tst/org/eclipse/jgit/storage/file/FileBasedConfigTest.java
index d3686285e3..77f5febc17 100644
--- a/org.eclipse.jgit.test/tst/org/eclipse/jgit/storage/file/FileBasedConfigTest.java
+++ b/org.eclipse.jgit.test/tst/org/eclipse/jgit/storage/file/FileBasedConfigTest.java
@@ -83,7 +83,7 @@ public class FileBasedConfigTest {
 	@Before
 	public void setUp() throws Exception {
 		trash = Files.createTempDirectory("tmp_");
-		FS.getFsTimerResolution(trash.getParent());
+		FS.getFileStoreAttributeCache(trash.getParent());
 	}
 
 	@After
diff --git a/org.eclipse.jgit.test/tst/org/eclipse/jgit/util/FSTest.java b/org.eclipse.jgit.test/tst/org/eclipse/jgit/util/FSTest.java
index bde8a8a6b3..63e295ec83 100644
--- a/org.eclipse.jgit.test/tst/org/eclipse/jgit/util/FSTest.java
+++ b/org.eclipse.jgit.test/tst/org/eclipse/jgit/util/FSTest.java
@@ -203,7 +203,8 @@ public class FSTest {
 				.ofPattern("uuuu-MMM-dd HH:mm:ss.nnnnnnnnn", Locale.ENGLISH)
 				.withZone(ZoneId.systemDefault());
 		Path dir = Files.createTempDirectory("probe-filesystem");
-		Duration resolution = FS.getFsTimerResolution(dir);
+		Duration resolution = FS.getFileStoreAttributeCache(dir)
+				.getFsTimestampResolution();
 		long resolutionNs = resolution.toNanos();
 		assertTrue(resolutionNs > 0);
 		for (int i = 0; i < 10; i++) {