Vscode-remote-release: watcherService: CPU usage rising with number of files in project

[scy]

Issue Type: Bug

When I started VS Code Insiders from WSL today in a Plone (Python) project of mine, I noticed that a node process started using around 55% of my 8-core i7 system a few seconds after startup and would not stop. That process is running inside of WSL, not on the host. (It appears in the Windows task manager though, of course.) Here's what I already did, trying to debug this:

• Disable all extensions except for Remote WSL. No change, CPU usage still too high.
• Install VS Code Stable (not Insiders) 1.35.1 (c7d83e5) with the most recent Remote WSL available (0.38.0). On startup, there's a high-CPU node process, but it stops creating significant CPU load after about 10 to 20 seconds.
• Downgrade Remote WSL in VSC Insiders to 0.38.0, i.e. the same version VSC Stable is using. CPU usage stays at the same high level. (Upgraded again afterwards.)
• Use rsync to mirror the project to the host system and run VSC Insiders there. No issues, not even the shorter CPU burst usage I had noticed in my VSC Stable test from above.
• Inside WSL, rsync the project dir to /tmp, remove .git and start VSC Insiders again. Same issue, so it's not Git-related.
• Move node_modules outside of the project directory, so that VSC can't see it anymore. No change.
• Move away eggs too. Issue goes away. Interesting.
• Check for special files in eggs (find . -not \( -type f -o -type d \)), like symlinks. None found. So it's not just recursive symlinks. There can't be any hard links, since this directory was rsynced with -rtl from the original before.
• Re-create eggs and move about ⅓ of the original directories back in it (eggs contains about 33,000 files and (sub)directories). Issue reappears, but it's now using only about 15% CPU constantly instead of 55%.
• Start VSC in a completely empty directory in WSL. No issue.
• In this empty directory, create 10 directories, each containing 1,000 empty files (for d in $(seq 0 9); do mkdir -p $d; done; for i in $(seq 1 10000); do touch $((x % 10))/file-$i.txt; done). Issue appears, again with lower constant CPU usage (around 15%).

By now, I think that some interaction between the WSL extension and the newer VSC version leads to elevated CPU usage of the file watcher process. This is my ps faux on the 10k files directory I've created in the last step:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root         1  0.0  0.0   9048   512 ?        Ssl  09:44   0:00 /init
root         6  0.0  0.0   8900   224 tty1     Ss   09:44   0:00 /init
scy          7  0.0  0.0 241576  6084 tty1     S    09:44   0:11  \_ -fish
root        65  0.0  0.0  11512   952 ?        Ss   09:44   0:00 /usr/sbin/cron
root      5681  0.0  0.0   8976   228 tty3     Ss   15:51   0:00 /init
scy       5682  0.8  0.0  16468  3928 tty3     S    15:51   0:42  \_ -bash
scy       5361  0.0  0.0  17056  1800 tty3     R    17:19   0:00      \_ ps faux
root      5289  0.0  0.0   9048   232 tty2     Ss   17:18   0:00 /init
scy       5290  0.0  0.0  14584  1636 tty2     S    17:18   0:00  \_ bash ./scripts/wslServer.sh fe0c3e785c22c3ed2d5caa7178488c92d62bdb08 insider .vscode-server-insiders
scy       5293  0.0  0.0  10428   680 tty2     S    17:18   0:00      \_ sh /home/scy/.vscode-server-insiders/bin/fe0c3e785c22c3ed2d5caa7178488c92d62bdb08/server.sh  --port=0
scy       5295  3.9  0.2 964180 36128 tty2     Sl   17:18   0:01          \_ /home/scy/.vscode-server-insiders/bin/fe0c3e785c22c3ed2d5caa7178488c92d62bdb08/node /home/scy/.vscode-server-insiders/bin/fe0c3e785c22c3ed2d5caa7178488c92d62bdb08/out/vs/server/main.js  --port=0
scy       5314 62.8  0.3 914932 58916 tty2     Sl   17:18   0:23              \_ /home/scy/.vscode-server-insiders/bin/fe0c3e785c22c3ed2d5caa7178488c92d62bdb08/node /home/scy/.vscode-server-insiders/bin/fe0c3e785c22c3ed2d5caa7178488c92d62bdb08/out/bootstrap-fork --type=watcherService
scy       5335  3.2  0.2 902772 38764 tty2     Sl   17:18   0:01              \_ /home/scy/.vscode-server-insiders/bin/fe0c3e785c22c3ed2d5caa7178488c92d62bdb08/node /home/scy/.vscode-server-insiders/bin/fe0c3e785c22c3ed2d5caa7178488c92d62bdb08/out/bootstrap-fork --type=extensionHost --uriTransformerPath=/home/scy/.vscode-server-insiders/bin/fe0c3e785c22c3ed2d5caa7178488c92d62bdb08/out/vs/server/uriTransformer.js

