VSCode TypeScript error suggestions are slow

[quicksnap]

Issue Type: Performance Issue

Hello all! Sorry about the vague title.

Our project has had ongoing performance issues with TSC / VSCode, where VSCode is generally very sluggish to update its TypeScript error/warning state.

A few libraries we use may be culprits, but it's difficult to track down what's going on, or if this kind of performance is expected. Two libraries that may be causing us issues are styled-components@4.4.0 and fp-ts@1.19.5.

I've been able recently to isolate a specific example: when changing a token to something invalid, it takes ~2-3 seconds for a response from TS. This in itself feels slow, but possibly acceptable. However, performance in day-to-day work for our devs can sometimes become really bad, taking up to 10 seconds or just becoming unstable.

I've attached some logs from when I hit the s key on the token onChange, making it become invalid: Isolated Logs.txt

As the stats below show, we do have a large-ish file graph, but it's not too crazy.

I'm happy to provide as much information as needed. Really appreciate any help with this!

VS Code version: Code 1.43.2 (0ba0ca52957102ca3527cf479571617f0de6ed50, 2020-03-24T07:34:57.037Z)
OS version: Darwin x64 19.3.0

System Info

Item	Value
CPUs	Intel(R) Core(TM) i9-9980HK CPU @ 2.40GHz (16 x 2400)
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: unavailable_off rasterization: enabled skia_renderer: disabled_off_ok video_decode: enabled viz_display_compositor: enabled_on viz_hit_test_surface_layer: disabled_off_ok webgl: enabled webgl2: enabled
Load (avg)	2, 2, 2
Memory (System)	32.00GB (10.69GB free)
Process Argv	--disable-extensions
Screen Reader	no
VM	0%

Process Info

CPU %	Mem MB	   PID	Process
   10	   131	 79867	code main
    5	    98	 79896	   gpu-process
    0	    33	 79909	   utility
    6	   393	 79911	   window (Isolated Logs.txt — client)
    0	    98	 79950	     extensionHost
    0	    66	 80458	       /Applications/Visual Studio Code.app/Contents/Frameworks/Code Helper (Renderer).app/Contents/MacOS/Code Helper (Renderer) /Applications/Visual Studio Code.app/Contents/Resources/app/extensions/json-language-features/server/dist/jsonServerMain --node-ipc --clientProcessId=79950
    0	    98	 91429	       electron_node tsserver.js 
    0	   819	 91430	       electron_node tsserver.js 
    0	    66	 91431	         electron_node typingsInstaller.js typesMap.js 
    0	    33	 91222	     watcherService
    0	    66	 91937	     searchService
   52	    98	 80062	   shared-process
    0	     0	 99638	     /bin/ps -ax -o pid=,ppid=,pcpu=,pmem=,command=
   49	    66	 99630	   window (Issue Reporter)

Workspace Info

|  Window (Isolated Logs.txt — client)
|    Folder (client): 9241 files
|      File types: js(3185) map(2350) tsx(912) ts(875) svg(253) scss(193)
|                  png(71) css(40) jpg(36) json(18)
|      Conf files: package.json(4) tsconfig.json(1) tslint.json(1)
|                  settings.json(1);

Extensions disabled

[quicksnap]

Also, I tested this on Insiders build and it exhibited the same performance.

[mjbvz]

From the logs, the longest request is encodedSemanticClassifications-full.

Can you test if setting "editor.semanticHighlighting.enabled": false fixes the issue?
Also please try upgrading your workspace to use typescript@next by installing this extension. After installing that and restarting VS Code, are things better?

[quicksnap]

Thanks again for taking the time to give these suggestions @mjbvz! Really appreciate it.

I think it helped a little bit, but it can still take about two seconds. Logs below, same single-keypress.

Am I being too picky with perf on this instance? The reason why I'm zeroing in on this occurrence is that this is the only case where I've been able to isolate something. Our project has had ongoing issues where performance degrades, and it has been really tough figuring out what the problem is.

