Slow completions request not cancellable while collecting auto-imports

[OliverJAsh]

Bug Report

🔎 Search Terms

auto completions complete suggestions performance slow vs code typing

🕗 Version & Regression Information

• This is the behavior in every version I tried, and I reviewed the FAQ for entries about performance

⏯ Playground Link

N/A

💻 Code

1. Clone and checkout https://github.com/unsplash/unsplash-web/tree/typescript-completion-performance, branch typescript-completion-performance. This is a private repository but I believe some members of the TS team already have access from debugging previous issues. If you don't have access, please send me your email address so I can provide access (TS team members only).
2. Run yarn to install TS
3. Open VS Code, navigate to the file app/helpers/my-test.ts and wait for TS to finish initialising

Type O. and wait for completions to appear.

🙁 Actual behavior

Completions should appear quickly.

🙂 Expected behavior

Completions appear slowly.

tsserver.log

web.mov

In the TS server log we can see that completions are slow:

Info 1961 [11:58:01.660] request:
    {"seq":8,"type":"request","command":"completionInfo","arguments":{"file":"/Users/oliverash/Development/unsplash-web/app/helpers/my-test.ts","line":3,"offset":2,"includeExternalModuleExports":true,"includeInsertTextCompletions":true}}
Info 1962 [11:58:01.660] Starting updateGraphWorker: Project: /Users/oliverash/Development/unsplash-web/tsconfig.app.json
Info 1963 [11:58:01.841] Finishing updateGraphWorker: Project: /Users/oliverash/Development/unsplash-web/tsconfig.app.json Version: 2 structureChanged: false Elapsed: 180.94832699745893ms
Info 1964 [11:58:01.841] Different program with same set of files:: structureIsReused:: 2
Info 1965 [11:58:01.843] getCompletionData: Get current token: 0.007962003350257874
Info 1966 [11:58:01.843] getCompletionData: Is inside comment: 0.03854600340127945
Info 1967 [11:58:01.843] getCompletionData: Get previous token 1: 0.015626996755599976
Info 1968 [11:58:01.844] getCompletionData: Get previous token 2: 0.1929429993033409
Info 1969 [11:58:01.844] getCompletionsAtPosition: isCompletionListBlocker: 0.3775179982185364
Info 1970 [11:58:01.850] collectAutoImports: starting, not resolving module specifiers
Info 1971 [11:58:01.850] collectAutoImports: module specifier cache size: 0
Info 1972 [11:58:01.999] getSymbolToExportInfoMap: cache miss or empty; calculating new results
Info 1973 [11:58:02.589] getSymbolToExportInfoMap: caching results
Info 1974 [11:58:02.589] getSymbolToExportInfoMap: done in 738.1664780005813 ms
Info 1975 [11:58:02.847] collectAutoImports: done in 996.4206670001149 ms
Info 1976 [11:58:02.847] getCompletionData: Semantic work: 1002.4234960004687
Info 1977 [11:58:02.978] getCompletionsAtPosition: getCompletionEntriesFromSymbols: 130.66120900213718
Perf 1978 [11:58:02.996] 8::completionInfo: elapsed time (in milliseconds) 1336.2221

The response for the completionInfo command contains an enormous body (see full log file) which seems to describe the exports for every single module in the TS project. I find this surprising considering we're only asking for the exports of one module.

I tested this in a fresh VS Code instance with no extensions.

I also tested this in a new folder and it was much faster.

tsserver.log

simple.mov

[andrewbranch]

I think what you’re looking at is the completions request for when you typed O, not when you typed ., and we’re probably just not cancelling the previous request soon enough. Actually, I know we don’t check the cancellation token during some of those auto-import tasks that can potentially take a long time. If you look a bit closer at the server log, does that match what you’re seeing? One surefire test would be to restart TS Server after you’ve already typed O and let . be the first/only thing you type.

[OliverJAsh]

One surefire test would be to restart TS Server after you’ve already typed O and let . be the first/only thing you type.

Yes that's significantly faster!

[OliverJAsh]

I was hoping I could workaround the slowness by disabling auto imports / import suggestions, but from the logs it looks like TS still "collects" the auto imports regardless of these settings:

"typescript.suggest.autoImports": false,
"typescript.suggest.includeCompletionsForImportStatements": false,
"javascript.suggest.autoImports": false,
"javascript.suggest.includeCompletionsForImportStatements": false

[andrewbranch]

"typescript.suggest.includeCompletionsForModuleExports": false should definitely work...

TypeScript/src/services/completions.ts

Line 1841 in 837ed96

if (!preferences.includeCompletionsForModuleExports) return false;

[OliverJAsh]

Are these two different settings or are they the same thing?

• includeCompletionsForImportStatements
• includeCompletionsForModuleExports

[OliverJAsh]

Perhaps VS Code needs to add a new setting to pass through the includeCompletionsForModuleExports setting to TS?

[andrewbranch]

Oh yeah, those are different. includeCompletionsForImportStatements is for completions at import s|, added in 4.3. includeCompletionsForModuleExports is for auto-imports generally.

[andrewbranch]

When I disable this, no auto-import related work shows up in the logs for me.

[OliverJAsh]

FYI: just tested #45138 via the nightly and it seems to work really well now. Thank you!

---

With regards to microsoft/vscode#127663:

@andrewbranch

When I disable this, no auto-import related work shows up in the logs for me.

I just tested it again and I'm definitely seeing collectAutoImports take up a lot of time.

Here is a video to demonstrate. You can see that the relevant setting is disabled.

https://www.dropbox.com/s/wgfdw0aycg7g4bl/Screen%20Recording%202021-07-22%20at%2007.48.34.mov?dl=0

tsserver.log

To rule out extensions or user settings, I tested this using a fresh instance of VS Code: code --user-data-dir temp --extensions-dir temp-extensions .. I also deleted workspace settings inside the root folder of the repo: rm -rf .vscode.

Are you able to reproduce using my steps from the original post above, i.e. inside of the unsplash-web repo?

[andrewbranch]

Ah, it’s on completion details that it’s building the map. Ok, I can fix that.

[andrewbranch]

@OliverJAsh actually, I think I already did. The log you just sent me is for TS 4.3.4. I’m pretty sure I fixed that issue in #44713. Can you send me a log showing the issue with the nightly build, if it repros there? I think it shouldn’t.

[OliverJAsh]

I can confirm that this is fixed in the nightly. When I enable the setting I no longer see collectAutoImports in the logs. 🎉