RFR: 8297275: WatchService delay with PollingWatchService causes test failures
Stewart X Addison
duke at openjdk.org
Mon Dec 19 15:23:50 UTC 2022
On Tue, 13 Dec 2022 19:27:28 GMT, Alan Bateman <alanb at openjdk.org> wrote:
>>> Does it always fail on specific systems or it is intermittent?
>>
>> I have an AIX system that reproduces the problem (almost) 100% of the time. Running your example repeatedly shows the following - second timestamp always later than the first, although in some cases (The final one here and the third one) it's very close:
>>
>> bash-5.1$ while true; do jdk-19.0.1+10-jre/bin/java AlanBatemanWatchTest; echo =====; sleep 5; done
>> 2022-12-13T15:14:40.634203242Z
>> 2022-12-13T15:14:40.638408744Z
>> =====
>> 2022-12-13T15:14:45.937219162Z
>> 2022-12-13T15:14:45.944337962Z
>> =====
>> 2022-12-13T15:14:51.23575265Z
>> 2022-12-13T15:14:51.235752651Z
>> =====
>> 2022-12-13T15:14:56.525754548Z
>> 2022-12-13T15:14:56.53320089Z
>> =====
>> 2022-12-13T15:15:01.816169292Z
>> 2022-12-13T15:15:01.82617524Z
>> =====
>> 2022-12-13T15:15:07.096153867Z
>> 2022-12-13T15:15:07.096153868Z
>> =====
>> 2022-12-13T15:15:12.366438085Z
>> 2022-12-13T15:15:12.373201878Z
>> =====
>> 2022-12-13T15:15:17.645776392Z
>> 2022-12-13T15:15:17.645776393Z
>> =====
>
> @sxa Would it be possible to try the following patch to record the timestamps as Instants rather than milliseconds as I suspect the issue is that milliseconds isn't precision enough for these systems. The test that is leading to the discussion here needs improving too but that's another issue. Running with this patch will help tell us if this is the issue you are running into but it's not the right change as file times can be outside of the range supported by Instant but it should be good enough for testing.
>
>
> diff --git a/src/java.base/share/classes/sun/nio/fs/PollingWatchService.java b/src/java.base/share/classes/sun/nio/fs/PollingWatchService.java
> index f86626d196a..ce0f937bb1a 100644
> --- a/src/java.base/share/classes/sun/nio/fs/PollingWatchService.java
> +++ b/src/java.base/share/classes/sun/nio/fs/PollingWatchService.java
> @@ -41,6 +41,7 @@ import java.security.PrivilegedAction;
> import java.security.PrivilegedExceptionAction;
> import java.security.PrivilegedActionException;
> import java.io.IOException;
> +import java.time.Instant;
> import java.util.HashMap;
> import java.util.HashSet;
> import java.util.Iterator;
> @@ -51,6 +52,7 @@ import java.util.concurrent.ScheduledExecutorService;
> import java.util.concurrent.ScheduledFuture;
> import java.util.concurrent.ThreadFactory;
> import java.util.concurrent.TimeUnit;
> +import static java.nio.file.LinkOption.NOFOLLOW_LINKS;
>
> /**
> * Simple WatchService implementation that uses periodic tasks to poll
> @@ -220,10 +222,10 @@ class PollingWatchService
> * Entry in directory cache to record file last-modified-time and tick-count
> */
> private static class CacheEntry {
> - private long lastModified;
> + private Instant lastModified;
> private int lastTickCount;
>
> - CacheEntry(long lastModified, int lastTickCount) {
> + CacheEntry(Instant lastModified, int lastTickCount) {
> this.lastModified = lastModified;
> this.lastTickCount = lastTickCount;
> }
> @@ -232,11 +234,11 @@ class PollingWatchService
> return lastTickCount;
> }
>
> - long lastModified() {
> + Instant lastModified() {
> return lastModified;
> }
>
> - void update(long lastModified, int tickCount) {
> + void update(Instant lastModified, int tickCount) {
> this.lastModified = lastModified;
> this.lastTickCount = tickCount;
> }
> @@ -278,8 +280,7 @@ class PollingWatchService
> try (DirectoryStream<Path> stream = Files.newDirectoryStream(dir)) {
> for (Path entry: stream) {
> // don't follow links
> - long lastModified =
> - Files.getLastModifiedTime(entry, LinkOption.NOFOLLOW_LINKS).toMillis();
> + Instant lastModified = Files.getLastModifiedTime(entry, NOFOLLOW_LINKS).toInstant();
> entries.put(entry.getFileName(), new CacheEntry(lastModified, tickCount));
> }
> } catch (DirectoryIteratorException e) {
> @@ -356,10 +357,9 @@ class PollingWatchService
> // iterate over all entries in directory
> try {
> for (Path entry: stream) {
> - long lastModified = 0L;
> + Instant lastModified;
> try {
> - lastModified =
> - Files.getLastModifiedTime(entry, LinkOption.NOFOLLOW_LINKS).toMillis();
> + lastModified = Files.getLastModifiedTime(entry, NOFOLLOW_LINKS).toInstant();
> } catch (IOException x) {
> // unable to get attributes of entry. If file has just
> // been deleted then we'll report it as deleted on the
> @@ -371,8 +371,7 @@ class PollingWatchService
> CacheEntry e = entries.get(entry.getFileName());
> if (e == null) {
> // new file found
> - entries.put(entry.getFileName(),
> - new CacheEntry(lastModified, tickCount));
> + entries.put(entry.getFileName(), new CacheEntry(lastModified, tickCount));
>
> // queue ENTRY_CREATE if event enabled
> if (events.contains(StandardWatchEventKinds.ENTRY_CREATE)) {
> @@ -391,7 +390,7 @@ class PollingWatchService
> }
>
> // check if file has changed
> - if (e.lastModified != lastModified) {
> + if (!e.lastModified().equals(lastModified)) {
> if (events.contains(StandardWatchEventKinds.ENTRY_MODIFY)) {
> signalEvent(StandardWatchEventKinds.ENTRY_MODIFY,
> entry.getFileName());
>
>
> Update: PR 11665 is now integrated so the last modified time is recorded as a FileTime. It would be good to test with main line to see if you still observe the issue.
@AlanBateman I'm building both options now, but so far 6 attempts with #11665 are looking positive! (I've had to put that fix on top of an older SHA since I'm having problems building the latest code despite @backwaterred's fix at https://github.com/openjdk/jdk/pull/11443
-------------
PR: https://git.openjdk.org/jdk/pull/10824
More information about the nio-dev
mailing list