fileWatcher at 100% CPU

Jason3S commented 2 months ago

Type: Performance Issue

fileWatcher process oftens gets stuck at 100% CPU.

It seems to be SCM related, but hard to tell.

VS Code version: Code 1.92.2 (Universal) (fee1edb8d6d72a0ddff41e5f71a671c23ed924b9, 2024-08-14T17:29:30.058Z) OS version: Darwin x64 23.6.0 Modes:

System Info

|Item|Value| |---|---| |CPUs|Intel(R) Core(TM) i9-9880H CPU @ 2.30GHz (16 x 2300)| |GPU Status|2d_canvas: enabled
canvas_oop_rasterization: disabled_off
direct_rendering_display_compositor: disabled_off_ok
gpu_compositing: enabled
multiple_raster_threads: enabled_on
opengl: enabled_on
rasterization: enabled
raw_draw: disabled_off_ok
skia_graphite: disabled_off
video_decode: enabled
video_encode: enabled
webgl: enabled
webgl2: enabled
webgpu: enabled
webnn: disabled_off| |Load (avg)|5, 4, 4| |Memory (System)|32.00GB (4.10GB free)| |Process Argv|--crash-reporter-id 21ae0ece-62a2-4681-a5cf-c687ea23e753| |Screen Reader|no| |VM|0%|

Process Info

``` CPU % Mem MB PID Process 19 262 838 code main 8 98 2931 gpu-process 0 0 2940 utility-network-service 0 164 4942 shared-process 0 0 99421 /bin/ps -ax -o pid=,ppid=,pcpu=,pmem=,command= 0 33 4944 ptyHost 0 0 5774 /bin/zsh -il 0 33 6283 node 0 0 6678 /bin/zsh -il 0 0 32740 /bin/zsh -il 0 0 33276 /bin/zsh -il 0 33 34358 npm run watch 0 33 34382 node /Users/jason/projects/vscode-spell-checker/node_modules/.bin/concurrently npm:watch:esbuild npm:watch:api npm:watch:tsc 0 33 34385 npm run watch:esbuild 0 33 34457 npm run build:esbuild --watch 0 33 34572 node ./build.mjs --watch 13 197 34613 /Users/jason/projects/vscode-spell-checker/node_modules/@esbuild/darwin-x64/bin/esbuild --service=0.23.1 --ping 0 33 34387 npm run watch:tsc 0 33 34488 npm run build:tsc --watch 0 328 34611 node /Users/jason/projects/vscode-spell-checker/node_modules/.bin/tsc -p tsconfig.test.json --watch 0 0 74824 /bin/zsh -il 5 1049 74656 window [15] (urlUtil.test.mts — Spell Checker (Workspace)) 99 66 74822 fileWatcher [15] 0 1769 74823 extensionHost [15] 0 229 75316 PHP Language Server 0 66 75552 electron-nodejs (server-node.js ) 0 164 75725 /Applications/Visual Studio Code.app/Contents/Frameworks/Code Helper (Plugin).app/Contents/MacOS/Code Helper (Plugin) /Users/jason/.vscode/extensions/streetsidesoftware.code-spell-checker-4.0.10/packages/_server/dist/main.cjs --node-ipc --clientProcessId=74823 0 164 80839 electron-nodejs (eslintServer.js ) 0 328 80849 electron-nodejs (tsserver.js ) 0 754 80850 electron-nodejs (tsserver.js ) 0 98 80888 electron-nodejs (typingsInstaller.js typesMap.js ) 0 197 80870 electron-nodejs (server.js ) 0 98 80872 /Applications/Visual Studio Code.app/Contents/Frameworks/Code Helper (Plugin).app/Contents/MacOS/Code Helper (Plugin) /Users/jason/.vscode/extensions/streetsidesoftware.code-spell-checker-4.0.10/packages/_serverPatternMatcher/dist/main.cjs --node-ipc --clientProcessId=74823 0 98 80873 mdx-language-server 2 66 99339 window [22] (Issue Reporter) ```

