Major CPU Usage with v1.74-on

[tgfactor]

Type: Bug

Ever since I installed version 1.74.x, I have run into a major CPU usage issue, especially if I work on any Angular scripts. As of right now, sitting idle, I look at my task manager and see my CPU usage is averaging around 18% for VSC alone. And that is with all the included extensions listed below. If I install version 1.73, with the same exact extensions listed below, my CPU usage in idle mode drops to barely 1% maybe 2%. My initial thought was the angular language service was causing the slowdown, but I need that extension to properly do my Angular coding. Any idea what the issue could be?

VS Code version: Code 1.74.2 (e8a3071ea4344d9d48ef8a4df2c097372b0c5161, 2022-12-20T10:29:14.590Z) OS version: Windows_NT x64 10.0.19045 Modes: Sandboxed: No

System Info

|Item|Value| |---|---| |CPUs|Intel(R) Core(TM) i7-8650U CPU @ 1.90GHz (8 x 2112)| |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_renderer: enabled_on
video_decode: enabled
video_encode: enabled
vulkan: disabled_off
webgl: enabled
webgl2: enabled
webgpu: disabled_off| |Load (avg)|undefined| |Memory (System)|31.86GB (14.79GB free)| |Process Argv|--crash-reporter-id 06af7a90-ed87-400f-8084-2a722a14634e| |Screen Reader|no| |VM|0%|

Extensions (27)

Extension|Author (truncated)|Version ---|---|--- ng-template|Ang|14.2.0 npm-intellisense|chr|1.4.4 path-intellisense|chr|2.8.4 angular-schematics|cyr|5.2.9 vscode-simpler-icons|dav|1.6.5 vscode-eslint|dba|2.2.6 githistory|don|0.6.19 EditorConfig|Edi|0.16.4 prettier-vscode|esb|9.10.3 auto-rename-tag|for|0.1.10 todo-tree|Gru|0.0.220 angular2-switcher|inf|0.4.0 search-node-modules|jas|1.3.0 Angular2|joh|13.0.0 refactorix|kri|0.3.6 regionfolder|map|1.0.18 json-to-ts|Mar|1.7.5 typescript-javascript-grammar|ms-|0.0.55 arrr|obe|0.1.3 docthis|oou|0.8.2 vscode-css-peek|pra|4.2.0 quicktype|qui|12.0.46 LiveServer|rit|5.7.9 autoimport|ste|1.5.4 move-ts|str|1.12.0 vscode-todo-highlight|way|1.0.5 JavaScriptSnippets|xab|1.8.0

A/B Experiments

``` vsliv368:30146709 vsreu685:30147344 python383cf:30185419 vspor879:30202332 vspor708:30202333 vspor363:30204092 vslsvsres303:30308271 pythonvspyl392:30443607 vserr242cf:30382550 pythontb:30283811 vsjup518:30340749 pythonptprofiler:30281270 vshan820:30294714 vstes263cf:30335440 pythondataviewer:30285071 vscod805:30301674 binariesv615:30325510 bridge0708:30335490 bridge0723:30353136 cmake_vspar411:30581797 vsaa593cf:30376535 pythonvs932:30410667 cppdebug:30492333 vsclangdf:30486550 c4g48928:30535728 dsvsc012:30540252 azure-dev_surveyone:30548225 vscccc:30610679 pyindex848cf:30577861 nodejswelcome1cf:30587006 2e4cg342:30602488 3d0df643:30613357 89544117:30613380 fim-prod:30623723 ```

[tgfactor]

It's been 3 weeks and nobody has bothered to check to see what could be causing this problem?

[tgfactor]

Ok, I can add additional context. I have gone ahead and disabled ALL my extensions, including even uninstalling those that are deprecated (though I think disabling should have been enough). I even ran the Start Extension Bisect command, to which I continue to see that VSC CPU usage averages between 8% and 12%. And this is using VSC v1.74.3. The command indicated it may be a problem with Code.