Thanks again for your insight!

    {"seq":104,"type":"request","command":"updateOpen","arguments":{"changedFiles":[{"fileName":"/Users/dan/projects/portal/client/src/common/monoblocks/form/FormIpCidrInput.tsx","textChanges":[{"newText":"s","start":{"line":144,"offset":7},"end":{"line":144,"offset":7}}]}],"closedFiles":[],"openFiles":[]}}
Perf 2880 [10:39:32.761] 104::updateOpen: elapsed time (in milliseconds) 0.2747
Info 2881 [10:39:32.761] response:
    {"seq":0,"type":"response","command":"updateOpen","request_seq":104,"success":true,"body":true}
Info 2882 [10:39:32.809] request:
    {"seq":105,"type":"request","command":"getApplicableRefactors","arguments":{"file":"/Users/dan/projects/portal/client/src/common/monoblocks/form/FormIpCidrInput.tsx","startLine":144,"startOffset":8,"endLine":144,"endOffset":8}}
Info 2883 [10:39:32.809] Starting updateGraphWorker: Project: /Users/dan/projects/portal/client/tsconfig.json
Info 2884 [10:39:32.969] Finishing updateGraphWorker: Project: /Users/dan/projects/portal/client/tsconfig.json Version: 16 structureChanged: false Elapsed: 160ms
Info 2885 [10:39:32.969] Different program with same set of files:: oldProgram.structureIsReused:: 2
Perf 2886 [10:39:32.970] 105::getApplicableRefactors: elapsed time (in milliseconds) 160.9877
Info 2887 [10:39:32.970] response:
    {"seq":0,"type":"response","command":"getApplicableRefactors","request_seq":105,"success":true,"performanceData":{"updateGraphDurationMs":160},"body":[]}
Info 2888 [10:39:32.970] request:
    {"seq":106,"type":"request","command":"geterr","arguments":{"delay":0,"files":["/Users/dan/projects/portal/client/src/common/monoblocks/form/FormIpCidrInput.tsx"]}}
Perf 2889 [10:39:32.970] 106::geterr: async elapsed time (in milliseconds) 0.1200
Info 2890 [10:39:32.971] event:
    {"seq":0,"type":"event","event":"syntaxDiag","body":{"file":"/Users/dan/projects/portal/client/src/common/monoblocks/form/FormIpCidrInput.tsx","diagnostics":[]}}
Info 2891 [10:39:33.690] event:
    {"seq":0,"type":"event","event":"semanticDiag","body":{"file":"/Users/dan/projects/portal/client/src/common/monoblocks/form/FormIpCidrInput.tsx","diagnostics":[{"start":{"line":144,"offset":7},"end":{"line":144,"offset":16},"text":"Cannot find name 'sonChange'. Did you mean 'onChange'?","code":2552,"category":"error","relatedInformation":[{"span":{"start":{"line":137,"offset":13},"end":{"line":137,"offset":21},"file":"/Users/dan/projects/portal/client/src/common/monoblocks/form/FormIpCidrInput.tsx"},"message":"'onChange' is declared here.","category":"message","code":2728}]}]}}
Info 2892 [10:39:33.691] event:
    {"seq":0,"type":"event","event":"suggestionDiag","body":{"file":"/Users/dan/projects/portal/client/src/common/monoblocks/form/FormIpCidrInput.tsx","diagnostics":[{"start":{"line":103,"offset":7},"end":{"line":103,"offset":21},"text":"'cidrInputsLens' is declared but its value is never read.","code":6133,"category":"suggestion","reportsUnnecessary":true},{"start":{"line":137,"offset":11},"end":{"line":137,"offset":23},"text":"'onChange' is declared but its value is never read.","code":6133,"category":"suggestion","reportsUnnecessary":true},{"start":{"line":153,"offset":11},"end":{"line":153,"offset":21},"text":"'inputs' is declared but its value is never read.","code":6133,"category":"suggestion","reportsUnnecessary":true}]}}
