High cpu usage with mobx project on windows

[mjbvz]

TypeScript Version: 3.7.3

Search terms:

• Cpu
• React

---

I can reproduce with the following steps (Windows 10 - vscode 1.41 system setup)

• clone and yarn install https://github.com/blikblum/lit-element-mobx-realworld-example-app
• go to https://github.com/blikblum/lit-element-mobx-realworld-example-app/blob/master/test/dummy-superagent.js
• Start a import statement and try to launch intelisense: import 'sup|' (Ctrl +Space) -> cpu usage will peak and remain high with a Loading indicator
• Alternatively add a complete import like import 'superagent' Ctrl + Click on 'superagent' -> high cpu usage for long time

I downgraded to 1.40.2 and the above commands are instantaneous without cpu usage peaks

Originally posted by @blikblum in https://github.com/microsoft/vscode/issues/87032#issuecomment-566287989

[mjbvz]

@blikblum Can you please follow these instructions to collect performance information about which process is causing the high cpu usage. Share the output of code --status

[blikblum]

After adding import 'sup|' Ctrl + Space.

The affecting is electron_node tsserver.js. It remains with that cpu usage until close app. BTW the cpu is somewhat new and powerful

Version:          Code 1.41.0 (9579eda04fdb3a9bba2750f15193e5fafe16b959, 2019-12-11T18:37:42.077Z)
OS Version:       Windows_NT x64 10.0.18363
CPUs:             Intel(R) Core(TM) i7-7700 CPU @ 3.60GHz (8 x 3600)
Memory (System):  7.91GB (1.84GB free)
VM:               67%
Screen Reader:    no
Process Argv:
GPU Status:       2d_canvas:                     enabled
                  flash_3d:                      enabled
                  flash_stage3d:                 enabled
                  flash_stage3d_baseline:        enabled
                  gpu_compositing:               enabled
                  metal:                         disabled_off
                  multiple_raster_threads:       enabled_on
                  oop_rasterization:             disabled_off
                  protected_video_decode:        enabled
                  rasterization:                 enabled
                  skia_renderer:                 disabled_off
                  surface_control:               disabled_off
                  surface_synchronization:       enabled_on
                  video_decode:                  enabled
                  viz_display_compositor:        enabled_on
                  viz_hit_test_surface_layer:    disabled_off
                  webgl:                         enabled
                  webgl2:                        enabled

CPU %   Mem MB     PID  Process
    0       85   17032  code main
    0      195    2580     window (tags.test.js - react-mobx-realworld-example-app - Visual Studio Code)
    0       69    1504       C:\WINDOWS\System32\WindowsPowerShell\v1.0\powershell.exe
    0       35    5740       searchService
    0      132   13532       extensionHost
   13      401    6212         electron_node tsserver.js
    0       48   12892           electron_node typingsInstaller.js typesMap.js
    0       80   10020         electron_node tsserver.js
    0       32   12368         "C:\Program Files\Microsoft VS Code\Code.exe" "c:\Program Files\Microsoft VS Code\resources\app\extensions\json-language-features\server\dist\jsonServerMain" --node-ipc --clientProcessId=13532
    0       13   14268       watcherService
    0        6   12928         console-window-host (Windows internal process)
    0        6   19384       console-window-host (Windows internal process)
    0       61    2616     window (Process Explorer)
    0      147    3856     gpu-process
    0       68    3976     shared-process
    0       15   14820     electron-crash-reporter

Workspace Stats:
|  Window (tags.test.js - react-mobx-realworld-example-app - Visual Studio Code)
|    Folder (react-mobx-realworld-example-app): 118 files
|      File types: js(46) html(26) json(5) md(3) png(2) ico(2) css(2) env(1)
|                  babelrc(1) prettierrc(1)
|      Conf files: jsconfig.json(1) package.json(1) webpack.config.js(1)
|                  settings.json(1)

[mjbvz]

Where are you seeing the high cpu usage? The output of --status shows it at 13%. Or is the issue that it never drops to zero even if you never interact with the code?

[blikblum]

Where are you seeing the high cpu usage? The output of --status shows it at 13%. Or is the issue that it never drops to zero even if you never interact with the code?

