FSWatcher.close() incurs a big performance cost in >=10.16

[jonjaques]

• Version: 10.16
• Platform: Mac
• Subsystem: fs

There seems to have been a massive performance decrease in FSWatcher.close() introduced in 10.16.

I use ts-node-dev as a file watcher when developing web applications, which under the hood uses filewatcher.

I believe the following commits/PRs could be contributing? Not smart enough to tell you why though 😅

• fs: improve errors from watch, watchFile and unwatchFile #19345
• fs: improve errors thrown from fs.watch() #19089

Some examples w/ a pretty small express app:

10.15

$ nvm use 10.15
$ tsnd src/index 

save some files...

Using ts-node version 8.4.1, typescript version 3.6.4
[INFO] 17:03:16 Restarting: manual restart from user
removing 962 watchers
watcher.removeAll: 5.162ms
Using ts-node version 8.4.1, typescript version 3.6.4
[INFO] 17:03:17 Restarting: manual restart from user
removing 962 watchers
watcher.removeAll: 3.997ms
Using ts-node version 8.4.1, typescript version 3.6.4
[INFO] 17:03:18 Restarting: manual restart from user
removing 962 watchers
watcher.removeAll: 3.915ms
Using ts-node version 8.4.1, typescript version 3.6.4
[INFO] 17:03:18 Restarting: manual restart from user
removing 921 watchers
watcher.removeAll: 2.992ms

10.16

$ nvm use 10.16
$ tsnd src/index

save some files...

Using ts-node version 8.4.1, typescript version 3.6.4
[INFO] 17:05:20 Restarting: manual restart from user
removing 962 watchers
watcher.removeAll: 8631.891ms
Using ts-node version 8.4.1, typescript version 3.6.4
[INFO] 17:05:31 Restarting: manual restart from user
removing 962 watchers
watcher.removeAll: 8679.892ms
Using ts-node version 8.4.1, typescript version 3.6.4
[INFO] 17:05:42 Restarting: manual restart from user
removing 962 watchers
watcher.removeAll: 8679.248ms
Using ts-node version 8.4.1, typescript version 3.6.4
[INFO] 17:05:51 Restarting: manual restart from user
removing 962 watchers
watcher.removeAll: 8764.230ms
Using ts-node version 8.4.1, typescript version 3.6.4

Method

Perf code added to the following: https://github.com/fgnass/filewatcher/blob/master/index.js#L130

FileWatcher.prototype.removeAll = function() {
  console.time("watcher.removeAll");
  console.log(`removing ${this.list().length} watchers`);
  this.list().forEach(this.remove, this);
  console.timeEnd("watcher.removeAll");
};

One might be tempted to think the list() method could be slow, however adding code right above it, a single invocation of watcher.close() took longer than all of them in 10.15.

watcher.close ~/project/node_modules/date-fns/getISOWeekYear/index.js: 6.616ms
watcher.close ~/project/node_modules/date-fns/startOfISOWeek/index.js: 6.514ms
watcher.close ~/project/node_modules/date-fns/startOfWeek/index.js: 6.731ms
watcher.close ~/project/node_modules/date-fns/setISOWeekYear/index.js: 6.540ms
watcher.close ~/project/node_modules/date-fns/startOfISOWeekYear/index.js: 6.447ms
watcher.close ~/project/node_modules/date-fns/differenceInCalendarDays/index.js: 6.563ms
watcher.close ~/project/node_modules/date-fns/_lib/getTimezoneOffsetInMilliseconds/index.js: 6.465ms

[sebdvd]

• Version: 14.17.6
• Platform: macos 11.5.2
• Subsystem: fs

Hello, I noticed too that closing a lot of fs.FSWatcher instances were slow. I recently migrated some big projects to webpack@5 and webpack-dev-server@4, and I noticed that closing the dev server was slow (cf. discussion here webpack/webpack-dev-server#1479 (comment)). I dug in the source code and found that the webpack watch feature uses watchpack@2 and fs.watch and takes a lot of time to close all the watchers. In my case it was about closing ~1200 fs.FSWatcher. So I wrote a few lines of code to reproduce this issue:

const fs = require('fs');
const watchers = [];
for (let n = 0; n < 1200; n += 1) {
  watchers.push(fs.watch(process.cwd()));
}
console.log('closing watchers...');
console.time('closed');
for (let w of watchers) {
  w.close();
}
console.timeEnd('closed');

On my laptop it's quite slow, here the output:

➜ for i in {1..5}; do node script.js; done

closing watchers...
closed: 5.244s
closing watchers...
closed: 5.247s
closing watchers...
closed: 5.217s
closing watchers...
closed: 5.272s
closing watchers...
closed: 5.242s

[heyimalex]

Noticing a similar issue on macOS Monterey 12.4, intel, node: v16.16.0. Closing a watcher takes up to 50ms, so closing 1k+ in a tight loop leads to the process being busy for many seconds. Reproducing is trivial: create 5k watchers and then time the closes:

const fs = require("fs");
const { performance } = require("perf_hooks");

const filenames = [/* 3k+ paths to files/directories */]

filenames
  .map((filename) => fs.watch(filename))
  .forEach((watcher) => {
    const start = performance.now();
    watcher.close();
    const duration = performance.now() - start;
    console.log(duration);
  })

From the output of this it's pretty clear what's happening: the first durations printed are ~35ms and they gradually decrease to sub-ms times, so FSWatcher.close performance scales with the total number of watchers open. Here's close duration plotted against watchers open.

Encountered this issue inside watchpack which "intelligently" replaces non-recursive watchers with recursive watchers when the total number of watchers hits some limit. When this replacement happens, watchpack will close the already-opened watchers, and if there are already a lot of files being watched this can take a long time.