Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Typescript server repetitively "initializing language features" causing high CPU usage in extension v107.2.5 #1963

Open
mpearce-bain opened this issue Mar 24, 2023 · 14 comments
Labels
bug Something isn't working

Comments

@mpearce-bain
Copy link

Describe the bug

When working in a Svelte repository with a TS and Svelte file open, VSCode begins rapidly flashing the initializing JS/TS language features notification in the bottom LH bar. I also notice the notification bell in the bottom RH bar flickering on and off with a new notification. This drives high CPU usage and noticeably slows down intellisense in my repo.

This behavior doesn't appear to be linked to any user input other than opening both *.svelte and *.ts files concurrently, and it will continue indefinitely until the VSCode instance is restarted. Running the Typescript: Restart Language Server command will temporarily halt the behavior, but it resumes within 30s afterward. If TS logging is turned on, the logs will grow indefinitely in size (in one instance I had a 2GB log file in <5 minutes).

I'm noticing the following lines appearing over and over in the Svelte output tab of my terminal. I am not modifying the tsconfig.json file at all, so it's odd to me it's detecting an updated config.

Reloading ts service at c:/Users/{my-project-directory} due to config updated
Trying to load configs for c:/Users/{my-project-directory}

Would anyone be able to suggest a potential next troubleshooting step?

Troubleshooting Attempts

  • Restart TS Language Server
  • Restart VSCode
  • Clean Install of VSCode
  • Update to latest nightly version of TS

Reproduction

  • Open my Svelte directory with both TS & Svelte files in VS Code

    • Unfortunately I haven't been able to reproduce with a hello-world project , so I'm aware that this could mean there is an issue with my configs. I'm hoping I might be able to get any guidance or suggestions on next troubleshooting steps)
  • Disable all extensions apart from 'Svelte for VS Code'

  • Open both a *.svelte and *.ts simultaneously in your window

Frustratingly, I can't share my full project directory because it's proprietary, but I have tried to narrow down the issue to a subset of causes. What I have noticed is that the error is reproducible using the latest Svelte for VSCode extention v107.2.5, but disapears when using any version prior to v106.0.0 -- even when using the same project directory with no code changes.

Expected behaviour

  • Initializing JS/TS language features appears once in the status bar and disappears after several seconds

System Info

  • OS: Windows 10
  • IDE: VS Code [details below]
  • Svelte VS Code Extension: v107.2.5
   Version: 1.76.2 (user setup)
   Commit: ee2b180d582a7f601fa6ecfdad8d9fd269ab1884
   Date: 2023-03-14T17:55:54.936Z
   Electron: 19.1.11
   Chromium: 102.0.5005.196
   Node.js: 16.14.2
   V8: 10.2.154.26-electron.0
   OS: Windows_NT x64 10.0.19044
   Sandboxed: Yes

Which package is the issue about?

Svelte for VS Code extension

Additional Information, eg. Screenshots

No response

@mpearce-bain mpearce-bain added the bug Something isn't working label Mar 24, 2023
@dummdidumm
Copy link
Member

dummdidumm commented Mar 24, 2023

Since you said it's not reproducible with a hello world example, could you provide a repository that reproduces this for you? Maybe you can provide a stripped down/anonymous version of your private repository

@mpearce-bain
Copy link
Author

mpearce-bain commented Mar 25, 2023

After much debugging this morning, I believe I've found a way to reproduce the error.

  1. In a fresh folder, run npm init vite and select the standalone svelte option with TypeScript to generate a hello-world app
  2. Follow the commands to cd into vite-project and npm install
  3. Open the vite-project folder in VS Code (v1.76.2) with the only extension being Svelte for VS Code (v107.2.5).
  4. Open App.svelte
  5. If you view the Svelte Output tab in your Terminal, the following lines will be repeatedly triggered every few seconds even with no user interaction:

Reloading ts service at c:/Users/{your-dir}/vite-project/tsconfig.json due to config updated
Trying to load configs for c:/Users/{your-dir}/vite-project

