Skip to content

Auto imports (getExportInfoMap) extremely slow #46735

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

Closed
moataz9 opened this issue Oct 11, 2021 · 45 comments
Closed

Auto imports (getExportInfoMap) extremely slow #46735

moataz9 opened this issue Oct 11, 2021 · 45 comments
Assignees
Labels
Domain: Auto-import Domain: Performance Reports of unusually slow behavior Needs Investigation This issue needs a team member to investigate its status.

Comments

@moataz9
Copy link

moataz9 commented Oct 11, 2021

Issue Type: Performance Issue

trying to use ctrl + space
loading... for a period of time
when I disabled it from builtin extensions
the list is shown as expected

please vs-code team solve that problem because that builtin extension is so essential for us as a web developer
best regards
thanks.

VS Code version: Code 1.61.0 (ee8c7def80afc00dd6e593ef12f37756d8f504ea, 2021-10-07T18:13:09.652Z)
OS version: Windows_NT x64 10.0.19043
Restricted Mode: No

System Info
Item Value
CPUs Intel(R) Core(TM) i5-2430M CPU @ 2.40GHz (4 x 2395)
GPU Status 2d_canvas: enabled
gpu_compositing: enabled
multiple_raster_threads: enabled_on
oop_rasterization: unavailable_off
opengl: enabled_on
rasterization: unavailable_off
skia_renderer: enabled_on
video_decode: enabled
vulkan: disabled_off
webgl: enabled
webgl2: unavailable_off
Load (avg) undefined
Memory (System) 7.91GB (2.46GB free)
Process Argv --crash-reporter-id d08f27d4-fc58-4cb3-87cf-fb19d0a2ef1e
Screen Reader no
VM 0%
Process Info
CPU %	Mem MB	   PID	Process
    0	    79	  9868	code main
    0	    87	  3704	   shared-process
    0	    67	  4632	     ptyHost
    0	     6	  1120	       console-window-host (Windows internal process)
    0	    48	  9336	       C:\WINDOWS\System32\WindowsPowerShell\v1.0\powershell.exe
    0	     5	  1088	         C:\WINDOWS\system32\cmd.exe /c ""C:\Program Files\nodejs\npm.cmd" start"
    0	    34	 11440	           "C:\Program Files\nodejs\\node.exe"  "C:\Program Files\nodejs\\node_modules\npm\bin\npm-cli.js" start
    0	     5	 11568	             electron_node app.js 
    0	    28	 11600	               electron_node nodemon.js app.js 
    0	    41	 12692	                 "C:\Program Files\nodejs\node.exe" app.js
    0	    22	  3772	   crashpad-handler
    0	   186	  5456	   gpu-process
    0	    34	  5736	   utility
    0	    82	  6732	   window (Issue Reporter)
    0	   208	  8128	   window (auth.js - starter - Visual Studio Code)
    0	    61	  1380	     watcherService
    0	   143	  5748	     extensionHost
    0	    64	   124	       electron_node eslintServer.js 
    0	    62	  1504	       electron_node serverMain.js 
    0	    63	  2688	       electron_node server.js 
    0	   624	  4948	       electron_node tsserver.js 
    0	    70	  6304	         electron_node typingsInstaller.js typesMap.js 
    0	    64	  5700	       electron_node server.js 
    0	    74	  7056	       electron_node tsserver.js 
    0	    70	 10684	     searchService
Workspace Info
|  Window (auth.js - starter - Visual Studio Code)
|    Folder (starter): 28 files
|      File types: js(16) json(2) env(1) gitignore(1) MD(1)
|      Conf files: package.json(1);
Extensions (77)
Extension Author (truncated) Version
better-comments aar 2.1.0
codesnap adp 1.3.4
format-selection-as-html adr 2.3.0
spaces-inside-braces Air 0.4.0
Bookmarks ale 13.2.2
copy-relative-path ale 0.0.2
auto-add-brackets ali 0.12.0
html-end-tag-labels ant 0.8.0
generate-wt-scheme bla 0.0.5
npm-intellisense chr 1.4.0
path-intellisense chr 2.4.0
bracket-pair-colorizer Coe 1.0.61
bracket-pair-colorizer-2 Coe 0.2.1
split-html-attributes dan 1.0.10
vscode-markdownlint Dav 0.44.4
vscode-eslint dba 2.2.1
dotfiles-syntax-highlighting dot 0.1.0
pug-formatter duc 0.6.0
vscode-html-css ecm 1.10.2
EditorConfig Edi 0.16.4
vscode-npm-script eg2 0.3.22
magick-image-reader ely 0.5.0
vsc-material-theme-icons equ 2.2.1
prettier-vscode esb 9.0.0
php-debug fel 1.19.0
vscode-firefox-debug fir 2.9.4
vscode-npm fkn 3.3.0
auto-close-tag for 0.5.12
auto-rename-tag for 0.1.8
vscode-mysql for 0.4.1
shell-format fox 7.1.1
gc-excelviewer Gra 3.0.44
output-colorizer IBM 0.1.2
phpcs ika 1.0.5
php-cs-fixer jun 0.2.8
cmderrunner jus 0.1.2
vscode-colorize kam 0.11.1
vscode-gutter-preview kis 0.27.1
node-module-intellisense lei 1.5.0
rainbow-csv mec 1.9.1
dotenv mik 1.0.1
HTMLHint mka 0.10.0
vscode-filesize mkx 3.1.0
vscode-scss mrm 0.10.0
python ms- 2021.10.1317843341
vscode-pylance ms- 2021.10.0
jupyter ms- 2021.9.1001312534
jupyter-keymap ms- 1.0.0
jupyter-renderers ms- 1.0.3
live-server ms- 0.2.9
vscode-typescript-next ms- 4.5.20211010
vscode-typescript-tslint-plugin ms- 1.3.3
debugger-for-chrome msj 4.13.0
debugger-for-edge msj 1.0.15
vscode-javascript-comment Nic 0.0.8
vscode-javascript-snippet Nic 0.1.2
vetur oct 0.34.1
indent-rainbow ode 8.2.0
vscode-html-scss P-d 0.0.42
nested-comments phi 2.3.1
csv-to-table php 1.3.0
material-icon-theme PKi 4.10.0
heroku-command pko 0.0.8
polacode pnp 0.3.4
vscode-css-peek pra 4.2.0
LiveServer rit 5.6.1
color-manager roy 0.6.3
html5-boilerplate sid 1.1.1
html-to-css-autocompletion sol 1.1.2
sass-indented syl 1.8.18
es6-string-html Tob 2.11.0
remove-empty-lines use 0.0.8
highlight-matching-tag vin 0.10.1
vscodeintellicode Vis 1.2.14
rainbow-tags vol 0.3.2
material-theme zhu 3.13.2
cmder-here zyq 0.0.2

