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>

1 files changed, 4 insertions, 1 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