Both in windows task manager and vscode process explorer.
The windows task manager is a bit higher with variation between 16% and 20%. This is a quad core i7 desktop cpu so is taking almost all cpu usage from one core.

Also the CPU FAN starts spinning continuously.

Finally, the task (autocomplete the import) does not complete.

[mjbvz]

@blikblum Thanks. One last thing to try: upgrade your workspace to use typescript@next by installing this extension

Does that fix the issue?

I haven't been able to repo this on my machine. CPU usage is high for a little when we first load the project while but then drops off

[blikblum]

Does that fix the issue?

Yes. Autocomplete is instantaneous and no CPU usage. Max is 4% in window task manager

[blikblum]

It was working fine until i found a new reproducible situation:

Checkout https://github.com/blikblum/slick-router/tree/vscode-cpu-test

Probably needs yarn install

Go to line https://github.com/blikblum/slick-router/blob/vscode-cpu-test/lib/router.js#L424

Put cursor after disposeIn. Press Ctrl + Space: a "Loading" box appears, CPU goes high indefinitely and CPU FAN starts to spin

I tested three times in a row and all the same behavior
Tested also with code --disable-extensions and same behavior

https://marketplace.visualstudio.com/items?itemName=ms-vscode.vscode-typescript-next is installed and enabled
code --status:

Version:          Code 1.41.0 (9579eda04fdb3a9bba2750f15193e5fafe16b959, 2019-12-11T18:37:42.077Z)
OS Version:       Windows_NT x64 10.0.18363
CPUs:             Intel(R) Core(TM) i7-7700 CPU @ 3.60GHz (8 x 3600)
Memory (System):  7.91GB (1.91GB free)
VM:               67%
Screen Reader:    no
Process Argv:
GPU Status:       2d_canvas:                     enabled
                  flash_3d:                      enabled
                  flash_stage3d:                 enabled
                  flash_stage3d_baseline:        enabled
                  gpu_compositing:               enabled
                  metal:                         disabled_off
                  multiple_raster_threads:       enabled_on
                  oop_rasterization:             disabled_off
                  protected_video_decode:        enabled
                  rasterization:                 enabled
                  skia_renderer:                 disabled_off
                  surface_control:               disabled_off
                  surface_synchronization:       enabled_on
                  video_decode:                  enabled
                  viz_display_compositor:        enabled_on
                  viz_hit_test_surface_layer:    disabled_off
                  webgl:                         enabled
                  webgl2:                        enabled

CPU %   Mem MB     PID  Process
    0       77    4732  code main
    0      138    4352     gpu-process
    0       14   10680     electron-crash-reporter
    0      203   18096     window (router.js - slick-router - Visual Studio Code)
    0       69    2388       C:\WINDOWS\System32\WindowsPowerShell\v1.0\powershell.exe
    0       11    6732       watcherService
    0        6     632         console-window-host (Windows internal process)
    0       34   13472       searchService
    0        5   14024       console-window-host (Windows internal process)
    0      116   19212       extensionHost
    0       78   14116         electron_node tsserver.js
    0       50   15156         electron_node server.js
   13      268   19852         electron_node tsserver.js
    0       46    1620           electron_node typingsInstaller.js typesMap.js
    0       69   19564     shared-process

Workspace Stats:
|  Window (router.js - slick-router - Visual Studio Code)
|    Folder (slick-router): 210 files
|      File types: js(74) html(45) md(12) css(7) json(6) lock(4) map(3)
|                  gitignore(1) info(1) png(1)
|      Conf files: package.json(5) webpack.config.js(3) settings.json(1)

[amcasey]

@blikblum Thanks for the detailed repro steps!

[amcasey]

@blikblum I immediately get a completion list with a single item: disposeIntercept. I'm on 1.41.1 (26076a4de974ead31f97692a0d32f90d735645c0) with ms-vscode.vscode-typescript-next (3.8.0-dev.20200114) Do you have any typescript. settings with non-default values? Having a local repro would be ideal, but there's also a lot we can learn from logging. If your versions look the same as mine, could you possibly try collecting a log? https://github.com/microsoft/TypeScript/wiki/Performance#collecting-a-tsserver-log-in-visual-studio-code

[amcasey]