I also noticed an associated spike in CPU usage that hovers around 15-20% for VS Code even if I'm not interacting with the window at all.

If you repeat the exact same steps, but with Svelte for VS Code (v105.22.1), these reloading ts service commands are not triggered repeatedly and there is no associated spike in CPU usage. Instead there is one instance of the following:

Trying to load configs for c:/Users/{your-dir}/vite-project
Loaded config at c:\Users{your-dir}\vite-project\svelte.config.js

@jasonlyu123
Copy link
Member

I can't reproduce it with the vite template. Can you check if the tsconfig.json is constantly getting updated? Checking it In both the current and the version that you think there isn't a bug.

In your terminal, use the node command to enter the node REPL. And run the following to register file watchers.

fs.watch(require.resolve('@tsconfig/svelte/tsconfig.json'), (e) => console.log('@tsconfig/svelte/tsconfig.json', e))
fs.watch('./tsconfig.json', (e) => console.log('./tsconfig.json', e))

@mpearce-bain
Copy link
Author

When using v107.2.5 of the extension and running the file watcher commands, it is showing that the tsconfig is constantly being updated in the background. Could that be due to my node installation perhaps? For context I'm running v16.13.1

@tsconfig/svelte/tsconfig.json change
@tsconfig/svelte/tsconfig.json change
@tsconfig/svelte/tsconfig.json change
@tsconfig/svelte/tsconfig.json change
@tsconfig/svelte/tsconfig.json change
...

When trying with the same repo and v105.22.1 of the Svelte for VS Code extension, the watcher commands don't generate any output.

@dummdidumm
Copy link
Member

Interesting - so from extension v106.0.0 onwards you see the watchers constantly firing change events?

@mpearce-bain
Copy link
Author

Yep, I just tried again with v106.0.0 and was able to see the change events firing on @tsconfig/svelte/tsconfig.json. It doesn't seem to be related to any user input -- I can swap extension versions, reload the window and the file watchers will start triggering.

@jasonlyu123
Copy link
Member

jasonlyu123 commented Mar 29, 2023

I scanned through TypeScript's watch file implementation and our codebase, but I still can't figure out where the file got updated. This might be a weird way to check it. But can you try changing the file permission to delay "write"? This way, when the file is written, an error will be thrown.

  1. In file explorer, right-click the "node_modules/@tsconfig/svelte/tsconfig.json" file
  2. Choose properties
  3. Choose the Security tab.
  4. Choose your user to edit and check the deny checkbox of "write" and apply the change.
  5. Check if the output channel has any errors.
  6. Revert the change

@mpearce-bain
Copy link
Author

Thanks for continuing to help follow up on this Jason!

I tried explicitly denying write permissions as you mentioned, but it didn't throw any errors in the output channel. I verified that the permissions were indeed changed by trying to manually modify and save the file, which I was prevented from doing. Below I've included more examples of the output. Is there anything else I can provide to try and nail this down?

