(Windows) Unknown and unexpected results

[Arcanemagus]

Prerequisites

• Put an X between the brackets on this line if you have done all of the following:
  • Reproduced the problem in Safe Mode: http://flight-manual.atom.io/hacking-atom/sections/debugging/#using-safe-mode
  • Followed all applicable steps in the debugging guide: http://flight-manual.atom.io/hacking-atom/sections/debugging/
  • Checked the FAQs on the message board for common solutions: https://discuss.atom.io/c/faq
  • Checked that your issue isn't already filed: https://github.com/issues?utf8=✓&q=is%3Aissue+user%3Aatom
  • Checked that there is not already an Atom package that provides the described functionality: https://atom.io/packages

Description

When testing using watcher-stress, I'm getting quite a bit of unexpected modification results (~75%), half of the renamed results are "split half unknown" (48%), and all deletion results are unknown.

Steps to Reproduce

1. watcher-stress --logging-dir C:\Users\abneyl\watcher-logs\polling\ --root C:\temp --exercise parallel --watcher-count 1

Expected behavior:

Accuracy to be 100% on all types?

Actual behavior:

I got the following output:

--seed ZRHCm255wrYje8KJw5zDkQnDtsKdMkZcw6rCr3nCoUpdw6FXw6xZwpcMPyNSw4TCtsOswrU4w58QHsKgT8KLwr0pL8Oow64gQMOaJsKeCkMRd8KXKsKoS8OJTcOoLsOTwp7DssKEwqnCgsOZw7nDhkt+fMOowr0bDjvDhcOCIS7Cl2XCr2zDpg0kZcODIMKzw7/Cph0aPBjChcOJS8KHwoTDhHPDqHRCVSc2w6fDrsOPwq/DgcK0HzIDLHgvwpdhayogLsOFDsKwDcKUw6fDsFx3YXzDn8Kvwo3DjMO2ecKmcsKjwpVBwp13GsKVHsOmLCnDq8Olw6LDvT/CsAA1wqnDn3hdBhkoEsOVc8KSdsK1R8Kvw40jw5vDiFjDjCPCrghswr1AT0pew7zDpRfChcOfSMOAwqBawr0Sw6A5EcO8DsKyc8Kpw7nDiMOnMyjCvMOJwpJedXgPJsOqWykYw4/DpHcaw7Alw6BCVzLDjjVFw6gQYATCmg==


>> PARALLEL WATCHER STRESS TEST <<
watcher #0 started on C:\temp\root-0

>> 1 WATCHERS STARTED <<

>> RESOURCE USAGE <<
uptime 1.27 seconds (1.268s)
CPU usage: 578000 user 687000 system
RAM usage: rss 39.87 M (39874560b) total heap 18.72 M (18718720b) used heap 11.52 M (11519120b) external 147.89 k (147888b)

>> CREATING FILESYSTEM EVENTS <<
................................................................................
................................................................................
................................................................................
................................................................................
................................................................................
................................................................................
................................................................................
................................................................................
................................................................................
................................................................................
................................................................................
................................................................................
........................................
>> RESOURCE USAGE <<
uptime 3.41 seconds (3.411s)
CPU usage: 781000 user 1453000 system
RAM usage: rss 50.33 M (50327552b) total heap 29.2 M (29204480b) used heap 15.85 M (15846216b) external 197.04 k (197040b)

>> STOPPING WATCHERS <<
watcher #0 stopped
>> 1 WATCHERS STOPPED <<


>> ACCURACY <<
created total: 307
 - exact: 307 (100%)
 - unknown: 0 (0%)
 - unexpected: 0 (0%)
 - missed: 0 (0%)
modified total: 1265
 - exact: 328 (25.92%)
 - unknown: 0 (0%)
 - unexpected: 937 (74.07%)
 - missed: 0 (0%)
deleted total: 275
 - exact: 0 (0%)
 - unknown: 275 (100%)
 - unexpected: 0 (0%)
 - missed: 0 (0%)
renamed total: 90
 - exact: 47 (52.22%)
 - unknown: 0 (0%)
 - split exact: 0 (0%)
 - split half unknown: 43 (47.77%)
 - split full unknown: 0 (0%)
 - unexpected: 0 (0%)
 - missed: 0 (0%)

>> LATENCY <<
 - mean: 1.81 milliseconds (1.808ms)
 - median: 2 milliseconds (2ms)
 - 95%: 3 milliseconds (3ms)
 - maximum: 7 milliseconds (7ms)

>> RESOURCE USAGE <<
uptime 3.43 seconds (3.434s)
CPU usage: 594000 user 687000 system
RAM usage: rss 49.49 M (49487872b) total heap 29.2 M (29204480b) used heap 16.05 M (16046224b) external 197.04 k (197040b)

Reproduces how often:

Seems to be 100% of the time, at the least 4 different runs all seem to be in the same ballpark.

Versions

@atom/watcher@0.0.7

Additional Information

Attached are zips of the logs generated, as well as the test directory.
watcher-93-root-0.zip
watcher-93-polling.zip

If this should instead be filed over on watcher-stress just let me know!

[smashwilson]

Ah, thanks for taking this for a spin! Those results are roughly in line with what I'm seeing here, too.

quite a bit of unexpected modification results (~75%)

I do expect some amount of noise in the modification results. Some platforms emit a modification event immediately after a file is created which watcher-stress isn't currently expecting. I've filed #95 to make sure we're being consistent here.

It doesn't look like this is happening for you, but I've also seen rapid modifications of the same file be coalesced into a single modification event (MacOS does this pretty aggressively). So some amount of "missed" modifications is not unusual either.

75% seems awfully high though... I'll 🔎 and see if there's something else going on 😄

all deletion results are unknown

This is a known platform limitation, although I didn't have an issue for it, yet. I've filed one at #96. Basically, ReadDirectoryChangesW doesn't include flags for "file" or "directory" in its callback, so when an entry is deleted we don't have any way to tell what it was and just emit it as KIND_UNKNOWN.

half of the renamed results are "split half unknown" (48%)

"Split" renames happen when a rename can't be correlated properly and is reported as separate creation and deletion events. "Half unknown" refers to one of those two events having an unknown kind. So this means that these events are being delivered like:

{ action: "deleted", kind: "unknown", path: "C:\root\old.txt" }
{ action: "created", kind: "file", path: "C:\root\new.txt" }

To contrast, "split exact" events would both be kind: "file", and "split full unknown" would both be kind: "unknown". On Windows right now, renames are always going to be either correlated exactly, split half unknown, or (rarely) split full unknown (if the renamed entry is deleted before the callback is next triggered). #96 will help with the "half unknown" part for the same reasons listed above, and #84 should reduce the number of split renames overall.

Accuracy to be 100% on all types?

Alas, we'll never be able to quite get all the way there 😅 There just isn't high enough fidelity in the underlying event stream delivered by the OS. At high enough event rates, we're going to drop some events, too.

I've been living on atom/atom#16124's branch for a few days now we already seem to be good enough for a comfortable editing experience, though. We're solidly ahead of --use nsfw in watcher-stress too. At this point, my goal is to asymptotically improve accuracy as much as I have time for until I vanish off the Internet for a few months to be a dad, then ship what I've got when I'm back to actually follow-through with support once we're live in 😄

[smashwilson]

quite a bit of unexpected modification results (~75%)

Ahh, I think Windows is a lot more aggressive about reporting modifications for directories. I'll have to see if I can filter those out somehow.

[Arcanemagus]

Forgot to mention that a serial test gave similar numbers, which since you're saying this is a platform issue makes perfect sense 😉.