One other thought: are you seeing this during the delays?

[blikblum]

@blikblum I immediately get a completion list with a single item: disposeIntercept. I'm on 1.41.1 (26076a4de974ead31f97692a0d32f90d735645c0) with ms-vscode.vscode-typescript-next (3.8.0-dev.20200114) Do you have any typescript.

Now, if i use https://marketplace.visualstudio.com/items?itemName=ms-vscode.vscode-typescript-next, it works instantly.

Disable it brings back the issue

One other thought: are you seeing this during the delays?

Yes. It keeps loading indefinitely

[amcasey]

@blikblum, that extension just tells VS Code to use the latest build of TypeScript. From your description, it sounds like the version that shipped with VS Code 1.41.1 may have had a performance issue that has since been corrected. I'll see if I can repro the issue with that version.

[amcasey]

As far as I can tell, VS Code 1.41.1 shipped with TS 3.7.3 and I don't see anything in your package.json that would override that. Things seem to work well for me with that version.

Fortunately, it sounds like you can reliably reproduce the problem. Can you please try collecting a TS Server Log?

[blikblum]

Info 0    [22:33:19.577] Starting TS Server
Info 1    [22:33:19.578] Version: 3.7.3
Info 2    [22:33:19.578] Arguments: C:\Program Files\Microsoft VS Code\Code.exe c:\Program Files\Microsoft VS Code\resources\app\extensions\node_modules\typescript\lib\tsserver.js --useInferredProjectPerProjectRoot --enableTelemetry --cancellationPipeName C:\Users\Luiz Américo\AppData\Local\Temp\vscode-typescript\b36dda324198b5150a76\tscancellation-5b0d965321c0b44ced2b.tmp* --logVerbosity verbose --logFile c:\Users\Luiz Américo\AppData\Roaming\Code\logs\20200115T223247\exthost1\vscode.typescript-language-features\tsserver-log-mfpLSM\tsserver.log --globalPlugins typescript-snapshots-plugin,ts-lit-plugin --pluginProbeLocations C:\Users\Luiz Américo\.vscode\extensions\asvetliakov.snapshot-tools-0.4.0,C:\Users\Luiz Américo\.vscode\extensions\runem.lit-plugin-1.1.9 --locale en --noGetErrOnBackgroundUpdate --validateDefaultNpmLocation
Info 3    [22:33:19.624] Platform: win32 NodeVersion: 12 CaseSensitive: false
Info 4    [22:33:19.668] Binding...
Info 5    [22:33:19.786] event:
    {"seq":0,"type":"event","event":"typingsInstallerPid","body":{"pid":15056}}
Info 6    [22:33:19.787] request:
    {"seq":0,"type":"request","command":"configure","arguments":{"hostInfo":"vscode","preferences":{"providePrefixAndSuffixTextForRename":true,"allowRenameOfImportPath":true}}}
Info 7    [22:33:19.788] Host information vscode
Info 8    [22:33:19.788] response:
    {"seq":0,"type":"response","command":"configure","request_seq":0,"success":true}
Perf 9    [22:33:19.788] 0::configure: async elapsed time (in milliseconds) 0.6796
Info 10   [22:33:20.32] request:
    {"seq":1,"type":"request","command":"compilerOptionsForInferredProjects","arguments":{"options":{"module":"commonjs","target":"es2016","jsx":"preserve","allowJs":true,"allowSyntheticDefaultImports":true,"allowNonTsExtensions":true}}}
Info 11   [22:33:20.32] Scheduled: *ensureProjectForOpenFiles*
Perf 12   [22:33:20.32] 1::compilerOptionsForInferredProjects: elapsed time (in milliseconds) 0.7567
Info 13   [22:33:20.33] response:

[..]
    {"seq":0,"type":"response","command":"definitionAndBoundSpan","request_seq":13,"success":true,"body":{"definitions":[]}}
Info 107  [22:33:26.804] request:
    {"seq":14,"type":"request","command":"completionInfo","arguments":{"file":"d:/repositories/slick-router/lib/router.js","line":424,"offset":19,"includeExternalModuleExports":true,"includeInsertTextCompletions":true,"includeAutomaticOptionalChainCompletions":true}}
