Suggestions regression since 3.6.0-dev.20190713

[IllusionMH]

TypeScript Version: 3.6.0-dev.20190717 (first version with problem 3.6.0-dev.20190713)

Search Terms: completion, completionInfo, autoimport

It is hard to provide repro code since this problem is found in large (4388 files processed by TS) code base with closed source.

However I see two regressions:

1. Performance hit even for suggestions for variables/imports in current file
2. Suggestions of other files exports are missing (even if there is already one named import from file where expected completion item located)

Performance problem

import { getSelectorData } from 'tools/store-reference';
...
function retrieveValue() {
    const valueType = getSe/* cursor here */
}

In TS Server log is see huge difference in performance and value for Semantic work

Log for 3.6.0-dev.20190713 (and later)

Info 4207 [15:36:38.239] request:
    {"seq":26,"type":"request","command":"completionInfo","arguments":{"file":"<filename>","line":30,"offset":28,"includeExternalModuleExports":true,"includeInsertTextCompletions":true}}
Info 4208 [15:36:38.240] getCompletionData: Get current token: 0
Info 4209 [15:36:38.240] getCompletionData: Is inside comment: 0
Info 4210 [15:36:38.240] getCompletionData: Get previous token 1: 0
Info 4211 [15:36:38.240] getCompletionData: Get previous token 2: 0
Info 4212 [15:36:38.240] getCompletionsAtPosition: isCompletionListBlocker: 0
Info 4213 [15:36:49.509] getCompletionData: Semantic work: 11269
Info 4214 [15:36:49.518] getCompletionsAtPosition: getCompletionEntriesFromSymbols: 8
Perf 4215 [15:36:49.525] 26::completionInfo: elapsed time (in milliseconds) 11286.3765
Info 4216 [15:36:49.526] response: <response object>

Log for 3.6.0-dev.20190712

Info 4180 [15:47:10.169] request:
    {"seq":23,"type":"request","command":"completionInfo","arguments":{"file":"<filename>","line":30,"offset":28,"includeExternalModuleExports":true,"includeInsertTextCompletions":true}}
Info 4181 [15:47:10.170] getCompletionData: Get current token: 0
Info 4182 [15:47:10.170] getCompletionData: Is inside comment: 0
Info 4183 [15:47:10.170] getCompletionData: Get previous token 1: 0
Info 4184 [15:47:10.170] getCompletionData: Get previous token 2: 0
Info 4185 [15:47:10.171] getCompletionsAtPosition: isCompletionListBlocker: 1
Info 4186 [15:47:10.238] getCompletionData: Semantic work: 67
Info 4187 [15:47:10.250] getCompletionsAtPosition: getCompletionEntriesFromSymbols: 11
Perf 4188 [15:47:10.260] 23::completionInfo: elapsed time (in milliseconds) 90.6148
Info 4189 [15:47:10.261] response: <response object (has more values than latest versions)>

Suggestion form other files

import { getSelectorData /*correctly suggest dispatchAction and other exports here*/ } from 'tools/store-reference';
...
dispatchAction/*no suggestion here*/