I also opened up the process explorer to see what could be causing a problem. The only line that indicated an increase in CPU usage was something from extensionHost:

"C:\Program Files\Microsoft VS Code\Code.exe" --ms-enable-electron-run-as-node --max-old-space-size=3072 "c:\Program Files\Microsoft VS Code\resources\app\extensions\node_modules\typescript\lib\tsserver.js" --useInferredProjectPerProjectRoot --enableTelemetry --cancellationPipeName C:\Users{MYUSERNAME}\AppData\Local\Temp\vscode-typescript\5f167de2a50f10f9d5a4\tscancellation-af47bae0b13580d1b87e.tmp* --locale en --noGetErrOnBackgroundUpdate --validateDefaultNpmLocation --useNodeIpc

Any help will be greatly appreciated since this is really cutting into our development time.

[mjbvz]

Does this reproduce in the latest VS Code insiders build with all extensions disabled?

[tgfactor]

Insiders build? What exactly is the Insiders Build? I have only used the regular VSCodeUSerSetup installer, the latest of which is 1.74.3. The latest insiders build that for yet-to-be released versions?

[mjbvz]

The link tells you this: https://code.visualstudio.com/insiders/

[tgfactor]

Ok, I just tried it, and since I have never used this, I have no extensions installed for it. However, it's still doing the CPU issue: Notice VSC down below, that's using 1.73.1.

One key way of testing - I go into my Angular component file, and I ctrl+click on a model or service method I want to be redirected to. With the Insider version, it takes roughly 3 seconds to be redirected to the model or service I want to investigate. With VSC v.1.73.1, the redirection is almost instantaneous.

[mjbvz]

Thanks for testing. Can you please share a minimal example angular project which demonstrates this issue

[tgfactor]

It's hard to share such a project with what I am allowed to share. Here is a test one: Test Project.

I just tested it out. In VSC v1.73.1, when I ctrl+click the model, it appears instantenously, even when I don't have the file opened. With the Insider version, it takes between 2 and 3 seconds for it to load and appear in the code.

[mjbvz]

Thanks. Where exactly are you ctrl clicking in that project that appears slow?

[tgfactor]

On FirmSummaryViewModel. ctrl+click on FirmSummaryViewModel.

[mjbvz]

Hm, doesn't repo for me:

Can you try to the TS Server log from when the happens:

1. Set "typescript.tsserver.log": "verbose",
2. Restart VS Code and reproduce the problem
3. In VS Code, run the TypeScript: Open TS Server log command
4. This should open a large log file called tsserver.log

That file includes timing information about how long various operations take. They should help us understand what is being slow

⚠️Warning: The TypeScript log may include information from your workspace, including file paths and source code. If you have any concerns about posting this publicly on Github, just let me know and we can arrange something else. On our side, we only use these logs to investigate issues like this

[tgfactor]

tsserver.log Added the tsserver log. Right now, it's moving faster, but I'm certain that it has been slower. In fact, it's not as instantaneous as it could be. There is a slight lull where you see the blue progress bar up top appear for a little bit before it finally finishes loading and shows the model. Before, in 1.73.1, that rarely happened. I'll send this to you and I will try to output (without disclosing too much file information) where I see the commands happening.

[tgfactor]

Ok, I did my own diagnostic of the issue and I might be able to shed a little light. I can't indicate the file paths involved, but I can indicate the file names and the models I'm trying to use in my main project. So, I tried to time my ctrl+click and model load, and I was able (with my human eye) to click on the model around the :00 second span, and to my knowledge, it loaded the file and the class I was looking for in :04.5 seconds. In the tsserver.log file, I came across these key items in the log:

**Info 6180 [12:46:00.312] request:
    {
      "seq": 24,
      "type": "request",
      "command": "definitionAndBoundSpan",
      "arguments": {
        "file": "{root}/proposal-team.models.ts",
        "line": 8,
        "offset": 31
      }
    }**