(3 theme extensions excluded)

A/B Experiments
vsliv368cf:30146710
vsreu685:30147344
python383cf:30185419
pythonvspyt602:30300191
vspor879:30202332
vspor708:30202333
vspor363:30204092
vstes627:30244334
pythonvspyt639:30300192
pythontb:30283811
pythonptprofiler:30281270
vshan820:30294714
vstes263cf:30335440
vscoreces:30358480
pythondataviewer:30285071
pythonvsuse255:30340121
vscod805:30301674
pythonvspyt200:30340761
binariesv615:30325510
vsccppwt:30378364
pythonvssor306:30344512
bridge0708:30335490
pygetstartedt2:30371810
dockerwalkthru:30377721
bridge0723:30353136
pythonrunftest32:30373476
pythonf5test824:30373475
javagetstartedt:30364666
pythonvspyt187:30373474
pydsgst2:30361792
vsqsis200:30374795
vsaa593:30376534
vssld246:30379911

@IllusionMH
Copy link
Contributor

/needsMoreInfo

Is it reproducible with all extensions disabled?
You can try this with F1 and >Developer: Reload Window With Extensions Disabled

Is this problem consistent across different projects?

@moataz9
Copy link
Author

moataz9 commented Oct 12, 2021

This problem appears when working with node projects

@moataz9
Copy link
Author

moataz9 commented Oct 12, 2021

it's taking a period of time to show suggestions list

@moataz9
Copy link
Author

moataz9 commented Oct 12, 2021

Screenshot (2)

@moataz9
Copy link
Author

moataz9 commented Oct 12, 2021

Screenshot (13)

@moataz9
Copy link
Author

moataz9 commented Oct 12, 2021

when I disable that built-in Extention, VS Code works normally in the task manager.

@ullaskunder3
Copy link

ullaskunder3 commented Oct 12, 2021

@moataz9 Exactly I'm facing the same problem... : (

  • It happens when I work with Node_modules backend project
  • And It work fine for normal JavaScript files with no node packages

@moataz9
Copy link
Author

moataz9 commented Oct 12, 2021

yes that's it

@mjbvz
Copy link
Contributor

mjbvz commented Oct 12, 2021

Please share an example project that demonstrates the issue

@moataz9
Copy link
Author

moataz9 commented Oct 13, 2021

When I work on a small node project (using less than 4 packages) the suggestions list shown up normally. when I add more packages to use in that project, it leads the suggestions list doesn't appear normally (loading ... for a long period sometimes it take 2 min to show up and VS code in the task manager take more than normally in CPU measure as I mentioned previously )

here are the packages I use in my project

{
"dependencies": {
    "bcryptjs": "^2.4.3",
    "cors": "^2.8.5",
    "dotenv": "^10.0.0",
    "express": "^4.17.1",
    "express-async-errors": "^3.1.1",
    "express-rate-limit": "^5.3.0",
    "helmet": "^4.6.0",
    "http-status-codes": "^2.1.4",
    "joi": "^17.4.0",
    "jsonwebtoken": "^8.5.1",
    "mongoose": "^5.13.2",
    "rate-limiter": "^0.2.0",
    "swagger-ui-express": "^4.1.6",
    "xss-clean": "^0.1.1",
    "yamljs": "^0.3.0"
  },
  "devDependencies": {
    "nodemon": "^2.0.9"
  }
}

@ullaskunder3
Copy link

@moataz9 hyy reinstalled nodejs and vs code worked

  • Uninstall vs code from control panel
  • delete the hidden save data from
  • %UserFolder%.vscode.
  • %UserFolder%\AppData\Roaming\Code
  • reinstall vs code

@moataz9
Copy link
Author

moataz9 commented Oct 18, 2021

@ullaskunder3 it doesn't really work for me

@mjbvz
Copy link
Contributor

mjbvz commented Oct 18, 2021

@moataz9 How do I reproduce this issue using that project?

@moataz9
Copy link
Author

moataz9 commented Oct 18, 2021

@mjbvz here is the project repo
https://github.com/moataz9/jobs-api

@mjbvz
Copy link
Contributor

mjbvz commented Oct 19, 2021

Thanks but what specific steps do I take to reproduce this issue in that project?

@moataz9
Copy link
Author

moataz9 commented Oct 19, 2021

For me in normal js files, it works with no performance problems and in the node projects when I press ctrl + space to show up the suggestions list it takes a long period plus that I heard my laptop's fan is spinning so fast so I check my task manager and here is what I found.
Screenshot (13)

@moataz9
Copy link
Author

moataz9 commented Oct 19, 2021

In my opinion, that problem occurred because the extension gathering its data, again and again, every time the VScode activate that extension (the suggestions list, coloring unused variables & functions parameters, ....)
it sould gathering node_modules folder one time and watching it for any adding packages to project.