Reloading ts service at  c:/Users/{your-dir}/vite-project/tsconfig.json  due to config updated
Trying to load configs for c:/Users/{your-dir}/vite-project
[Trace - 2:56:07 PM] Received notification 'textDocument/publishDiagnostics'.
[Trace - 2:56:07 PM] Received request 'workspace/inlayHint/refresh - (110)'.
[Trace - 2:56:07 PM] Sending response 'workspace/inlayHint/refresh - (110)'. Processing request took 0ms
[Trace - 2:56:07 PM] Received request 'workspace/semanticTokens/refresh - (111)'.
[Trace - 2:56:07 PM] Sending response 'workspace/semanticTokens/refresh - (111)'. Processing request took 0ms
[Trace - 2:56:07 PM] Sending request 'textDocument/semanticTokens/full - (61)'.
Executing next invocation of "getSemanticTokens" with low priority
Reloading ts service at  c:/Users/{your-dir}/vite-project/tsconfig.json  due to config updated
Trying to load configs for c:/Users/{your-dir}/vite-project
[Trace - 2:56:09 PM] Received notification 'textDocument/publishDiagnostics'.
[Trace - 2:56:09 PM] Received response 'textDocument/semanticTokens/full - (61)' in 1663ms.
[Trace - 2:56:09 PM] Received request 'workspace/inlayHint/refresh - (112)'.
[Trace - 2:56:09 PM] Sending response 'workspace/inlayHint/refresh - (112)'. Processing request took 0ms
[Trace - 2:56:09 PM] Received request 'workspace/semanticTokens/refresh - (113)'.
[Trace - 2:56:09 PM] Sending response 'workspace/semanticTokens/refresh - (113)'. Processing request took 0ms
[Trace - 2:56:09 PM] Sending request 'textDocument/semanticTokens/full - (62)'.
Reloading ts service at  c:/Users/{your-dir}/vite-project/tsconfig.json  due to config updated
Trying to load configs for c:/Users/{your-dir}/vite-project
[Trace - 2:56:10 PM] Received response 'textDocument/semanticTokens/full - (62)' in 668ms.
....

@jasonlyu123
Copy link
Member

If it weren't being written, maybe something is changing the file's attributes, like permission. https://nodejs.org/api/fs.html#stat-time-values. In that case, the "Modified Time" doesn't change but the "Change Time" changes. But I still have no idea who is doing that. An antivirus software?

I think we can skip reloading if "Modified Time" doesn't change. But that wouldn't change the "initializing language features" thing. That's out of our control. We have a different instance of TypeScript language service separate from the TSServer. It'll solve the "Reloading ts service at c:/Users/{your-dir}/vite-project/tsconfig.json due to config updated" problem. And probably the high CPU usage problem since our reloading is less efficient.

@dummdidumm
Copy link
Member

Could it be that due to us and typescript polling for file updates, that this poll is somehow modifying file attributes which triggers the other watcher to think something changed?

@jasonlyu123
Copy link
Member

I also suspected that, but I can't reproduce it even when I explicitly set the option to use polling instead of fs event. Also, it seems like all polling file-watch implementations in TypeScript check modified time.

https://github.com/microsoft/TypeScript/blob/27d3454f07cb41a24275d7f1de07621b8217f739/src/compiler/sys.ts#L244
https://github.com/microsoft/TypeScript/blob/27d3454f07cb41a24275d7f1de07621b8217f739/src/compiler/sys.ts#L435
https://github.com/microsoft/TypeScript/blob/27d3454f07cb41a24275d7f1de07621b8217f739/src/compiler/sys.ts#L1758

This doc explains the possible watch options:
https://www.typescriptlang.org/docs/handbook/configuring-watch.html

fs event doesn't check it, though. It directly forwards the callback to fs.watch of node.js. So it's likely because of the fs event implementation.

@dummdidumm
Copy link
Member

Should we try a shot in the blue and replace tsSystem.watchFile with chokidar? It's in our dependencies anyway.

@mpearce-bain
Copy link
Author

@jasonlyu123 @dummdidumm you are both wizards 🧙🏻 thank you!

By switching to the latest 107.3.0 release incorporating your PR (#1973), the repetitive Reloading ts service at c:/Users/{your-dir}/vite-project/tsconfig.json due to config updated messages were resolved. I'm no longer able to recreate that reloading behaviour in hello-world or in my private repo.

I'm curious, you mentioned that the initializing JS/TS language features notification in VSCode is unrelated to the Svelte extension. Do you know what process is in control of that notification or how I might approach understanding why it's triggering so often?

@jasonlyu123
Copy link
Member

VSCode TypeScript feature controls the initializing JS/TS language features notification. The root cause is that something is updating the file's attributes. So that both the file watcher in TSServer and the svelte language server get notified of the changes. Since it's actual file system changes, It might or might not have to do with our code. I still have no idea what that might be. Maybe instead of restricting the write access restricting "Modify" can let us know the problem.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

3 participants