I see this next:

**Info 6182 [12:46:00.314] Starting updateGraphWorker: Project: {root}/tsconfig.json
Info 6183 [12:46:01.612] Finishing updateGraphWorker: Project: {root}/tsconfig.json**

Followed by:

**Perf 6185 [12:46:01.627] 24::definitionAndBoundSpan: elapsed time (in milliseconds) 1315.2599
Info 6186 [12:46:01.627] response:
    {"seq":0,"type":"response","command":"definitionAndBoundSpan","request_seq":24,"success":true,"performanceData":{"updateGraphDurationMs":1298.3500999212265},"body":{"definitions":[{"file":"{root}/proposal.dtos.ts","start":{"line":187,"offset":14},"end":{"line":187,"offset":42},"contextStart":{"line":187,"offset":1},"contextEnd":{"line":200,"offset":2}}],"textSpan":{"start":{"line":8,"offset":9},"end":{"line":8,"offset":37}}}}**

This file in this response is where the model class I was looking for but again I didn't see it get loaded.

I also saw quite a bit of Scheduled: {root}/tsconfig.jsonFailedLookupInvalidation calls that were being scheduled and cancelled.

The log continues...

**Info 6381 [12:46:01.648] request:
    {
      "seq": 26,
      "type": "request",
      "command": "documentHighlights",
      "arguments": {
        "file": "{root}/proposal-team.models.ts",
        "line": 8,
        "offset": 30,
        "filesToSearch": [
          "{root}/proposal-team.models.ts"
        ]
      }
    }**
...
**Info 6383 [12:46:01.649] Starting updateGraphWorker: Project: {root}/tsconfig.json
Info 6384 [12:46:03.072] Finishing updateGraphWorker: Project: {root}/tsconfig.json**
...
**Info 6387 [12:46:03.082] response:
    {"seq":0,"type":"response","command":"documentHighlights","request_seq":26,"success":true,"performanceData":{"updateGraphDurationMs":1422.9143999814987},"body":[{"file":"{root}/proposal-team.models.ts","highlightSpans":[{"start":{"line":1,"offset":10},"end":{"line":1,"offset":38},"contextStart":{"line":1,"offset":1},"contextEnd":{"line":1,"offset":98},"kind":"writtenReference"},{"start":{"line":4,"offset":10},"end":{"line":4,"offset":38},"kind":"reference"},{"start":{"line":8,"offset":9},"end":{"line":8,"offset":37},"kind":"reference"}]}]}**
...
**Info 6582 [12:46:03.146] request:
    {
      "seq": 27,
      "type": "request",
      "command": "definitionAndBoundSpan",
      "arguments": {
        "file": "{root}/proposal-team.models.ts",
        "line": 8,
        "offset": 30
      }
    }**
...
**Info 6584 [12:46:03.148] Starting updateGraphWorker: Project: {root}/tsconfig.json
Info 6585 [12:46:04.372] Finishing updateGraphWorker: Project: {root}/tsconfig.json**
...
**Info 6588 [12:46:04.375] response:
    {"seq":0,"type":"response","command":"definitionAndBoundSpan","request_seq":27,"success":true,"performanceData":{"updateGraphDurationMs":1224.6564999818802},"body":{"definitions":[{"file":"{root}/proposal.dtos.ts","start":{"line":187,"offset":14},"end":{"line":187,"offset":42},"contextStart":{"line":187,"offset":1},"contextEnd":{"line":200,"offset":2}}],"textSpan":{"start":{"line":8,"offset":9},"end":{"line":8,"offset":37}}}}**

At this point, remember I said I noticed the file get opened at roughly :04.5 seconds, so this marker in the log would be an appropriate spot to indicate when I finally saw the file and class opened up in the editor. Like you can see here, it took nearly 4 seconds for me just to click and see the file.

Any further ideas?

[tgfactor]