Workspace Info

Extensions (93)

Extension|Author (truncated)|Version ---|---|--- terraform|4op|0.2.5 ada|Ada|24.0.6 commit-message-editor|ada|0.25.0 tsl-problem-matcher|amo|0.6.2 alignment|ann|0.3.0 cpupro|ant|0.1.1 vscode-zipfs|arc|3.0.0 astro-vscode|ast|2.14.1 npm-intellisense|chr|1.4.5 jison-syntax-highlight|cru|0.1.1 scala|dal|0.0.5 vscode-jq-playground|dav|4.3.5 vscode-eslint|dba|3.0.13 vscode-wasm|dts|1.4.1 gitlens|eam|15.3.0 EditorConfig|Edi|0.16.4 prettier-vscode|esb|11.0.0 linter-gfortran|for|3.2.0 copilot|Git|1.223.0 copilot-chat|Git|0.18.2 remotehub|Git|0.62.0 vscode-github-actions|git|0.26.3 vscode-pull-request-github|Git|0.94.0 gitpod-desktop|git|0.0.172 yaml-plus-json|hil|1.12.2 mediawiki|jak|2.1.0 latex-workshop|Jam|10.1.0 svg|joc|1.5.4 jq-syntax-highlighting|jq-|0.0.2 vscode-tree-sitter-query|jri|0.0.6 language-haskell|jus|3.6.0 vscode-cfml|Kam|0.5.4 bison|lun|0.1.0 Kotlin|mat|1.7.1 Lisp|mat|0.1.12 rainbow-csv|mec|3.12.0 dotenv|mik|1.0.1 vscode-apache|mrm|1.2.0 vscode-puglint|mrm|2.3.0 vscode-azureresourcegroups|ms-|0.9.2 vscode-docker|ms-|1.29.2 vscode-dotnet-runtime|ms-|2.1.2 al|ms-|13.1.1065068 playwright|ms-|1.1.7 black-formatter|ms-|2024.2.0 debugpy|ms-|2024.10.0 isort|ms-|2023.10.1 python|ms-|2024.12.3 vscode-pylance|ms-|2024.8.1 jupyter|ms-|2024.7.0 jupyter-keymap|ms-|1.1.2 jupyter-renderers|ms-|1.0.19 vscode-jupyter-cell-tags|ms-|0.1.9 vscode-jupyter-slideshow|ms-|0.1.6 remote-containers|ms-|0.380.0 remote-ssh|ms-|0.113.1 remote-ssh-edit|ms-|0.86.0 remote-wsl|ms-|0.88.2 azure-account|ms-|0.12.0 azure-repos|ms-|0.38.0 cpptools|ms-|1.21.6 cpptools-extension-pack|ms-|1.3.0 live-server|ms-|0.4.14 powershell|ms-|2024.2.2 remote-explorer|ms-|0.4.3 remote-repositories|ms-|0.40.0 test-adapter-converter|ms-|0.1.9 vscode-js-profile-flame|ms-|1.0.9 vsliveshare|ms-|1.0.5936 vetur|oct|0.37.3 common-lisp|qin|1.2.11 vscode-yaml|red|1.15.0 rust-analyzer|rus|0.3.2078 es6-mocha-snippets|spo|0.2.2 avro|str|0.5.0 code-spell-checker|str|4.0.10 code-spell-checker-british-english|str|1.4.11 code-spell-checker-portuguese|str|2.0.2 code-spell-checker-portuguese-brazilian|str|2.2.1 hunspell|str|1.0.4 iconfont-preview|stx|0.0.5 svelte-vscode|sve|108.6.0 even-better-toml|tam|0.19.2 msbuild-project-tools|tin|0.6.5 es6-string-html|Tob|2.16.0 vscode-mdx|uni|1.8.10 intellicode-api-usage-examples|Vis|0.2.8 vscodeintellicode|Vis|1.3.1 vscode-gradle|vsc|3.16.4 vscode-java-debug|vsc|0.58.0 debug|web|0.27.0 php-debug|xde|1.35.0 php-intellisense|zob|1.3.3 (1 theme extensions excluded)