As you can see, the --type=watcherService process is eating excessive amounts of CPU. It's not a child of --type=extensionHost, but a sibling. You can also see it in code-insiders --status:

Version:          Code - Insiders 1.36.0-insider (fe0c3e785c22c3ed2d5caa7178488c92d62bdb08, 2019-06-28T12:34:35.956Z)
OS Version:       Windows_NT x64 10.0.18362
CPUs:             Intel(R) Core(TM) i7-7700HQ CPU @ 2.80GHz (8 x 2808)
Memory (System):  15.89GB (5.45GB free)
VM:               0%
Screen Reader:    no
Process Argv:     --folder-uri=vscode-remote://wsl+Debian/tmp/artificial --remote=wsl+Debian
GPU Status:       2d_canvas:                     enabled
                  flash_3d:                      enabled
                  flash_stage3d:                 enabled
                  flash_stage3d_baseline:        enabled
                  gpu_compositing:               enabled
                  multiple_raster_threads:       enabled_on
                  native_gpu_memory_buffers:     disabled_software
                  oop_rasterization:             disabled_off
                  protected_video_decode:        unavailable_off
                  rasterization:                 enabled
                  skia_deferred_display_list:    disabled_off
                  skia_renderer:                 disabled_off
                  surface_synchronization:       enabled_on
                  video_decode:                  enabled
                  viz_display_compositor:        disabled_off
                  webgl:                         enabled
                  webgl2:                        enabled

CPU %   Mem MB     PID  Process
    0       83   15456  code-insiders main
    0      124     248     window (artificial [WSL: Debian] - Welcome)
    0       56   12184       extensionHost
    0       30    4388         electron_node wslDaemon.js 
    0        5   10812           C:\WINDOWS\System32\wsl.exe -d Debian bash -c "'./scripts/wslServer.sh' 'fe0c3e785c22c3ed2d5caa7178488c92d62bdb08' 'insider' '.vscode-server-insiders' ''  "
    0        5    3996             C:\WINDOWS\System32\lxss\wslhost.exe {37a9a09e-9cda-4f53-81d9-433fa2a41a81} 448 464 468
    0       12   17804               console-window-host (Windows internal process)
    0       11    5976             console-window-host (Windows internal process)
    0       65    9028     gpu-process
    0       65    9432     shared-process
    0       14   19276     electron-crash-reporter



Remote:           WSL: Debian
OS Version:       Linux x64 4.4.0-18362-Microsoft
CPUs:             Intel(R) Core(TM) i7-7700HQ CPU @ 2.80GHz (8 x 2801)
Memory (System):  15.89GB (5.53GB free)
VM:               0%
CPU %   Mem MB     PID  Process
    0        0    5295  remote agent
    6        0    5314     watcherService
    0        0    5335     extensionHost
    0        0    5394     /bin/sh -c /bin/ps -ax -o pid=,ppid=,pcpu=,pmem=,command=
    0        0    5395       /bin/ps -ax -o pid=,ppid=,pcpu=,pmem=,command=
Folder (artificial): 10001 files
|      File types: txt(10001)
|      Conf files:

Curiously, in my real project directory, the process does not show up in code-insiders --status, but instead the high CPU usage is attributed to the remote agent. No idea why that is. code-insiders --status looks like this there:

Remote:           WSL: Debian
OS Version:       Linux x64 4.4.0-18362-Microsoft
CPUs:             Intel(R) Core(TM) i7-7700HQ CPU @ 2.80GHz (8 x 2801)
Memory (System):  15.89GB (6.20GB free)
VM:               0%
CPU %   Mem MB     PID  Process
   45        0    6018  remote agent
    0        0    6058     extensionHost
    0        0    6283     /bin/sh -c /bin/ps -ax -o pid=,ppid=,pcpu=,pmem=,command=
    0        0    6284       /bin/ps -ax -o pid=,ppid=,pcpu=,pmem=,command=