Ok, this is getting interesting. So I managed to reinstall version 1.73.1 and load VSCode. I went to the same file, with the same model I want to see and ctrl+clicked to the same model I wanted to see. It was instantenous. I found the following in the tsserver.log, in fact no need to partition out what I see in the server log, I'll paste it in its entirety (minus the root paths):

**Info 592  [13:12:00.648] request:
    {
      "seq": 24,
      "type": "request",
      "command": "quickinfo",
      "arguments": {
        "file": "{root}/proposal-team.models.ts",
        "line": 8,
        "offset": 26
      }
    }
Perf 593  [13:12:00.665] 24::quickinfo: elapsed time (in milliseconds) 17.1374
Info 594  [13:12:00.665] response:
    {"seq":0,"type":"response","command":"quickinfo","request_seq":24,"success":true,"body":{"kind":"alias","kindModifiers":"export","start":{"line":8,"offset":9},"end":{"line":8,"offset":37},"displayString":"(alias) class ProposalDetailPartyPersonDto\nimport ProposalDetailPartyPersonDto","documentation":[],"tags":[]}}
Info 595  [13:12:00.949] request:
    {
      "seq": 25,
      "type": "request",
      "command": "documentHighlights",
      "arguments": {
        "file": "{root}/proposal-team.models.ts",
        "line": 8,
        "offset": 26,
        "filesToSearch": [
          "{root}/proposal-team.models.ts"
        ]
      }
    }
Perf 596  [13:12:00.961] 25::documentHighlights: elapsed time (in milliseconds) 12.2381
Info 597  [13:12:00.962] response:
    {"seq":0,"type":"response","command":"documentHighlights","request_seq":25,"success":true,"body":[{"file":"{root}/proposal-team.models.ts","highlightSpans":[{"start":{"line":1,"offset":10},"end":{"line":1,"offset":38},"contextStart":{"line":1,"offset":1},"contextEnd":{"line":1,"offset":98},"kind":"writtenReference"},{"start":{"line":4,"offset":10},"end":{"line":4,"offset":38},"kind":"reference"},{"start":{"line":8,"offset":9},"end":{"line":8,"offset":37},"kind":"reference"}]}]}
Info 598  [13:12:00.962] request:
    {
      "seq": 26,
      "type": "request",
      "command": "definitionAndBoundSpan",
      "arguments": {
        "file": "{root}/proposal-team.models.ts",
        "line": 8,
        "offset": 26
      }
    }
Perf 599  [13:12:00.976] 26::definitionAndBoundSpan: elapsed time (in milliseconds) 13.5463
Info 600  [13:12:00.976] response:
    {"seq":0,"type":"response","command":"definitionAndBoundSpan","request_seq":26,"success":true,"body":{"definitions":[{"file":"{root}/proposal.dtos.ts","start":{"line":187,"offset":14},"end":{"line":187,"offset":42},"contextStart":{"line":187,"offset":1},"contextEnd":{"line":200,"offset":2}}],"textSpan":{"start":{"line":8,"offset":9},"end":{"line":8,"offset":37}}}}**

(Side Note: I think it is around this point where I would see the file loaded and the class I ctrl+clicked)

**Info 601  [13:12:01.435] request:
    {
      "seq": 27,
      "type": "request",
      "command": "updateOpen",
      "arguments": {
        "changedFiles": [],
        "closedFiles": [],
        "openFiles": [
          {
            "file": "{root}/proposal.dtos.ts",
            "fileContent": "{filecontentgoeshere}",
            "projectRootPath": "{root}",
            "scriptKindName": "TS"
          }
        ]
      }
    }**

I noticed a lot of updateGraphWorker calls NOT being made, and also quickInfo was not being used. I hope this helps us come to a conclusion as to why it's taking so much longer with the same project but in a different, newer version of vscode.

[mjbvz]

Thank you for the investigation @tgfactor! This is very helpful

I've moved this issue over to the TypeScript team who may have a better understanding of what is going wrong here