A/B Experiments

``` vsliv368:30146709 vspor879:30202332 vspor708:30202333 vspor363:30204092 vscod805:30301674 binariesv615:30325510 vsaa593:30376534 py29gd2263:31024239 vscaac:30438847 c4g48928:30535728 azure-dev_surveyone:30548225 vscrp:30673768 2i9eh265:30646982 962ge761:30959799 pythongtdpath:30769146 welcomedialogc:30910334 pythonnoceb:30805159 asynctok:30898717 pythonregdiag2:30936856 pythonmypyd1:30879173 2e7ec940:31000449 pythontbext0:30879054 accentitlementsc:30995553 dsvsc016:30899300 dsvsc017:30899301 dsvsc018:30899302 cppperfnew:31000557 dsvsc020:30976470 pythonait:31006305 dsvsc021:30996838 945dj816:31013170 pythoncenvpt:31062603 a69g1124:31058053 dvdeprecation:31068756 dwnewjupyter:31046869 impr_priority:31102340 refactort:31108082 pythonrstrctxt:31112756 wkspc-onlycs-c:31111717 wkspc-ranged-c:31118571 ```

It is hard to say if it is related, but copilot tends to get stuck after killing the watcher.

Jason3S commented 2 months ago

A bit more information:

Restarting the Extension Host doesn't seem to make a difference. The fileWatcher still runs at 100%.
Sometimes there is more than one fileWatcher process running. But only 1 seems to get stuck at 100%.
Killing the fileWatcher process using Process Explorer seems to help, but the issue often comes back a few minutes later.
Restarting VSCode helps for longer.
Note: I tend to keep VSCode open for days.
The issue is intermittent.
Seems to happen more often when debugging a VSCode Extension.
Started happening about 2 months ago.

bpasero commented 2 months ago

Does it go away if you set typescript.tsserver.experimental.useVsCodeWatcher to false.

And can you share a repository where this happens easy to reproduce?

Jason3S commented 2 months ago

@bpasero,

Thank you.

It is not easy to reproduce.

Here is the repo: https://github.com/streetsidesoftware/vscode-spell-checker

Setup is:

npm install
npm run build

Does it go away if you set typescript.tsserver.experimental.useVsCodeWatcher to false.

I will try it out. It might be related, since it seem to happen quicker if I do a bit of refactoring or delete node_modules and rebuild.

bpasero commented 2 months ago

Thank you.

balazsbajorics commented 1 month ago

I had a similar problem with the fileWatcher pinning a CPU to 100%, and indeed setting typescript.tsserver.experimental.useVsCodeWatcher to false fixed it for me!

the repository is https://github.com/concrete-utopia/utopia, working inside the editor folder has been making the filewatcher spin on 100% for weeks now.

Jason3S commented 1 month ago

I had a similar problem with the fileWatcher pinning a CPU to 100%, and indeed setting typescript.tsserver.experimental.useVsCodeWatcher to false fixed it for me!

the repository is https://github.com/concrete-utopia/utopia, working inside the editor folder has been making the filewatcher spin on 100% for weeks now.

@balazsbajorics,

Thank you for the repo case.

I hadn't found a good case in my own repos to properly test it out.

bpasero commented 1 month ago

@balazsbajorics thanks, I tried to repro (on macOS) but do not see that. Is there a build step involved (maybe PNPM?) to get this into that state?

When I set log level to trace and open the file watcher output channel, I only see a small amount of recursively watched folders, maybe you could check too:


[File Watcher] request stats:

[Summary]
- Recursive Requests:     total: 125, suspended: 118, polling: 3
- Non-Recursive Requests: total: 1339, suspended: 3, polling: 0
- Recursive Watchers:     total: 7, active: 7, failed: 0, stopped: 0
- Non-Recursive Watchers: total: 1336, active: 6, failed: 7, reusing: 1323
- I/O Handles Impact:     total: 16
- ```

bpasero commented 1 month ago

ℹ I would appreciate if people impacted here could try out our latest insiders build (commit c4efe1dc9eec4914f3076b2d954fe4fe174a5820). It includes a change to reduce the pressure of file watching from the TypeScript extension.

Steps:

download insiders from https://code.visualstudio.com/insiders/
configure typescript.tsserver.experimental.useVsCodeWatcher to the default value of true
please make sure your files.watcherExclude setting does not include **/node_modules/*/**
perform your workload that was showing issues

Happy to hear back how it goes 🙏

tmm1 commented 1 month ago

hi @bpasero, i have been tracking this issue as well (albeit in a vscode 1.91.1 fork), and I have reason to believe this would be fixed by upgrading:

https://github.com/microsoft/vscode/blob/7eae20c99c42a2954cea8be92f0dbe39e2951776/package.json#L77

to v2.3.0 or newer, to include: https://github.com/parcel-bundler/watcher/pull/146

when this happened to me earlier, I attached Instruments.app (and after loading the associated v29.4.0 electron dSYMs), saw the following:

it appears to be stuck in this loop:

https://github.com/libuv/libuv/blob/32603fd5ff56ea4634c66ce2941a053f5d381edd/src/unix/async.c#L197-L202

  while (!uv__queue_empty(&queue)) {
    q = uv__queue_head(&queue);
    h = uv__queue_data(q, uv_async_t, queue);

    uv__queue_remove(q);
    uv__queue_insert_tail(&loop->async_handles, q);

this makes little sense, and could only happen if something massively got corrupted in the linked list somehow.

on the libuv side, things have been stable for quite a while. there are some old issues that describe possibly-related behavior:

on windows, there was mention of uv_send_async from a nodejs extension causing weird behavior in the early days of electron https://github.com/electron/electron/issues/11699
https://github.com/libuv/libuv/pull/3879
https://github.com/libuv/libuv/pull/2231

nothing directly confirming my theory in these old threads.. but if a process running nothing but the watcher.node ext is causing uv to loop, removing the calls into libuv from that extension may help?

tmm1 commented 1 month ago

The easiest way to diagnose this is using /usr/bin/sample <fileWatcherPid>. If you have the correct version of the electron dSYMs downloaded and extracted, it will produce accurate call traces as so:

Call graph:
    2094 Thread_8903082   DispatchQueue_1: com.apple.main-thread  (serial)
    + 2094 start  (in dyld) + 2360  [0x185d490e0]
    +   2094 main (in Electron Helper) (electron_main_mac.cc:84) + 2544  [0x104d289f0]
    +     2094 ElectronMain (in Electron Framework) (electron_library_main.mm:26) + 180  [0x10e1a57fc]
    +       2094 content::ContentMain(content::ContentMainParams) (in Electron Framework) (content_main.cc:347) + 299864  [0x10e4ab024]
    +         2094 content::RunContentProcess(content::ContentMainParams, content::ContentMainRunner*) (in Electron Framework) (content_main.cc:334) + 299412  [0x10e4aae60]
    +           2094 content::ContentMainRunnerImpl::Run() (in Electron Framework) (content_main_runner_impl.cc:0) + 305156  [0x10e4ac4d0]
    +             2094 content::RunOtherNamedProcessTypeMain(std::__Cr::basic_string<char, std::__Cr::char_traits<char>, std::__Cr::allocator<char>> const&, content::MainFunctionParams, content::ContentMainDelegate*) (in Electron Framework) (content_main_runner_impl.cc:775) + 301824  [0x10e4ab7cc]
    +               2094 content::UtilityMain(content::MainFunctionParams) (in Electron Framework) (utility_main.cc:444) + 18717632  [0x110ea14b0]
    +                 2094 base::RunLoop::Run(base::Location const&) (in Electron Framework) (run_loop.cc:136) + 24943996  [0x11149166c]
    +                   2094 base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::Run(bool, base::TimeDelta) (in Electron Framework) (thread_controller_with_message_pump_impl.cc:631) + 25173124  [0x1114c9574]
    +                     2094 base::MessagePumpDefault::Run(base::MessagePump::Delegate*) (in Electron Framework) (message_pump_default.cc:41) + 24788856  [0x11146b868]
    +                       2094 non-virtual thunk to base::sequence_manager::internal::ThreadControllerWithMessagePumpImpl::DoWork() (in Electron Framework) (thread_controller_with_message_pump_impl.cc:0) + 25170312  [0x1114c8a78]
    +                         2094 base::TaskAnnotator::RunTaskImpl(base::PendingTask&) (in Electron Framework) (task_annotator.cc:201) + 25052240  [0x1114abd40]
    +                           2094 electron::NodeBindings::UvRunOnce() (in Electron Framework) (node_bindings.cc:891) + 17652  [0x10e32cac0]
    +                             2094 uv_run (in Electron Framework) (core.c:0) + 372  [0x10e194a60]
    +                               2094 uv__io_poll (in Electron Framework) (kqueue.c:0) + 1552  [0x10e1a4f88]
    +                                 2094 uv__async_io (in Electron Framework) (async.c:165) + 1124,1148,...  [0x10e19456c,0x10e194584,...]

bpasero commented 1 month ago

@tmm1 👏 great findings. Yes, @deepak1556 and me where tracing this issue as well some weeks ago using Instruments and found the call site, but were clueless as to how this could happen. We also figured out that updating to latest parcel watcher resolves this issue and that is actually the reason I went ahead and started an experiment to try out this new version. Unfortunately it has a serious bug and a engineering change that currently block us from adopting this version:

The former, I was able to address in https://github.com/parcel-bundler/watcher/pull/189 but needs a newer release.

The endless CPU spike only seems to happen when a massive amount of paths is watched at the same time, potentially overlapping, as it is the case before https://github.com/microsoft/vscode/commit/88b706b2bb41b85a82e183801fd1b9a090fa95ce landed where I enforce the TypeScript extension to re-use the workspace watcher instead of spawning their own.

I am still trying to get newer parcel watcher builds, but we are currently blocked and I hope things move on again soon so that we can update.

Thanks for your contributions to the watcher, if you see more things, please make sure to let us know 🙏

tmm1 commented 1 month ago

Wow you guys are way ahead of me. Thanks for all the links, as I had missed this side of the discussion!

I suspected the npm distribution changes might be a problem. I will take a look there.

patroza commented 1 week ago

here I thought my MacBook was dying. turns out it's the age old file watching 🚀 science problem

my current workaround settings:

 "files.watcherExclude": {
    "**/.bloop": true,
    "**/.metals": true,
    "**/.ammonite": true,
    "**/.git/objects/**": true,
    "**/.git/subtree-cache/**": true,
    "**/.hg/store/**": true,
    "**/node_modules/**": true
  },
  // https://github.com/microsoft/vscode/issues/226050#issuecomment-2354708049
  "typescript.tsserver.experimental.useVsCodeWatcher": false,

tmm1 commented 4 days ago

@bpasero I just saw this issue occur on vscode 1.94.2 on a large typescript project, so I suspect the workaround in https://github.com/microsoft/vscode/pull/228703 is not effective

bpasero commented 4 days ago

@tmm1 we are still not on the latest Parcel version, pending an update from their end, so I would think its still possible that this issue can happen, just less likely because we no longer have overlapping file system registrations.

See https://github.com/microsoft/vscode/issues/216825

tmm1 commented 4 days ago

Right. I can confirm using the latest parcel version (including your deadlock fix) has not replicated this issue for us in several weeks.

But on the latest vscode (with old parcel version + overlapping workaround), it seems to happen just as frequently as before.

bpasero commented 4 days ago

But on the latest vscode (with old parcel version + overlapping workaround), it seems to happen just as frequently as before.

Enabling trace level and printing what the file watcher channel prints as watched paths, can you share that to see what kind of watching situation you have before it happens?

microsoft / vscode

fileWatcher at 100% CPU #226050