RFR: 8297275: WatchService delay with PollingWatchService causes test failures
Alan Bateman
alanb at openjdk.org
Tue Dec 13 19:29:58 UTC 2022
On Tue, 13 Dec 2022 15:17:23 GMT, Stewart X Addison <duke at openjdk.org> wrote:
>>> > Would it be possible to run this on the AIX system and paste in the output?
>>>
>>> On AIX:
>>>
>>> ```
>>> 2022-11-28T16:12:18.277871263Z
>>> 2022-11-28T16:12:18.281290513Z
>>> ```
>>
>> Okay, so this means you've got high precision on the last modification time. So for these values it means that registering the directory will read initial time stamp as "2022-11-28T16:12:18.277871263Z", recording it in milliseconds. The file is modified (append in the example) and a short time later the WatchService should read the time stamp as "022-11-28T16:12:18.281290513Z", see that it has changed, and queue ENTRY_MODIFY event. So now I think we are back to why this is not happening on some AIX systems. Does it always fail on specific systems or it is intermittent? Any mount options or other config that enables or disables higher precision time stamps?
>
>> 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());
-------------
PR: https://git.openjdk.org/jdk/pull/10824
More information about the nio-dev
mailing list