[jakebailey]

Edited your comments as I was having trouble reading the traces.

[tgfactor]

It's been a couple of weeks and I wanted to see if anything new has come up to explain why this would be happening.

[jakebailey]

I've been unable to reproduce this; navigating to FirmSummaryViewModel is always instant for me.'

The tsserver log uploaded isn't the one you did your analysis on, and in the log I don't see a definitionAndBoundSpan call taking 4 seconds.

But, I do see in the logs a near constant stream of FileWatcher:: Triggered with ... lines, which could explain the CPU usage if it's continually seeing events.

Can you try setting:

"typescript.tsserver.watchOptions": {
    "watchFile": "fixedPollingInterval"
},

In your VS Code settings? This default was recently changed to a new watching method, and the above would restore an older version.

If this is easily reproducible for you, I would also consider downgrading TS and setting VS Code to use it, just so you can go back and find the TS version where this changed. The VS Code version is not super helpful in that way, though it's probable that it's TS 4.9 given v1.74 introduced it.

[Lonli-Lokli]

We faced a similar thing, it was resolved by selecting the lower typescript version from node_modules (hover { } on the left of Typescript and selecting Typescript from node_modules.

[jakebailey]

It's good to know that downgrading fixes it as it means that something changed, but I would really appreciate it if you could try the suggestion above and see if playing with the watch mode changes anything for you in TS 4.9. (We want to fix the problem, not tell everyone to downgrade!)

[Lonli-Lokli]

@jakebailey Yes it fixed performance as well

[jakebailey]

@sheetalkamat for interest.

[jakebailey]

Can you tell me about where your project lives on disk? Is it somewhere that's synced to OneDrive, for example?

[tgfactor]

The test project I submitted here, or the actual project where I first encountered this issue?

[jakebailey]

The latter, though if the test project you linked isn't representative of the actual project and doesn't reproduce the issue, then I'm not sure what to do with it.

So, either, so long as something is showing the high CPU usage + FileWatcher events?

@Lonli-Lokli already tried the file watching change, but I'd appreciate it if you tried it as well.

[tgfactor]

Yeah, I can't disclose the other project, as it is company code. However, I did have one of my developers try out the watchOptions solution, and he told me it was a lot faster for him accessing files with ctrl + clicks. My hope is not to downgrade TS especially since we are getting ready to upgrade to Angular 15. But for right now, we'll continue to give this a shot and see how it works out.

[jakebailey]

Not disclosing it is fine, though it is possible for us to view the code under NDA (not uncommon given how much closed-source TS there is out there).

I am still interested in what the environment is that you're running under; is it always Windows? Where are the files saved? For example, my Documents dir is synced to OneDrive, and that can have a performance impact.

Does your sample repo produce the same thing?

[tgfactor]

Always Windows. Unfortunately, I can't give an accurate account now, since I just upgraded my machine to Windows 11.

[tgfactor]

I talked to one of my other developers having the same issue on an older machine, told him to add the watchOptions property to his VSC, and he said it was running a lot faster than before.

[jakebailey]

Thanks for the info; I'm still looking for more info about the systems themselves, specifically where the files are stored. Is this in a drive which is networked? Shared on OneDrive? Is Defender active? Some other corporate software that may be touching the files?

[tgfactor]

The files are stored locally. They are not involved with onedrive or any other networked drive. We do have Windows Security active and use FortiClient.

[tgfactor]

Is there any new update on this issue? One of my other developers just upgraded to v1.76.1, and he tells me that the long wait times between ctrl+click on classes is still happening.

[ZachHaber]

But, I do see in the logs a near constant stream of FileWatcher:: Triggered with ... lines, which could explain the CPU usage if it's continually seeing events.

I'm running into a similar problem on a workspace with a vue 2 frontend, a hapi backend, and a common folder all of which are in JS. I'm getting 10s of thousands of those lines. The log I've attached is from ~2 minutes of activity. Over the course of <24hrs that I had verbose logging turned on, I have over 1GB of log files. And half that time, the computer should've been asleep.

I'm using VSCode's built-in TS version since it's a JS project.

tsserver.log ti-47412.log

System Info

|Item|Value| |---|---| |OS|Windows_NT x64 10.0.19044| |CPUs|Intel(R) Core(TM) i9-10900X CPU @ 3.70GHz (20 x 3696)| |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_renderer: enabled_on
video_decode: enabled
video_encode: enabled
vulkan: disabled_off
webgl: enabled
webgl2: enabled
webgpu: disabled_off| |Load (avg)|undefined| |Memory (System)|63.72GB (26.40GB free)| |Process Argv|--file-uri file:///c%3A/code/arcade/Arcade.code-workspace --crash-reporter-id e4ef971e-1bc8-4898-8110-c4ac3a2b7acf| |Screen Reader|no| |VM|0%|

I also can't send you the codebase, but if it helps at all, here's the jsconfig data:

service jsconfig.json

```jsonc { "compilerOptions": { "target": "ES2021", "module": "Node16", "lib": ["es2022"], "baseUrl": ".", "moduleResolution": "nodenext", "paths": { "#cache/*": ["./src/cache/*"], "#routes/*": ["./src/routes/*"], "#helpers/*": ["./src/helpers/*"], "#types/*": ["./src/types/*"], "#src/*": ["./src/*"] }, "types": ["./src/types/environment", "node"], "strict": true }, "include": ["src"], "exclude": ["node_modules"] } ```

client jsconfig.json

```jsonc { "compilerOptions": { "lib": ["DOM", "es2022"], "types": ["vite/client", "./src/types/environment"], "baseUrl": ".", "moduleResolution": "NodeNext", "paths": { "@/*": ["src/*"] }, "jsx": "preserve" }, "vueCompilerOptions": { "target": 2.7 } } ```

common jsconfig.json

```jsonc { "compilerOptions": { "target": "ES2021", "module": "Node16", "lib": ["es2021"], "baseUrl": ".", "moduleResolution": "nodenext", "paths": { "arcade-common/types": ["./src/types.js"] }, // "types": ["./src/types/environment", "node"], "strict": true }, "include": ["src"], "exclude": ["node_modules"] } ```

[jakebailey]

No update besides that #52876 is pretty sure the same thing. TS 4.9 changed the watch default to use native watching more, and that apparently was not good, so I can only suggest changing your watch setting back to a polling-based one if it's not working correctly.

[tgfactor]

FYI, as of now (and I'm assuming it's due to a very recent Windows Update) I'm no longer able to "run and debug" with VSCode on my Angular project while still running v1.73.1. In order for me to effectively debug my application, I have to upgrade to v1.76.x. In addition, the solutions provided here may have once temporarily solved this issue, but now according to other developers, they no longer apply, or do not solve it like it used to be in 1.73.

[jakebailey]

Nothing would have changed about watching in 1.76.x; is what you have been setting what I suggested to add to your VS Code user config?

"typescript.tsserver.watchOptions": {
    "watchFile": "fixedPollingInterval"
},

[tgfactor]

Correct. My other developer confirmed that even with that setting turned on, it still takes him about 10s to go to the definition via ctrl+click if it isn't already cached.

[stephengeorgewest-navitaire]

After updating past 1.74 I was seeing 5-7% cpu usage for tsserver, or about a full proccessor (14 cores, 20 logical processors), after applying "watchFile": "fixedPollingInterval" it dropped to a reasonable < 1%. Then something happened, and it started using 2-3%, regadless of typescript version (4.8.4 workspace or 5.2.2 vs)

switching to "watchFile": "fixedChunkSizePolling" dropped the cpu usage back to < 1% (bounces between 0.2 and 0.7%) "watchFile": "dynamicPriorityPolling" seems slightly higher at 0.4-1.3%