Info 2893 [10:39:33.691] event:
    {"seq":0,"type":"event","event":"requestCompleted","body":{"request_seq":106}}
Info 2894 [10:39:34.3] request:
    {"seq":107,"type":"request","command":"getApplicableRefactors","arguments":{"file":"/Users/dan/projects/portal/client/src/common/monoblocks/form/FormIpCidrInput.tsx","startLine":144,"startOffset":8,"endLine":144,"endOffset":8}}
Perf 2895 [10:39:34.4] 107::getApplicableRefactors: elapsed time (in milliseconds) 0.6625
Info 2896 [10:39:34.4] response:
    {"seq":0,"type":"response","command":"getApplicableRefactors","request_seq":107,"success":true,"body":[]}
Info 2897 [10:39:34.4] request:
    {"seq":108,"type":"request","command":"getCodeFixes","arguments":{"file":"/Users/dan/projects/portal/client/src/common/monoblocks/form/FormIpCidrInput.tsx","startLine":144,"startOffset":7,"endLine":144,"endOffset":16,"errorCodes":[2552]}}```

[quicksnap]

Those logs are from 3.8.3, not nightly, since I booted in --disable-extensions mode to gather them with semanticHighlighting disabled.

[EricKit]

I also have issues with semantic highlighting in medium to large files.

Perf 430 [18:29:11.606] 104::encodedSemanticClassifications-full: elapsed time (in milliseconds) 1029.8463

Disabling semantic highlighting resolves my delays. Commenting a line takes ~1 second. Disabling it, it appears immediate.

[VictorQueiroz]

I'm trying to move on from 3.8.3 for a long time, because it's the only version which does not kill my productivity. I have an extremely slow code completion in anything higher than 3.8.3. Currently the logs are from TS 4.4.2.

Sometimes resting the cursor over a property/method completely stucks TS server for seconds:

Perf 566  [01:39:04.841] 14::encodedSemanticClassifications-full: elapsed time (in milliseconds) 6612.9189

This is code completion when writing a dot after an object, after ~8 seconds I could finally see the property list:

Info 798  [02:05:51.334] Starting updateGraphWorker: Project: /home/work/Projects/hidden/core/tsconfig.json
Info 799  [02:05:51.380] Finishing updateGraphWorker: Project: /home/work/Projects/hidden/core/tsconfig.json Version: 3 structureChanged: false structureIsReused:: Completely Elapsed: 45.291651997715235ms
Info 800  [02:05:51.380] Different program with same set of files
Info 801  [02:05:51.382] getCompletionData: Get current token: 0.027127999812364578
Info 802  [02:05:51.382] getCompletionData: Is inside comment: 0.06167500093579292
Info 803  [02:05:51.382] getCompletionData: Get previous token: 0.03589100018143654
Info 804  [02:05:51.382] getCompletionsAtPosition: isCompletionListBlocker: 0.17612700164318085
Info 805  [02:05:55.188] getCompletionData: Semantic work: 3805.772270999849
Info 806  [02:05:55.189] getCompletionsAtPosition: getCompletionEntriesFromSymbols: 0.7570599988102913
Info 807  [02:05:55.639] IntelliCode plugin: successfully loaded model from /home/work/.vscode/extensions/visualstudioexptteam.vscodeintellicode-1.2.14/cache/1A3F919CD5B7725108B03C349630A1C82B03_4A84987F2428442A9EC84563BB2BC063
Info 808  [02:05:55.640] IntelliCode plugin: program found
Info 809  [02:05:55.640] IntelliCode plugin: source file found
Info 810  [02:05:55.641] IntelliCode plugin: determined type: "reducer".IAuthenticationForgotPasswordState
Info 811  [02:05:55.642] IntelliCode plugin: pushing prior access: email
Info 812  [02:05:55.653] IntelliCode plugin: prior accesses: email
Info 813  [02:05:55.653] IntelliCode plugin: sequences: N~email,N
Info 814  [02:05:55.653] IntelliCode plugin: sequences: N~email,N
Info 815  [02:05:55.653] IntelliCode plugin: added metadata {"Id":1630364755653,"ModelVersion":"typescript_1.5","Count":0,"FailureReason":"NotInModel","Class":"","InIf":false,"ElapsedTime":463.245825,"Methods":[],"PrevInvoc":"","ItemMetadata":{}} to completion result
Perf 816  [02:05:55.654] 95::completionInfo: elapsed time (in milliseconds) 4319.9144

Another test with VS Code Insiders:

Info 603  [02:19:20.988] Starting updateGraphWorker: Project: /home/work/Projects/hidden/core/tsconfig.json
Info 604  [02:19:21.034] Finishing updateGraphWorker: Project: /home/work/Projects/hidden/core/tsconfig.json Version: 3 structureChanged: false structureIsReused:: Completely Elapsed: 45.792923998087645ms
Info 605  [02:19:21.034] Different program with same set of files
Info 606  [02:19:21.035] getCompletionData: Get current token: 0.039069999009370804
Info 607  [02:19:21.035] getCompletionData: Is inside comment: 0.05014200136065483
Info 608  [02:19:21.035] getCompletionData: Get previous token: 0.04182099923491478
Info 609  [02:19:21.035] getCompletionsAtPosition: isCompletionListBlocker: 0.00338900089263916
Info 610  [02:19:25.077] getCompletionData: Semantic work: 4042.3234740011394
Info 611  [02:19:25.080] getCompletionsAtPosition: getCompletionEntriesFromSymbols: 1.3409719988703728
Perf 612  [02:19:25.081] 40::completionInfo: elapsed time (in milliseconds) 4093.2213
Info 613  [02:19:25.081] response:
    {"seq":0,"type":"response","command":"completionInfo","request_seq":40,"success":true,"performanceData":{"updateGraphDurationMs":45.792923998087645},"body":{"isGlobalCompletion":false,"isMemberCompletion":true,"isNewIdentifierLocation":false,"entries":[{"name":"email","kind":"property","kindModifiers":"","sortText":"11"},{"name":"error","kind":"property","kindModifiers":"optional","sortText":"11"},{"name":"isLoading","kind":"property","kindModifiers":"","sortText":"11"},{"name":"state","kind":"property","kindModifiers":"","sortText":"11"}]}}
Info 614  [02:19:25.082] request:
    {"seq":41,"type":"request","command":"encodedSemanticClassifications-full","arguments":{"file":"/home/work/Projects/hidden/core/authentication/effects/index.ts","start":2441,"length":3413,"format":"2020"}}
Perf 615  [02:19:27.203] 41::encodedSemanticClassifications-full: elapsed time (in milliseconds) 2121.3128

VS Code Insiders version:

Version: 1.60.0-insider
Commit: 44a4b19a910a287adef4daaeabcf68f2ba893c35
Date: 2021-08-30T11:36:28.164Z
Electron: 13.1.8
Chrome: 91.0.4472.164
Node.js: 14.16.0
V8: 9.1.269.39-electron.0
OS: Linux x64 5.10.61-1-lts snap

VS Code version:

Version: 1.59.1
Commit: 3866c3553be8b268c8a7f8c0482c0c0177aa8bfa
Date: 2021-08-19T11:54:37.513Z
Electron: 13.1.7
Chrome: 91.0.4472.124
Node.js: 14.16.0
V8: 9.1.269.36-electron.0
OS: Linux x64 5.10.61-1-lts snap

My question mainly is, how can I find out exactly what are the expressions in this project (70k+ LoC), that are creating these problems? Any help is much appreciated. Thank you!

[andrewbranch]

This is now being tracked at #44851.