Folder (xxxx.xxxxxx): more than 23283 files
|      File types: py(8531) pyc(5863) pyo(2468) txt(1623) dat(1472) zcml(534)
|                  rst(289) pth(186) json(109) js(105)
|      Conf files: grunt.js(3) package.json(2) makefile(1)

While the high-CPU process is running, it starts with using about 220 MB RAM, slowly rises up to 280 MB over the course of about 40 to 60 seconds and then starts again at 220 MB. If I'd have to guess, this looks like an initial indexing run repeating over and over to me.

Let me know if you need any more information. For now, I think I'll use VSC Stable to continue working until there's a solution.

Extension version: 0.38.5
VS Code version: Code - Insiders 1.36.0-insider (fe0c3e785c22c3ed2d5caa7178488c92d62bdb08, 2019-06-28T12:34:35.956Z)
OS version: Windows_NT x64 10.0.18362
Remote OS version: Linux x64 4.4.0-18362-Microsoft

System Info

|Item|Value|
|---|---|
|CPUs|Intel(R) Core(TM) i7-7700HQ CPU @ 2.80GHz (8 x 2808)|
|GPU Status|2d_canvas: enabled
flash_3d: enabled
flash_stage3d: enabled
flash_stage3d_baseline: enabled
gpu_compositing: enabled
multiple_raster_threads: enabled_on
native_gpu_memory_buffers: disabled_software
oop_rasterization: disabled_off
protected_video_decode: unavailable_off
rasterization: enabled
skia_deferred_display_list: disabled_off
skia_renderer: disabled_off
surface_synchronization: enabled_on
video_decode: enabled
viz_display_compositor: disabled_off
webgl: enabled
webgl2: enabled|
|Load (avg)|undefined|
|Memory (System)|15.89GB (5.58GB free)|
|Process Argv|--folder-uri=vscode-remote://wsl+Debian/tmp/artificial --remote=wsl+Debian|
|Screen Reader|no|
|VM|0%|

|Item|Value|
|---|---|
|Remote|WSL: Debian|
|OS|Linux x64 4.4.0-18362-Microsoft|
|CPUs|Intel(R) Core(TM) i7-7700HQ CPU @ 2.80GHz (8 x 2801)|
|Memory (System)|15.89GB (5.58GB free)|
|VM|0%|

[aeschli]

We switched the file watching by polling in WSL1 (non-VM mode) to workaround the WSL issue that non-empty folders are locked and can not be renamed when observed by inotify. While it's clear that that comes at the cost of performance our testing so far looked good. I will investigate what we can do to improve the performance. Right now the polling interval is 1s and things are not configurable.

By default we exclude the node_modules folder from being watched.

I'm not familiar with the 'eggs' folder. Can it be excluded from watching?
If yes, as a workaround on your side I suggest to use files.watcherExclude. It can be set as a workspace setting but also as a machine setting.

[offero]

https://github.com/microsoft/vscode/issues/76303#issuecomment-507298737

I am also experiencing this issue now. It is causing my editing experience to have noticeable lag.

[scy]

We switched the file watching by polling in WSL1 (non-VM mode) to workaround the WSL issue that non-empty folders are locked and can not be renamed when observed by inotify.

@aeschli, thanks for the explanation. Does that mean that this won't be a problem anymore in WSL2, because you can go back to inotify?

By default we exclude the node_modules folder from being watched.

I didn't know about files.watcherExclude before, and I guess most users don't. So you can expect quite a few bug reports once this hits stable. All kinds of languages have directories similar to node_modules, be it eggs in Python, vendor in PHP etc. I'm not sure whether excluding all of these in the default config is feasible.

I'm not familiar with the 'eggs' folder. Can it be excluded from watching?

They are pretty much comparable to node_modules or JAR files:

$ ls eggs | head; find eggs | head
AccessControl-4.0b6-py2.7-linux-x86_64.egg
Acquisition-4.5-py2.7-linux-x86_64.egg
alabaster-0.7.12-py2.7.egg
archetypes.referencebrowserwidget-2.5.10-py2.7.egg
archetypes.schemaextender-3.0.0-py2.7.egg
AuthEncoding-4.1-py2.7.egg
Babel-2.6.0-py2.7.egg
backports.functools_lru_cache-1.5-py2.7.egg
BeautifulSoup-3.2.1-py2.7.egg
beautifulsoup4-4.7.1-py2.7.egg
eggs
eggs/AccessControl-4.0b6-py2.7-linux-x86_64.egg
eggs/AccessControl-4.0b6-py2.7-linux-x86_64.egg/AccessControl
eggs/AccessControl-4.0b6-py2.7-linux-x86_64.egg/AccessControl/AuthEncoding.py
eggs/AccessControl-4.0b6-py2.7-linux-x86_64.egg/AccessControl/AuthEncoding.pyc
eggs/AccessControl-4.0b6-py2.7-linux-x86_64.egg/AccessControl/AuthEncoding.pyo
eggs/AccessControl-4.0b6-py2.7-linux-x86_64.egg/AccessControl/DTML.py
eggs/AccessControl-4.0b6-py2.7-linux-x86_64.egg/AccessControl/DTML.pyc
eggs/AccessControl-4.0b6-py2.7-linux-x86_64.egg/AccessControl/DTML.pyo
eggs/AccessControl-4.0b6-py2.7-linux-x86_64.egg/AccessControl/ImplC.py

So I guess, yeah, they don't need to be watched upon.

If yes, as a workaround on your side I suggest to use files.watcherExclude. It can be set as a workspace setting but also as a machine setting.

After setting .vscode/settings.json to

{
    "files.watcherExclude": {
        "**/eggs": true,
        "**/node_modules": true,
        "**/parts/omelette": true,
    },
}

the watcherService is down to a constant ~1–2% CPU. I guess I can improve this further by finding more directories to exclude.

To be honest, I don't think that I should have to, though. I shouldn't have to configure an internal implementation detail of my IDE for each project I'm using it with, just to keep it from eating all my battery and driving the fan to 11.

Of course I understand that not being able to move/rename files/directories because they're being watched by inotify isn't cool either. Does this apply to rename operations from within WSL too, or just when working with the files from within the Windows host? If it's the latter, then I wonder how many WSL users are really affected by it. I, for example, have my projects only inside WSL, not somewhere under /mnt/c or something. If most users are like me (don't know whether that's the case), I doubt that this issue justifies switching from inotify to polling and thus slowing it down for everyone. At the very least, make it configurable whether to use inotify or polling.

[aeschli]

@scy Yes, this only applies to WSL1. WSL2 uses the regular file watcher

Yes, agree, adding a exclusion pattern is just a workaround, we don't want that regular users have to do anything.

Yes, I'm working on making this configurable.

[aeschli]

I published a new remote WSL extension with a larger polling interval (5s)
The interval is now user configurable (Setting: remote.WSL.fileWatcher.polling). Also, you can turn polling of (value 0)

This requires the latest VSCode insiders... (b7ca272b6e)

[scy]

Thanks for the quick release. The larger polling interval doesn't seem to change CPU usage for me at all, but I can confirm that setting remote.WSL.fileWatcher.polling to 0 solves the CPU usage issue completely. Also, using that setting, I can now answer my own question:

Of course I understand that not being able to move/rename files/directories because they're being watched by inotify isn't cool either. Does this apply to rename operations from within WSL too, or just when working with the files from within the Windows host?

You can't move/rename directories inside of WSL (i.e. those _not_ below /mnt/c etc.) either; you'll get a "permission denied" error. But for now, I can live with that; my workaround is to either close VS Code if I need to rename directories, or use files.watcherExclude as demonstrated in https://github.com/microsoft/vscode-remote-release/issues/864#issuecomment-507670332 to exclude some directories from watching (and thus locking). Looking forward to WSL2 hitting stable. 😉

For my use case, this issue is kind of resolved with the workaround, but I leave closing it up to the VS Code Remote team, maybe you folks want to keep it around for a bit longer. Thanks again!

[aeschli]

Thanks for the feedback.
I released one more version:

• the settings are now split in two: remote.WSL.fileWatcher.polling (boolean) and remote.WSL.fileWatcher.pollingInterval (number).

The default is remote.WSL.fileWatcher.polling=false given your (and of others) feedback.