Info 108  [22:33:26.806] getCompletionData: Get current token: 0
Info 109  [22:33:26.806] getCompletionData: Is inside comment: 0
Info 110  [22:33:26.806] getCompletionData: Get previous token 1: 0
Info 111  [22:33:26.806] getCompletionData: Get previous token 2: 0
Info 112  [22:33:26.807] getCompletionsAtPosition: isCompletionListBlocker: 1
Info 113  [22:33:26.816] getSymbolsFromOtherSourceFileExports: Recomputing list
Info 114  [22:33:26.817] FileWatcher:: Added:: WatchInfo: d:/repositories/slick-router/package.json 250 Project:  WatchType: package.json file for import suggestions

[blikblum]

No log entry is added after 22:33h even if i quit the loading and try again

[amcasey]

Thanks! A few thoughts:

1. That's just for initialization - I don't see any completion requests. If you wait for that 7 second initialization period to elapse (I agree that it's too long), does completion work correctly after that?
2. If you restart the editor, it'll start a new log file - the old one won't be updated.
3. If you'd prefer not to post the contents of your log publicly, you can add me to a private gist or mail me at [email protected].

Edit: Just saw the completion call right at the end. I missed it because I was looking at responses. If the log ends right there, it's possible the language service is crashing.

[amcasey]

Crashing without a stack in the log is pretty unusual, but not impossible. Normally, I'd guess you'd run out of memory, but your project isn't that big.

Another possibility is that we have different type definitions. In particular, you might have some bad ones for 3.7. There's a cache you might try clearing: can you close your editors and rename %LOCALAPPDATA%\Microsoft\TypeScript to something else (e.g. TypeScript2)? It's possible one of the type definitions has a bug that has subsequently been fixed and that's why I'm not seeing the problem (and the caches are 3.7 and 3.8 are different, which would explain why the nightly works for you).

[blikblum]

That's just for initialization - I don't see any completion requests. If you wait for that 7 second initialization period to elapse (I agree that it's too long), does completion work correctly after that?

No, i waited 10 min and the loading... keep there. If i try completing any other thing it just shows the loading... indicator and no more trace is added to log

Below is another trace. Took at 23h

Info 0    [22:51:21.104] Starting TS Server
Info 1    [22:51:21.106] Version: 3.7.3
Info 2    [22:51:21.109] Arguments: C:\Program Files\Microsoft VS Code\Code.exe c:\Program Files\Microsoft VS Code\resources\app\extensions\node_modules\typescript\lib\tsserver.js --useInferredProjectPerProjectRoot --enableTelemetry --cancellationPipeName C:\Users\Luiz Américo\AppData\Local\Temp\vscode-typescript\a5bc020335eba780798a\tscancellation-f9639e63aa58266afa67.tmp* --logVerbosity verbose --logFile c:\Users\Luiz Américo\AppData\Roaming\Code\logs\20200115T225116\exthost1\vscode.typescript-language-features\tsserver-log-HbL2y6\tsserver.log --globalPlugins typescript-snapshots-plugin,ts-lit-plugin --pluginProbeLocations C:\Users\Luiz Américo\.vscode\extensions\asvetliakov.snapshot-tools-0.4.0,C:\Users\Luiz Américo\.vscode\extensions\runem.lit-plugin-1.1.9 --locale en --noGetErrOnBackgroundUpdate --validateDefaultNpmLocation
Info 3    [22:51:21.110] Platform: win32 NodeVersion: 12 CaseSensitive: false
Info 4    [22:51:21.114] Binding...
Info 5    [22:51:21.165] event:
    {"seq":0,"type":"event","event":"typingsInstallerPid","body":{"pid":12424}}
Info 6    [22:51:21.168] request:
    {"seq":0,"type":"request","command":"configure","arguments":{"hostInfo":"vscode","preferences":{"providePrefixAndSuffixTextForRename":true,"allowRenameOfImportPath":true}}}
Info 7    [22:51:21.168] Host information vscode
Info 8    [22:51:21.169] response:
    {"seq":0,"type":"response","command":"configure","request_seq":0,"success":true}
Perf 9    [22:51:21.170] 0::configure: async elapsed time (in milliseconds) 1.6241
Info 10   [22:51:21.170] request:
    {"seq":1,"type":"request","command":"compilerOptionsForInferredProjects","arguments":{"options":{"module":"commonjs","target":"es2016","jsx":"preserve","allowJs":true,"allowSyntheticDefaultImports":true,"allowNonTsExtensions":true}}}
Info 11   [22:51:21.171] Scheduled: *ensureProjectForOpenFiles*
Perf 12   [22:51:21.172] 1::compilerOptionsForInferredProjects: elapsed time (in milliseconds) 1.6257
Info 13   [22:51:21.172] response:
  
[..]
    {"seq":0,"type":"response","command":"getApplicableRefactors","request_seq":13,"success":true,"body":[]}
Info 131  [22:51:27.706] request:
    {"seq":14,"type":"request","command":"completionInfo","arguments":{"file":"d:/repositories/slick-router/lib/router.js","line":424,"offset":19,"includeExternalModuleExports":true,"includeInsertTextCompletions":true,"includeAutomaticOptionalChainCompletions":true}}
Info 132  [22:51:27.708] getCompletionData: Get current token: 0
Info 133  [22:51:27.708] getCompletionData: Is inside comment: 0
Info 134  [22:51:27.708] getCompletionData: Get previous token 1: 0
Info 135  [22:51:27.708] getCompletionData: Get previous token 2: 0
Info 136  [22:51:27.708] getCompletionsAtPosition: isCompletionListBlocker: 0
Info 137  [22:51:27.716] getSymbolsFromOtherSourceFileExports: Recomputing list
Info 138  [22:51:27.717] FileWatcher:: Added:: WatchInfo: d:/repositories/slick-router/package.json 250 Project:  WatchType: package.json file for import suggestions

[blikblum]

Another possibility is that we have different type definitions. In particular, you might have some bad ones for 3.7. There's a cache you might try clearing: can you close your editors and rename %LOCALAPPDATA%\Microsoft\TypeScript to something else (e.g. TypeScript2)? It's possible one of the type definitions has a bug that has subsequently been fixed and that's why I'm not seeing the problem (and the caches are 3.7 and 3.8 are different, which would explain why the nightly works for you).

With that, loading is instantaneous

thanks

[amcasey]

@blikblum I don't suppose you feel like zipping up the package.json and package-lock.json files from your backup of the old cache so I can test things out locally? You can double check, but I don't believe it contains anything specific to you - just packages from the @types namespace. Thanks!

[blikblum]

I can do, but i am travelling. Only in a few days.

[amcasey]

Sounds good. Ping me when you're ready.

[blikblum]

on't suppose you feel like zipping up the package.json and package-lock.json files from your backup of the old cache so I can test things out locally?

Sent by mail

Mail not worked.

Here it is
3.7.zip

[amcasey]

Thanks! I kept digging through my junk folder without seeing any obvious matches before I noticed you had updated your comment. 😄

[amcasey]

@blikblum Is that the old package-lock.json that was causing you problems or the new one that solved them? When I try the completion you suggested (disposeIn| in router.js), it appears almost instantly.

[blikblum]

The old one, that was causing problems.

For your info after some time with the cleared cache the slowdown got back. When using 3.8 working fine until now

[amcasey]

Interesting, I wasn't expecting anything to happen in the background since the cache was pre-populated (i.e. I manually ran npm ci), but maybe it does. I'll run it for longer and see if things get worse. Thanks!

[amcasey]

I gave it more time and still had no luck. I also tried locking the package.json file, since that seems to be what the language service was trying to access at the end of your log.

I'm kind of grasping at straws here: are any of your files symlinks or on network shares? That can cause behavior changes that wouldn't be reflected in my local testing.

[blikblum]

I'm kind of grasping at straws here: are any of your files symlinks or on network shares?

No.

BTW: at the time i consider resolved by using typescript 3.8, not sure, if worth pursuing a backport fix

[amcasey]

My concern was that there would be a flood of incoming reports of this problem, but that doesn't seem to have happened. I'm fine saying we've investigated as much as we need to. Thanks for your help!

[blikblum]

Thanks for you looking into it

[amcasey]

Update: this looks very much like a duplicate of #35733.