From e60b9e1879f8774e1afe07be4224605045f49eec Mon Sep 17 00:00:00 2001 From: Han-Wen Nienhuys Date: Wed, 31 Jul 2019 17:27:47 +0200 Subject: [PATCH] FileSnapshot: fix bug with timestamp thresholding Increase the safety factor to 2.5x for extra safety if max of measured timestamp resolution and measured minimal racy threshold is < 100ms, use 1.25 otherwise since for large filesystem resolution values the influence of finite resolution of the system clock should be negligible. Before, not yet using the newly introduced minRacyThreshold measurement, the threshold was 1.1x FS resolution, and we could issue the following sequence of events, start create-file read-file (currentTime) end which had the following timestamps: create-file 1564589081998 start 1564589082002 read 1564589082003 end 1564589082004 In this case, the difference between create-file and read is 5ms, which exceeded the 4ms FS resolution, even though the events together took just 2ms of runtime. Reproduce with: bazel test --runs_per_test=100 \ //org.eclipse.jgit.test:org_eclipse_jgit_internal_storage_file_FileSnapshotTest The file system timestamp resolution is 4ms in this case. This code assumes that the kernel and the JVM use the same clock that is synchronized with the file system clock. This seems plausible, given the resolution of System.currentTimeMillis() and the latency for a gettimeofday system call (typically ~1us), but it would be good to justify this with specifications. Also cover a source of flakiness: if the test runs under extreme load, then we could have start create-file read end which would register as an unmodified file. Avoid this by skipping the test if end-start is too big. [msohn]: - downported from master to stable-5.1 - skip test if resolution is below 10ms - adjust safety factor to 1.25 for resolutions above 100ms Change-Id: I87d2cf035e01c44b7ba8364c410a860aa8e312ef Signed-off-by: Han-Wen Nienhuys Signed-off-by: Matthias Sohn --- .../storage/file/FileSnapshotTest.java | 36 ++++++++++++++----- .../internal/storage/file/FileSnapshot.java | 5 +-- 2 files changed, 31 insertions(+), 10 deletions(-) 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 40af9e2a0..6fa35d64b 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 @@ -47,6 +47,7 @@ import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertTrue; +import static org.junit.Assert.fail; import java.io.File; import java.io.IOException; @@ -150,14 +151,33 @@ public void testNewFileWithWait() throws Exception { */ @Test public void testNewFileNoWait() throws Exception { - // if filesystem timestamp resolution is high the snapshot won't be - // racily clean - Assume.assumeTrue( - fsAttrCache.getFsTimestampResolution() - .compareTo(Duration.ofMillis(10)) > 0); - Path f1 = createFile("newfile"); - FileSnapshot save = FileSnapshot.save(f1.toFile()); - assertTrue(save.isModified(f1.toFile())); + // if filesystem timestamp resolution is smaller than time needed to + // create a file and FileSnapshot the snapshot won't be racily clean + Assume.assumeTrue(fsAttrCache.getFsTimestampResolution() + .compareTo(Duration.ofMillis(10)) > 0); + for (int i = 0; i < 50; i++) { + Instant start = Instant.now(); + Path f1 = createFile("newfile"); + FileSnapshot save = FileSnapshot.save(f1.toFile()); + Duration res = FS.getFileStoreAttributes(f1) + .getFsTimestampResolution(); + Instant end = Instant.now(); + if (Duration.between(start, end) + .compareTo(res.multipliedBy(2)) > 0) { + // This test is racy: under load, there may be a delay between createFile() and + // FileSnapshot.save(). This can stretch the time between the read TS and FS + // creation TS to the point that it exceeds the FS granularity, and we + // conclude it cannot be racily clean, and therefore must be really clean. + // + // This should be relatively uncommon. + continue; + } + // The file wasn't really modified, but it looks just like a "maybe racily clean" + // file. + assertTrue(save.isModified(f1.toFile())); + return; + } + fail("too much load for this test"); } /** diff --git a/org.eclipse.jgit/src/org/eclipse/jgit/internal/storage/file/FileSnapshot.java b/org.eclipse.jgit/src/org/eclipse/jgit/internal/storage/file/FileSnapshot.java index 77005100e..976f946e5 100644 --- a/org.eclipse.jgit/src/org/eclipse/jgit/internal/storage/file/FileSnapshot.java +++ b/org.eclipse.jgit/src/org/eclipse/jgit/internal/storage/file/FileSnapshot.java @@ -523,8 +523,9 @@ private long getEffectiveRacyThreshold() { .getFsTimestampResolution().toNanos(); long minRacyInterval = fileStoreAttributeCache.getMinimalRacyInterval() .toNanos(); - // add a 30% safety margin - return Math.max(timestampResolution, minRacyInterval) * 13 / 10; + long max = Math.max(timestampResolution, minRacyInterval); + // safety margin: factor 2.5 below 100ms otherwise 1.25 + return max < 100_000_000L ? max * 5 / 2 : max * 5 / 4; } private boolean isModified(Instant currLastModified) {