RFR: 8297275: WatchService delay with PollingWatchService causes test failures
Stewart X Addison
duke at openjdk.org
Tue Dec 20 15:37: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've submitted a backport for 11665 to jdk17u-dev since that's looking positive: https://github.com/openjdk/jdk17u-dev/pull/957
What's the process for getting it into jdk20? Can I just PR to `jdk20` in the absence of a `-dev` branch for it?
-------------
PR: https://git.openjdk.org/jdk/pull/10824
More information about the nio-dev
mailing list