@mjbvz
Copy link
Contributor

mjbvz commented Oct 19, 2021

Please share the specific steps to trigger this issue. I don't see an this problem if I open connect.js and trigger suggestions

Also does this reproduce in the latest VS Code insiders build with all extensions disabled? (don't disable the built-in extension)

@moataz9
Copy link
Author

moataz9 commented Oct 19, 2021

@mjbvz yes, it's still reproduced in the latest VS Code insiders build with all extensions disabled.
And for me, this problem happens each time VS Code activated this extension (the suggestions list, coloring unused variables & functions parameters, .... ).

@moataz9
Copy link
Author

moataz9 commented Oct 19, 2021

here is exactly what happens in my laptop
https://youtu.be/eSUXYArETZI

@mjbvz
Copy link
Contributor

mjbvz commented Oct 21, 2021

Please try collecting the TS Server log for this:

  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

⚠️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

@moataz9
Copy link
Author

moataz9 commented Oct 22, 2021

here is my tsserver log file
https://github.com/moataz9/tsserver/blob/main/tsserver.log

@ullaskunder3
Copy link

@moataz9 @mjbvz hello sir, I think Typescript intelligence causing delay because of mongoose

@moataz9
Copy link
Author

moataz9 commented Oct 25, 2021

@ullaskunder3 I try to use it inside another project that doesn't use MongoDB (small node and express app) and unfortunately is still reproduced on my pc

@moataz9
Copy link
Author

moataz9 commented Oct 25, 2021

do I need to exchange any hardware chips

@ullaskunder3
Copy link

@moataz9 sir did you changed the typescript version, right now vs code using 4.4.3 &
did you installed node_module => mongodb locally or globally
Did you tried clean reinstalling with all the root folder most of the time they are hidden and when we reinstall it goes back to old messed up settings...

@moataz9
Copy link
Author

moataz9 commented Oct 25, 2021

@ullaskunder3

  • I didn't change the typescript version
  • I installed mongodb package locally
  • I reinstalled all the root folders ( I reinstall all my extensions and change vsCode sitting as I need )

@devb119
Copy link

devb119 commented Oct 28, 2021

Facing the same problems on my node project. I found out that it works just fine before I install node_modules but after installing packages it becomes extremely slow. Here are the packages that i'm using
image

@whengely
Copy link

I have this issue and do not use mongoose. It's been so slow the past couple of months that I've started typing everything out. Not much to contribute but didn't want anyone caught up on mongoose specifically.

@elclanrs
Copy link

elclanrs commented Nov 4, 2021

Same issue here. After 10-15min intellisense becomes unbearable and I have to keep restarting the editor. I have a fairly simple file with about 300 lines of code for a Babel plugin using @babel/core, but it eventually becomes slow regardless of the project.

I tried both on Linux and Windows and have the same exact issue on both OSs.

@mjbvz mjbvz transferred this issue from microsoft/vscode Nov 8, 2021
@mjbvz mjbvz removed their assignment Nov 8, 2021
@mjbvz
Copy link
Contributor

mjbvz commented Nov 8, 2021

Thanks for the logs @moataz9!

From them, I can see where the long requests are happening:

Info 336  [16:38:32.189] getExportInfoMap: cache miss or empty; calculating new results
Info 337  [16:38:45.544] forEachExternalModuleToImportFrom autoImportProvider: 813.0726000070572
Info 338  [16:38:45.544] getExportInfoMap: done in 18613.582800000906 ms
Info 339  [16:38:45.664] DirectoryWatcher:: Added:: WatchInfo: c:/users/moataz/appdata/local/microsoft/typescript/4.5/node_modules 1 undefined WatchType: node_modules for closed script infos and package.jsons affecting module specifier cache
Info 340  [16:38:45.664] watchDirectory for c:/users/moataz/appdata/local/microsoft/typescript/4.5/node_modules uses cached drive information.
Info 341  [16:38:45.666] Elapsed:: 1.297100007534027ms DirectoryWatcher:: Added:: WatchInfo: c:/users/moataz/appdata/local/microsoft/typescript/4.5/node_modules 1 undefined WatchType: node_modules for closed script infos and package.jsons affecting module specifier cache
Info 342  [16:38:45.765] collectAutoImports: resolved 85 module specifiers, plus 41 ambient and -14959 from cache
Info 343  [16:38:45.765] collectAutoImports: response is complete
Info 344  [16:38:45.765] collectAutoImports: 220.53980001807213
Info 345  [16:38:45.765] getCompletionData: Semantic work: 18842.079499989748
Info 346  [16:38:45.834] getCompletionsAtPosition: getCompletionEntriesFromSymbols: 67.11149999499321
Perf 347  [16:38:45.847] 40::completionInfo: elapsed time (in milliseconds) 18928.3270

Moving upstream to TS to see if they have any ideas on what may be causing this

@mjbvz mjbvz changed the title vscode.typescript-language-features is slow down the suggestion's list Slow IntelliSense in project Nov 8, 2021
@andrewbranch
Copy link
Member

@moataz9 can you try disabling TypeScript > Preferences: Include Package JSON Auto Imports and seeing how much that improves things?

image

@andrewbranch andrewbranch added Domain: Auto-import Domain: Performance Reports of unusually slow behavior Needs Investigation This issue needs a team member to investigate its status. labels Nov 9, 2021
@andrewbranch andrewbranch self-assigned this Nov 9, 2021
@andrewbranch andrewbranch added this to the TypeScript 4.6.0 milestone Nov 9, 2021
@moataz9
Copy link
Author

moataz9 commented Nov 10, 2021

@andrewbranch I tried that solution but it doesn't affect the issue

@andreialecu
Copy link

Related (re: mongoose):

#45249
Automattic/mongoose#10349

@vvo
Copy link

vvo commented Nov 22, 2021

Also experiencing slow VSCode since 4.5 upgrade. I believe maybe because of https://github.com/Vincit/objection.js/ types?

Switching back to 4.4 makes it instant, as usual.

@zeshanvirk
Copy link

Crashes in Angular 12 Project with Typescript 4.3.5
image

@atsikov
Copy link

atsikov commented Nov 26, 2021

I'm experiencing the same issue. With 4.5.2 it takes 2 minutes to simply load a type hint on hover (Controller from react-hook-form in this particular case). Our project is indeed huge, but the same operation with vs code's built-in 4.4.3 is instant.

I have no idea what's happening under the hood, but these are the two things from the server log that look very slow in 4.52:

  • "command":"geterr" - almost two minutes until "event":"requestCompleted" against ~10ms for 4.4.3
  • 44::encodedSemanticClassifications-full: elapsed time (in milliseconds) 109280.8950 against less than 1s first time and less than 10ms later for 4.4.3
Part of TS 4.5.2 server log
Info 2001 [19:47:33.826] request:
    {"seq":41,"type":"request","command":"geterr","arguments":{"delay":0,"files":["/Users/aleksei.tsikov/git/project/src/Component.tsx"]}}
Perf 2002 [19:47:33.827] 41::geterr: async elapsed time (in milliseconds) 0.3917
Info 2003 [19:47:33.828] event:
    {"seq":0,"type":"event","event":"syntaxDiag","body":{"file":"/Users/aleksei.tsikov/git/project/src/Component.tsx","diagnostics":[]}}
Info 2004 [19:49:29.994] event:
    {"seq":0,"type":"event","event":"requestCompleted","body":{"request_seq":41}}
Info 2005 [19:49:29.996] request:
    {"seq":42,"type":"request","command":"getApplicableRefactors","arguments":{"file":"/Users/aleksei.tsikov/git/project/src/Component.tsx","startLine":1,"startOffset":1,"endLine":1,"endOffset":1}}
Perf 2006 [19:49:30.009] 42::getApplicableRefactors: elapsed time (in milliseconds) 13.2598
Info 2007 [19:49:30.009] response:
    {"seq":0,"type":"response","command":"getApplicableRefactors","request_seq":42,"success":true,"body":[{"name":"Convert export","description":"Convert default export to named export","actions":[{"name":"Convert default export to named export","description":"Convert default export to named export","kind":"refactor.rewrite.export.named","notApplicableReason":"Could not find export statement"},{"name":"Convert named export to default export","description":"Convert named export to default export","kind":"refactor.rewrite.export.default","notApplicableReason":"Could not find export statement"}]},{"name":"Convert import","description":"Convert namespace import to named imports","actions":[{"name":"Convert namespace import to named imports","description":"Convert namespace import to named imports","kind":"refactor.rewrite.import.named","notApplicableReason":"Selection is not an import declaration."}]},{"name":"Convert import","description":"Convert named imports to namespace import","actions":[{"name":"Convert named imports to namespace import","description":"Convert named imports to namespace import","kind":"refactor.rewrite.import.namespace","notApplicableReason":"Selection is not an import declaration."}]},{"name":"Extract Symbol","description":"Extract function","actions":[{"name":"Extract Function","description":"Extract function","kind":"refactor.extract.function","notApplicableReason":"Cannot extract empty range."}]},{"name":"Extract Symbol","description":"Extract constant","actions":[{"name":"Extract Constant","description":"Extract constant","kind":"refactor.extract.constant","notApplicableReason":"Cannot extract empty range."}]},{"name":"Extract type","description":"Extract type","actions":[{"name":"Extract to typedef","description":"Extract to typedef","kind":"refactor.extract.typedef","notApplicableReason":"Selection is not a valid type node"},{"name":"Extract to type alias","description":"Extract to type alias","kind":"refactor.extract.type","notApplicableReason":"Selection is not a valid type node"},{"name":"Extract to interface","description":"Extract to interface","kind":"refactor.extract.interface","notApplicableReason":"Selection is not a valid type node"}]},{"name":"Move to a new file","description":"Move to a new file","actions":[{"name":"Move to a new file","description":"Move to a new file","kind":"refactor.move.newFile","notApplicableReason":"Selection is not a valid statement or statements"}]},{"name":"Add or remove braces in an arrow function","description":"Add or remove braces in an arrow function","actions":[{"name":"Add braces to arrow function","description":"Add braces to arrow function","kind":"refactor.rewrite.arrow.braces.add","notApplicableReason":"Could not find a containing arrow function"},{"name":"Remove braces from arrow function","description":"Remove braces from arrow function","kind":"refactor.rewrite.arrow.braces.remove","notApplicableReason":"Could not find a containing arrow function"}]},{"name":"Convert to template string","description":"Convert to template string","actions":[{"name":"Convert to template string","description":"Convert to template string","kind":"refactor.rewrite.string","notApplicableReason":"Can only convert string concatenation"}]},{"name":"Infer function return type","description":"Infer function return type","actions":[{"name":"Infer function return type","description":"Infer function return type","kind":"refactor.rewrite.function.returnType","notApplicableReason":"Return type must be inferred from a function"}]}]}
Info 2008 [19:49:30.009] request:
    {"seq":43,"type":"request","command":"projectInfo","arguments":{"file":"/Users/aleksei.tsikov/git/project/src/Component.tsx","needFileNameList":false}}
Perf 2009 [19:49:30.009] 43::projectInfo: elapsed time (in milliseconds) 0.1021
Info 2010 [19:49:30.009] response:
    {"seq":0,"type":"response","command":"projectInfo","request_seq":43,"success":true,"body":{"configFileName":"/Users/aleksei.tsikov/git/project/tsconfig.json","languageServiceDisabled":false}}
Info 2011 [19:49:30.011] request:
    {"seq":44,"type":"request","command":"encodedSemanticClassifications-full","arguments":{"file":"/Users/aleksei.tsikov/git/project/src/Component.tsx","start":1277,"length":3642,"format":"2020"}}
Perf 2012 [19:51:19.295] 44::encodedSemanticClassifications-full: elapsed time (in milliseconds) 109280.8950
Info 2013 [19:51:19.295] response:
    {"seq":0,"type":"response","command":"encodedSemanticClassifications-full","request_seq":44,"success":true,"body":{"spans":[1281,8,2561,1312,6,2561,1342,8,2561,1368,6,2561,1403,29,2825,1436,11,1793,1449,11,1536,1463,17,1544,1496,11,1792,1678,11,1792,1702,5,1537,1712,5,2561,1720,4,1536,1728,15,2561,1769,16,2057,1787,3,1536,1791,5,1536,1803,5,1793,1810,15,1793,1844,5,2857,1851,12,2857,1865,7,2089,1874,8,2857,1887,7,2816,1895,10,1536,1913,13,2561,1936,9,2561,1947,15,1792,1970,8,2561,1980,8,2816,1989,10,2816,2004,4,272,2023,6,2561,2031,10,2816,2046,4,272,2066,4,2561,2100,11,2560,2113,5,2857,2120,4,2089,2126,6,2089,2137,11,2816,2150,6,1793,2158,10,1536,2177,3,2056,2181,4,2560,2186,23,3072,2218,9,2561,2229,6,1792,2236,9,2560,2253,8,2561,2263,6,1792,2270,8,2560,2279,7,3088,2296,6,2561,2304,6,1792,2311,6,2560,2318,7,3088,2350,12,2089,2365,4,2088,2371,4,2560,2393,11,2089,2406,19,2089,2430,13,2816,2444,12,2088,2467,11,2089,2481,7,2816,2501,5,1792,2514,3,3088,2518,8,1793,2533,5,2561,2540,8,1792,2549,3,2560,2554,5,2561,2561,8,1792,2570,5,2560,2586,5,1792,2607,9,2089,2619,5,2856,2646,8,2089,2657,5,2856,2800,15,1792,2868,7,2088,2933,5,1793,3044,11,2088,3288,7,2088,3348,5,1793,3475,5,1792,3481,5,2560,3514,5,1793,3549,8,2089,3560,10,2816,3571,5,1792,3598,5,1792,3604,8,3072,3613,8,2088,3641,8,2856,3660,7,2816,3668,8,2088,3789,7,2088,3847,5,1793,3999,6,2561,4007,8,2088,4035,5,2561,4042,8,2816,4051,8,2088,4107,5,1792,4113,5,2560,4146,5,1793,4175,5,1792,4181,8,3072,4190,10,2816,4201,5,1792,4381,12,2856,4394,10,1793,4408,5,2856,4414,10,1792,4475,9,2088,4618,29,2824,4648,6,2088,4673,11,2088,4705,7,2056,4754,6,2088,4865,19,2088],"endOfLineState":0}}
Info 2014 [19:51:19.297] request:
    {"seq":47,"type":"request","command":"provideInlayHints","arguments":{"file":"/Users/aleksei.tsikov/git/project/src/Component.tsx","start":714,"length":4205}}
Perf 2015 [19:51:19.350] 47::provideInlayHints: elapsed time (in milliseconds) 52.9589
Info 2016 [19:51:19.350] response:
    {"seq":0,"type":"response","command":"provideInlayHints","request_seq":47,"success":true,"body":[{"text":": PropsWithChildren<CellProps...","position":{"line":36,"offset":21},"kind":"Type","whitespaceBefore":true},{"text":": Element","position":{"line":36,"offset":22},"kind":"Type","whitespaceBefore":true},{"text":"date:","position":{"line":36,"offset":56},"kind":"Parameter","whitespaceAfter":true},{"text":": PropsWithChildren<CellProps...","position":{"line":49,"offset":21},"kind":"Type","whitespaceBefore":true},{"text":": Element","position":{"line":49,"offset":22},"kind":"Type","whitespaceBefore":true},{"text":"value:","position":{"line":50,"offset":34},"kind":"Parameter","whitespaceAfter":true},{"text":": (queryStatus: QueryStatus) ...","position":{"line":63,"offset":36},"kind":"Type","whitespaceBefore":true},{"text":": Props","position":{"line":79,"offset":72},"kind":"Type","whitespaceBefore":true},{"text":": Element","position":{"line":79,"offset":73},"kind":"Type","whitespaceBefore":true},{"text":"props:","position":{"line":80,"offset":74},"kind":"Parameter","whitespaceAfter":true},{"text":"date:","position":{"line":83,"offset":26},"kind":"Parameter","whitespaceAfter":true},{"text":"amount:","position":{"line":83,"offset":50},"kind":"Parameter","whitespaceAfter":true},{"text":"date:","position":{"line":83,"offset":37},"kind":"Parameter","whitespaceAfter":true},{"text":"date:","position":{"line":84,"offset":26},"kind":"Parameter","whitespaceAfter":true},{"text":"mutationFn:","position":{"line":89,"offset":60},"kind":"Parameter","whitespaceAfter":true},{"text":": AxiosPromise<RevPTransactio...","position":{"line":89,"offset":80},"kind":"Type","whitespaceBefore":true},{"text":": RevPTransaction[]","position":{"line":97,"offset":21},"kind":"Type","whitespaceBefore":true},{"text":"data:","position":{"line":99,"offset":62},"kind":"Parameter","whitespaceAfter":true},{"text":": { label: string; value: str...","position":{"line":101,"offset":20},"kind":"Type","whitespaceBefore":true},{"text":"factory:","position":{"line":102,"offset":5},"kind":"Parameter","whitespaceAfter":true},{"text":"deps:","position":{"line":103,"offset":5},"kind":"Parameter","whitespaceAfter":true},{"text":": { label: string; value: str...","position":{"line":102,"offset":7},"kind":"Type","whitespaceBefore":true},{"text":"callbackfn:","position":{"line":102,"offset":29},"kind":"Parameter","whitespaceAfter":true},{"text":": Card","position":{"line":102,"offset":37},"kind":"Type","whitespaceBefore":true},{"text":": string","position":{"line":106,"offset":18},"kind":"Type","whitespaceBefore":true},{"text":"name:","position":{"line":106,"offset":27},"kind":"Parameter","whitespaceAfter":true},{"text":": Date","position":{"line":107,"offset":17},"kind":"Type","whitespaceBefore":true},{"text":"name:","position":{"line":107,"offset":26},"kind":"Parameter","whitespaceAfter":true},{"text":": { field: ControllerRenderPr...","position":{"line":117,"offset":33},"kind":"Type","whitespaceBefore":true},{"text":": Element","position":{"line":117,"offset":34},"kind":"Type","whitespaceBefore":true},{"text":": { field: ControllerRenderPr...","position":{"line":132,"offset":31},"kind":"Type","whitespaceBefore":true},{"text":": Element","position":{"line":132,"offset":32},"kind":"Type","whitespaceBefore":true},{"text":": Date | null","position":{"line":137,"offset":32},"kind":"Type","whitespaceBefore":true},{"text":": Date","position":{"line":138,"offset":33},"kind":"Type","whitespaceBefore":true},{"text":"date:","position":{"line":138,"offset":47},"kind":"Parameter","whitespaceAfter":true},{"text":"...event:","position":{"line":140,"offset":34},"kind":"Parameter","whitespaceAfter":true},{"text":"name:","position":{"line":141,"offset":28},"kind":"Parameter","whitespaceAfter":true},{"text":"value:","position":{"line":141,"offset":38},"kind":"Parameter","whitespaceAfter":true},{"text":"date:","position":{"line":141,"offset":46},"kind":"Parameter","whitespaceAfter":true},{"text":"amount:","position":{"line":141,"offset":56},"kind":"Parameter","whitespaceAfter":true},{"text":": { field: ControllerRenderPr...","position":{"line":149,"offset":31},"kind":"Type","whitespaceBefore":true},{"text":": Element","position":{"line":149,"offset":32},"kind":"Type","whitespaceBefore":true},{"text":"date:","position":{"line":155,"offset":35},"kind":"Parameter","whitespaceAfter":true},{"text":"amount:","position":{"line":155,"offset":45},"kind":"Parameter","whitespaceAfter":true},{"text":": Date | null","position":{"line":158,"offset":32},"kind":"Type","whitespaceBefore":true},{"text":"...event:","position":{"line":159,"offset":34},"kind":"Parameter","whitespaceAfter":true},{"text":"date:","position":{"line":159,"offset":45},"kind":"Parameter","whitespaceAfter":true},{"text":"onValid:","position":{"line":168,"offset":35},"kind":"Parameter","whitespaceAfter":true},{"text":": { cardToken: string; dateFr...","position":{"line":168,"offset":45},"kind":"Type","whitespaceBefore":true},{"text":"variables:","position":{"line":168,"offset":55},"kind":"Parameter","whitespaceAfter":true},{"text":"queryStatus:","position":{"line":178,"offset":55},"kind":"Parameter","whitespaceAfter":true}]}
Info 2017 [19:51:19.350] request:
    {"seq":48,"type":"request","command":"getApplicableRefactors","arguments":{"file":"/Users/aleksei.tsikov/git/project/src/Component.tsx","startLine":126,"startOffset":17,"endLine":126,"endOffset":17}}
Perf 2018 [19:51:19.352] 48::getApplicableRefactors: elapsed time (in milliseconds) 2.1181
Info 2019 [19:51:19.352] response:
    {"seq":0,"type":"response","command":"getApplicableRefactors","request_seq":48,"success":true,"body":[{"name":"Convert export","description":"Convert default export to named export","actions":[{"name":"Convert default export to named export","description":"Convert default export to named export","kind":"refactor.rewrite.export.named","notApplicableReason":"Could not find export statement"},{"name":"Convert named export to default export","description":"Convert named export to default export","kind":"refactor.rewrite.export.default","notApplicableReason":"Could not find export statement"}]},{"name":"Convert import","description":"Convert namespace import to named imports","actions":[{"name":"Convert namespace import to named imports","description":"Convert namespace import to named imports","kind":"refactor.rewrite.import.named","notApplicableReason":"Selection is not an import declaration."}]},{"name":"Convert import","description":"Convert named imports to namespace import","actions":[{"name":"Convert named imports to namespace import","description":"Convert named imports to namespace import","kind":"refactor.rewrite.import.namespace","notApplicableReason":"Selection is not an import declaration."}]},{"name":"Extract Symbol","description":"Extract function","actions":[{"name":"Extract Function","description":"Extract function","kind":"refactor.extract.function","notApplicableReason":"Cannot extract empty range."}]},{"name":"Extract Symbol","description":"Extract constant","actions":[{"name":"Extract Constant","description":"Extract constant","kind":"refactor.extract.constant","notApplicableReason":"Cannot extract empty range."}]},{"name":"Extract type","description":"Extract type","actions":[{"name":"Extract to typedef","description":"Extract to typedef","kind":"refactor.extract.typedef","notApplicableReason":"Selection is not a valid type node"},{"name":"Extract to type alias","description":"Extract to type alias","kind":"refactor.extract.type","notApplicableReason":"Selection is not a valid type node"},{"name":"Extract to interface","description":"Extract to interface","kind":"refactor.extract.interface","notApplicableReason":"Selection is not a valid type node"}]},{"name":"Generate 'get' and 'set' accessors","description":"Generate 'get' and 'set' accessors","actions":[{"name":"Generate 'get' and 'set' accessors","description":"Generate 'get' and 'set' accessors","kind":"refactor.rewrite.property.generateAccessors","notApplicableReason":"Could not find property for which to generate accessor"}]},{"name":"Move to a new file","description":"Move to a new file","actions":[{"name":"Move to a new file","description":"Move to a new file","kind":"refactor.move.newFile","notApplicableReason":"Selection is not a valid statement or statements"}]},{"name":"Convert to template string","description":"Convert to template string","actions":[{"name":"Convert to template string","description":"Convert to template string","kind":"refactor.rewrite.string","notApplicableReason":"Can only convert string concatenation"}]},{"name":"Infer function return type","description":"Infer function return type","actions":[{"name":"Infer function return type","description":"Infer function return type","kind":"refactor.rewrite.function.returnType","notApplicableReason":"Return type must be inferred from a function"}]}]}
Info 2020 [19:51:19.353] request:
    {"seq":50,"type":"request","command":"quickinfo","arguments":{"file":"/Users/aleksei.tsikov/git/project/src/Component.tsx","line":129,"offset":16}}
Perf 2021 [19:51:19.364] 50::quickinfo: elapsed time (in milliseconds) 11.1055
Info 2022 [19:51:19.364] response:
    {"seq":0,"type":"response","command":"quickinfo","request_seq":50,"success":true,"body":{"kind":"alias","kindModifiers":"declare","start":{"line":129,"offset":12},"end":{"line":129,"offset":22},"displayString":"(alias) const Controller: <TFieldValues extends FieldValues = FieldValues, TName extends Path<TFieldValues> = Path<TFieldValues>>(props: ControllerProps<TFieldValues, TName>) => import(\"react\").ReactElement<any, string | import(\"react\").JSXElementConstructor<any>>\nimport Controller","documentation":[],"tags":[]}}
Info 2023 [19:51:19.364] request:
    {"seq":51,"type":"request","command":"geterr","arguments":{"delay":0,"files":["/Users/aleksei.tsikov/git/project/src/Component.tsx"]}}
Perf 2024 [19:51:19.364] 51::geterr: async elapsed time (in milliseconds) 0.4231
Info 2025 [19:51:19.366] event:
    {"seq":0,"type":"event","event":"syntaxDiag","body":{"file":"/Users/aleksei.tsikov/git/project/src/Component.tsx","diagnostics":[]}}
Info 2026 [19:51:19.825] event:
    {"seq":0,"type":"event","event":"requestCompleted","body":{"request_seq":51}}
Info 2027 [19:51:19.827] request:
    {"seq":52,"type":"request","command":"quickinfo","arguments":{"file":"/Users/aleksei.tsikov/git/project/src/Component.tsx","line":129,"offset":16}}
Perf 2028 [19:51:19.839] 52::quickinfo: elapsed time (in milliseconds) 11.8457
Info 2029 [19:51:19.839] response:
    {"seq":0,"type":"response","command":"quickinfo","request_seq":52,"success":true,"body":{"kind":"alias","kindModifiers":"declare","start":{"line":129,"offset":12},"end":{"line":129,"offset":22},"displayString":"(alias) const Controller: <TFieldValues extends FieldValues = FieldValues, TName extends Path<TFieldValues> = Path<TFieldValues>>(props: ControllerProps<TFieldValues, TName>) => import(\"react\").ReactElement<any, string | import(\"react\").JSXElementConstructor<any>>\nimport Controller","documentation":[],"tags":[]}}
Info 2030 [19:51:19.839] request:
    {"seq":53,"type":"request","command":"geterr","arguments":{"delay":0,"files":["/Users/aleksei.tsikov/git/project/src/Component.tsx"]}}
Perf 2031 [19:51:19.840] 53::geterr: async elapsed time (in milliseconds) 0.1562
Info 2032 [19:51:19.841] event:
    {"seq":0,"type":"event","event":"syntaxDiag","body":{"file":"/Users/aleksei.tsikov/git/project/src/Component.tsx","diagnostics":[]}}

@andrewbranch
Copy link
Member

andrewbranch commented Nov 29, 2021

@atsikov semantic highlighting is the only thing in that log that looks at all slow. If you disable semantic highlighting in VS Code settings, how is the perf?

Ah sorry, I missed the geterr elapsed time coming back as a separate event.

@atsikov
Copy link

atsikov commented Nov 29, 2021

Here's the minimal repro (basically, only react and react-hook-form)
https://github.com/atsikov/ts-4.5.2-perf-issue

I've found out that this issue is reproducible with react-hook-form < 7.17.2. In react-hook-form/react-hook-form@85097ae types were improved, so with >= 7.17.2 type hints and autocomplete work as expected.

@kmoschcau
Copy link

Hi, I hope I can give some additional helpful info. I maintain a repo with some fairly complex generic types and I can see a huge performance difference in both tsc and tsserver between 4.4.4 and 4.5.2.

Also I don't think this is really related to the VSCode plugin, because I use (Neo)Vim and a language client plugin in there to talk to tsserver. The autocompletion with 4.4.4 is there in less than a second while 4.5.2 sometimes takes longer than 5 seconds. (My client just lets it time out then.) Another thing I observed is that the hover comes up fairly quickly, but autocompletion does not. When the repo files are freshly changed both take a really long time to come up.

Here is the repo: https://github.com/League-of-Foundry-Developers/foundry-vtt-types
You should be able to compile it with both typescript versions by just cloning it, running npm ci and then tsc in the root. I ran both versions with --extendedDiagnostics on this repo and here are the stats for both runs. (Especially of note are the tripled amount of types and the more than doubled check time.)

4.4.4
tsc --extendedDiagnostics
Files:                         478
Lines of Library:            27589
Lines of Definitions:       146444
Lines of TypeScript:             0
Lines of JavaScript:             0
Lines of JSON:                   0
Lines of Other:                  0
Nodes of Library:           114619
Nodes of Definitions:       341949
Nodes of TypeScript:             0
Nodes of JavaScript:             0
Nodes of JSON:                   0
Nodes of Other:                  0
Identifiers:                168963
Symbols:                    196745
Types:                       80541
Instantiations:             176586
Memory used:               266118K
Assignability cache size:    38755
Identity cache size:           302
Subtype cache size:              3
Strict subtype cache size:       1
I/O Read time:               0.03s
Parse time:                  1.70s
ResolveModule time:          0.09s
ResolveTypeReference time:   0.01s
Program time:                1.89s
Bind time:                   1.03s
Check time:                  5.49s
printTime time:              0.00s
Emit time:                   0.00s
Total time:                  8.40s
4.5.2
tsc --extendedDiagnostics
Files:                         478
Lines of Library:            26543
Lines of Definitions:       146444
Lines of TypeScript:             0
Lines of JavaScript:             0
Lines of JSON:                   0
Lines of Other:                  0
Nodes of Library:           114494
Nodes of Definitions:       341871
Nodes of TypeScript:             0
Nodes of JavaScript:             0
Nodes of JSON:                   0
Nodes of Other:                  0
Identifiers:                168741
Symbols:                    196841
Types:                      264674
Instantiations:             178696
Memory used:               328640K
Assignability cache size:    76679
Identity cache size:           301
Subtype cache size:              3
Strict subtype cache size:       2
I/O Read time:               0.03s
Parse time:                  1.75s
ResolveModule time:          0.09s
ResolveTypeReference time:   0.01s
Program time:                1.98s
Bind time:                   0.94s
Check time:                 12.92s
printTime time:              0.00s
Emit time:                   0.00s
Total time:                 15.84s

xdy added a commit to xdy/xdy-pf2e-workbench that referenced this issue Nov 29, 2021
@atsikov
Copy link

atsikov commented Nov 29, 2021

@andrewbranch turns out, it's not only about vs code, yarn tsc is also incredibly slow. Not sure why I didn't notice type checking issues after the upgrade on my main project.

4.5.2 created 30 times more (intermediate?) types and consumed 8 times more memory.

TS 4.4.4 extended diagnostics
Files:                         50
Lines of Library:           26160
Lines of Definitions:       24762
Lines of TypeScript:           14
Lines of JavaScript:            0
Lines of JSON:                  0
Lines of Other:                 0
Nodes of Library:          112958
Nodes of Definitions:       60457
Nodes of TypeScript:           55
Nodes of JavaScript:            0
Nodes of JSON:                  0
Nodes of Other:                 0
Identifiers:                58865
Symbols:                    39464
Types:                      28967
Instantiations:             86282
Memory used:               93470K
Assignability cache size:   17107
Identity cache size:           62
Subtype cache size:             0
Strict subtype cache size:      0
I/O Read time:              0.01s
Parse time:                 0.48s
ResolveModule time:         0.02s
ResolveTypeReference time:  0.00s
Program time:               0.53s
Bind time:                  0.21s
Check time:                 0.64s
printTime time:             0.00s
Emit time:                  0.00s
Total time:                 1.39s
TS 4.5.2 extended diagnostics
Files:                          50
Lines of Library:            25009
Lines of Definitions:        24762
Lines of TypeScript:            14
Lines of JavaScript:             0
Lines of JSON:                   0
Lines of Other:                  0
Nodes of Library:           112478
Nodes of Definitions:        60453
Nodes of TypeScript:            55
Nodes of JavaScript:             0
Nodes of JSON:                   0
Nodes of Other:                  0
Identifiers:                 58582
Symbols:                     39008
Types:                     1048793
Instantiations:             135356
Memory used:               724704K
Assignability cache size:  7007111
Identity cache size:            27
Subtype cache size:              0
Strict subtype cache size:       0
I/O Read time:               0.03s
Parse time:                  0.49s
ResolveModule time:          0.02s
ResolveTypeReference time:   0.00s
Program time:                0.57s
Bind time:                   0.22s
Check time:                 93.30s
printTime time:              0.00s
Emit time:                   0.00s
Total time:                 94.09s

@andrewbranch andrewbranch changed the title Slow IntelliSense in project Auto imports (getExportInfoMap) extremely slow Nov 29, 2021
@andrewbranch
Copy link
Member

This is excellent repro information @atsikov and @kmoschcau. However, it’s a completely separate issue from the one reported by @moataz9, so I’ve forked your issue to #46948. If you have any further discussion, please continue it there. Let’s keep this issue specific to getExportInfoMap being super slow as shown in the TS Server log (which I haven’t been able to repro but need to try more).

@andrewbranch
Copy link
Member

@moataz9 do you still have this issue when you use the latest nightly JS/TS via this extension? The slowness you measured is showing up in a different place than what others mentioned here, but it could actually have the same root cause. We’ve made a lot of performance fixes recently so it’s worth trying this again.

@moataz9
Copy link
Author

moataz9 commented Dec 7, 2021

@andrewbranch no, I don't have this issue anymore. thanks for the great work.
note: I upgrade my working PC to another one with a higher processing speed

@moataz9 moataz9 closed this as completed Dec 7, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Domain: Auto-import Domain: Performance Reports of unusually slow behavior Needs Investigation This issue needs a team member to investigate its status.
Projects
None yet
Development

No branches or pull requests

14 participants