This is project written in JS has @types packages in node_modules 1 level above project package.json (since it isn't commited for everyone)

Related Issues:
Probably related to #31893 however it is unclear why there is big performance hit for "local" suggestions and why I'm unable to see suggestions from other files even (in the same folder).
I would understand why there might be no globals @types/* that are not specified in package.json, but not sure why there are no suggestion from other files at all.

Would be glad to follow instructions that will help to narrow this problem, however cannot provide source code.

[IllusionMH]

The behavior I’ve coded here is to look for all package.jsons in scope for the current file and offer auto-imports from all of them.

If this statement in #31893 (comment) is still true and it would include all package.json files between file and volume root then I would expect to see all suggestions (I have both package.json and node_modules/@types/* 1 level above the project)

@andrewbranch could you please confirm that all package.json files between edited file and volume root will be checked for @types packages?

[andrewbranch]

Whoa, 90ms to 11 seconds? 😱 That’s obviously unacceptable, and since you isolated the change to a single day, I feel quite confident it’s #31893. I’m going to revert it for now because that’s just unusable.

As far as missing things go, there’s a test verifying that multiple levels of package.jsons are looked at, so I’m not sure what the problem is there, but would love your help investigating further once I can improve the performance.

Thanks for the detailed reports!

[IllusionMH]

Do you have any suggestions what I should check (or profile) first in order to narrow root cause?

Also I would like to mention that I encountered this problem on large project, and when tried to create repro with 2-3 files everything worked as expected (suggestions were fast and also contained auto imports from other files).

[fatcerberus]

Shouldn’t #31893 cause the compiler to do less work, not more?

[IllusionMH]

I haven't done any profiling or detailed look at PR (so may be wrong in my assumptions), however first thing that I will check if it is because of deep nesting because of convention + 2 package.json files.
I suspect that there might be penalty when TS checks all parent folders while looking for package.json and then checks paths for dependencies.

Also comment #31893 (review) isn't marked as resolved so I'm not sure if it is possible to cache everything.

But at this time it's just a speculation on my part.

[andrewbranch]

Shouldn’t #31893 cause the compiler to do less work, not more?

You’d think so intuitively, but no—all those external modules are already in the program, so getting the whole lot of them is pretty easy. Adding additional filters to them adds work. (Particularly, looking for and reading package.json files, and deduplicating re-exports of the same symbol taking into account that some re-exports might be in modules specified in package.json while some may not be.)

Also comment #31893 (review) isn't marked as resolved so I'm not sure if it is possible to cache everything.

It should be possible, but the caching didn’t make it into that PR. If I make a second attempt, it will likely have to include a caching scheme.

Do you have any suggestions what I should check (or profile) first in order to narrow root cause?

Do you mean for the performance regression or for the missing exports? For the perf, my plan is just to run a JS sampling profiler with ndb to see what’s taking so much time. For the missing exports, you could probably figure it out just by stepping through the filtering code I added to importFixes.ts. Of course I plan to do this at some point (likely not this week), but if you want to start investigating, that’s awesome 👍

[andrewbranch]

I reverted the problematic PR, but I’ll leave this one open to track the progress of bringing it back.

[IllusionMH]

@andrewbranch thank you! I will verify timings with that next build and follow up.

Also I tried to debug tsserver, but no luck. I was using approach described in Debugging Language Service in VS Code - I can see that process.env.TSS_DEBUG is set to 5859 inside devtools but I'm unable to attach any debugger (build in chrome or from another VS Code instance).
Do you know if this doc is still correct? If not could you please suggest proper docs on how to do that?

Or I should launch tsserver manually (with ndb) and call it directly to profile?

[andrewbranch]

Do you know if this doc is still correct?

Yeah, but the order of the steps there is important—is it possible you set the environment variable and then tried to attach to an existing VS Code instance? I usually just do TSS_DEBUG=5859 code ., and then in another Code window, I just do ⌘⇧P → Attach to Node Process → pick the one with 5859.

Also, it’s much easier to debug a local build of TypeScript with source maps—not sure if you were doing that or not. Clone TypeScript, npm run build, then in the test project, point the TypeScript version specified in .vscode/settings.json to TypeScript/built/local. You can also ⌘⇧P → Restart TS Server to pick up a new build (from npm run build in the TypeScript repo) on the fly, then reattach.

[IllusionMH]

If it works for you that it is something strange with my PC - nothing runs on selected post (even after project is fully processed by tsserver and I can see suggestions).

$ TSS_DEBUG=6699 code-insiders

$ curl localhost:6699/json/version
curl: (7) Failed to connect to localhost port 6699: Connection refused

Working examples for browser and node

Browser running with --remote-debugging-port=9222

$ curl localhost:9222/json/version
{
   "Browser": "Edg/77.0.221.0",
   "Protocol-Version": "1.3",
   "User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3851.0 Safari/537.36 Edg/77.0.221.0",
   "V8-Version": "7.7.213",
   "WebKit-Version": "537.36 (@6cddbee7eee3614cce9c4226a6d6ace7937636d9)",
   "webSocketDebuggerUrl": "ws://localhost:9222/devtools/browser/75a2d31e-4a2c-494c-adcc-2400f7beecd7"
}

For node started as node --inspect-brk=9966 -e "console.log('works')"

$ curl localhost:9966/json/version
{
  "Browser": "node.js/v10.16.0",
  "Protocol-Version": "1.1"
}

Anyway, now I'm sure that it is correct way to debug tsserver and only one step left.

You can also ⌘⇧P → Restart TS Server to pick up a new build (from npm run build in the TypeScript repo) on the fly, then reattach.

Thanks for the tip! Will be useful when I will attach debugger.

[andrewbranch]

FWIW I’m on a Mac and it looks like you’re on Windows, but everything I see here looks correct 🤔

[IllusionMH]

As usually: checked 3 times on different ports that it doesn't work, posted GitHub comment, tried one more time and voilà - there is response for curl calls and I was able to attach debugger :)

Thanks for the help. I will let you know if I'll find anything useful.

[IllusionMH]

Checked [email protected] and suggestions are fast now - about 220-350 ms.
However it most likely caused by some changes to project and/or PC load because I see same timings for [email protected].

Haven't chance to profile slow nightly builds yet.

[andrewbranch]

The culprit is the repeated calls of this stack: getNodeModulesPackageNameFromFileName -> getModuleSpecifier -> ... -> discoverProbableSymlinks. discoverProbablySymlinks seems to account for a pretty huge amount of the new time for getSymbolsFromOtherSourceFileExports.