Long running 'completions' request on TS project using lodash

[mjbvz]

From microsoft/vscode#47253 (comment)

TypeScript Version: 2.9.0-dev.20180409

Search Terms:

• completions

Code
In a new folder without a tsconfig:

package.json:

{
  "name": "test",
  "private": true,
  "version": "1.0.0",
  "description": "",
  "main": "index.js",
  "keywords": [],
  "author": "",
  "license": "ISC",
  "dependencies": {
    "@types/lodash": "^4.14.106",
    "lodash": "^4.17.5",
    "typescript": "^2.9.0-dev.20180409"
  }
}

index.ts:

import * as _ from 'lodash';

const result = _.chain([]).ma
// or
const result = _([]).ma

1. Run npm install
2. Open index.ts in vscode
3. Trigger completions on .ma

Bug:
TS Server completions requests end up taking ~6seconds each time. Here's my tsserver log
tsserver copy.log

Look for the lines around: getCompletionData: Semantic work: 6974

[ghost]

Probably a duplicate of #21968

[sheetalkamat]

Looks like we are spending lot of time in isTypeAssignableTo for conforms, flow, flowRight and such which is in multiple seconds and then there are few where we are spending time in three digit miliseconds

Info 82   [16:0:1.532] getCompletionData: IsValidTime: 8756 addPropertySymbolTime: 1

Info 1907 [16:0:1.557] getCompletionData:: conforms isValidPropertyAccessWithType::getPropertyOfType :: 0
Info 1908 [16:0:1.557] getCompletionData:: conforms isValidPropertyAccessWithType::checkPropertyAccessibility :: 0
Info 1909 [16:0:1.557] getCompletionData:: conforms isValidMethodAccess::getTypeOfFuncClassEnumModule :: 0
Info 1910 [16:0:1.557] getCompletionData:: conforms isValidMethodAccess::getSignaturesOfType :: 0
Info 1911 [16:0:1.557] getCompletionData:: conforms isValidMethodAccess:: getThisTypeOfSignature :: 0
Info 1912 [16:0:1.557] getCompletionData:: conforms isValidMethodAccess:: isTypeAssignableTo :: 2636
Info 1913 [16:0:1.557] getCompletionData:: conforms isValidMethodAccess::[{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":2636}] :: 0

Info 1928 [16:0:1.557] getCompletionData:: flow isValidPropertyAccessWithType::getPropertyOfType :: 0
Info 1929 [16:0:1.557] getCompletionData:: flow isValidPropertyAccessWithType::checkPropertyAccessibility :: 0
Info 1930 [16:0:1.557] getCompletionData:: flow isValidMethodAccess::getTypeOfFuncClassEnumModule :: 0
Info 1931 [16:0:1.557] getCompletionData:: flow isValidMethodAccess::getSignaturesOfType :: 0
Info 1932 [16:0:1.557] getCompletionData:: flow isValidMethodAccess:: getThisTypeOfSignature :: 7
Info 1933 [16:0:1.557] getCompletionData:: flow isValidMethodAccess:: isTypeAssignableTo :: 2681
Info 1934 [16:0:1.557] getCompletionData:: flow isValidMethodAccess::[{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":111},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":92},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":31},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":62},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":55},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":58},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":27},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":53},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":60},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":62},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":63},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":31},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":73},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":81},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":57},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":29},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":70},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":75},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":51},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":55},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":24},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":66},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":61},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":64},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":27},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":59},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":61},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":65},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":66},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":28},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":68},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":65},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":68},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":26},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":75},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":73},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":70},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":26},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":73},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":95},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":129},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":145},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":51}] :: 0

Info 1935 [16:0:1.557] getCompletionData:: flowRight isValidPropertyAccessWithType::getPropertyOfType :: 0
Info 1936 [16:0:1.557] getCompletionData:: flowRight isValidPropertyAccessWithType::checkPropertyAccessibility :: 0
Info 1937 [16:0:1.557] getCompletionData:: flowRight isValidMethodAccess::getTypeOfFuncClassEnumModule :: 0
Info 1938 [16:0:1.557] getCompletionData:: flowRight isValidMethodAccess::getSignaturesOfType :: 0
Info 1939 [16:0:1.557] getCompletionData:: flowRight isValidMethodAccess:: getThisTypeOfSignature :: 4
Info 1940 [16:0:1.557] getCompletionData:: flowRight isValidMethodAccess:: isTypeAssignableTo :: 2312
Info 1941 [16:0:1.557] getCompletionData:: flowRight isValidMethodAccess::[{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":74},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":78},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":68},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":19},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":58},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":70},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":71},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":69},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":28},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":65},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":86},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":81},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":25},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":69},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":69},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":70},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":23},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":75},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":69},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":72},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":66},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":22},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":66},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":66},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":68},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":21},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":69},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":66},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":69},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":74},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":26},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":89},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":72},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":67},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":20},{"signatureThisType":true,"getThisTypeOfSignature":1,"isTypeAssignableTo":67},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":72},{"signatureThisType":true,"getThisTypeOfSignature":0,"isTypeAssignableTo":73}] :: 0

Used branch https://github.com/Microsoft/TypeScript/tree/completionLodashPerfInvestigation for these extra debug info and used code and package.json mentioned in repro for this analysis.

[sheetalkamat]

@weswigham can you take a look if we can do something better with isTypeAssignableTo in this case? U think we spend time to compare this types that say no is isn't assignable for these methods (to not show them in the completion)

[weswigham]

I get instant completions on lodash on master with @types/lodash v 4.14.118 and with 4.14.106 as in the OP. It seems like this was fixed by something else?

[sheetalkamat]

@weswigham No it still repros. This is what I see. (I think you need to just remove the dot and type it again to ensure that you are getting completion from fresh graph. Note how semantic work takes 8+ seconds ).

Info 1089 [8:40:38.475] request:
    {"seq":186,"type":"request","command":"change","arguments":{"insertString":".","file":"c:/temp/test2/index.ts","line":2,"offset":27,"endLine":2,"endOffset":27}}
Perf 1090 [8:40:38.475] 186::change: async elapsed time (in milliseconds) 0.1827
Info 1091 [8:40:38.476] request:
    {"seq":187,"type":"request","command":"completionInfo","arguments":{"file":"c:/temp/test2/index.ts","line":2,"offset":28,"includeExternalModuleExports":true,"includeInsertTextCompletions":true,"triggerCharacter":"."}}
Info 1092 [8:40:38.476] Starting updateGraphWorker: Project: /dev/null/inferredProject1*
Info 1093 [8:40:38.482] Finishing updateGraphWorker: Project: /dev/null/inferredProject1* Version: 32 structureChanged: false Elapsed: 6ms
Info 1094 [8:40:38.482] getCompletionData: Get current token: 0
Info 1095 [8:40:38.482] getCompletionData: Is inside comment: 0
Info 1096 [8:40:38.482] getCompletionData: Get previous token 1: 0
Info 1097 [8:40:38.482] getCompletionsAtPosition: isCompletionListBlocker: 0
Info 1098 [8:40:47.437] getCompletionData: Semantic work: 8955
Info 1099 [8:40:47.440] getCompletionsAtPosition: getCompletionEntriesFromSymbols: 2
Perf 1100 [8:40:47.442] 187::completionInfo: elapsed time (in milliseconds) 8965.6524

[weswigham]

Hm, you're right, Opened it up and tried it again and saw the problem. Anyway, I have a change that cuts it from around 8s to 3s on my machine; but the core of the issue is what isValidPropertyAccessForCompletions is doing right now - it's essentially doing a (partial) call resolution, which is fairly expensive. My change caches the result, so it can be reused if encountered again, which seems to help, since completions is always followed by a completion entry details request which currently repeats the work.

[sheetalkamat]

@weswigham While I was investigating this, I had questioned whether doing check for correct this parameter is correct. Frankly I think we can just remove that check (since that's valid only for calling and not for assignment of the method to another variable anyways?) That would just break the test case that introduced this check in first place (which I believe was just a single test case) What are your thoughts on doing that instead?

[weswigham]

Caching doesn't really help (why would it) on inspection; I had messed up the cache key while I was looking at it, so it was just skipping a bunch. T.T I'm going to reiterate the "is this really necessary" question, and continue looking into why the comparisons are slow (but I have a suspicion that it's because lodash is a big tree of this types that are just plain expensive to compare and we're running hundreds of them).

[weswigham]

We spend a huge chunk of time in gc - compareSignaturesRelated is responsible for around 400MB of garbage of the duration of the call (!!!).

[weswigham]

Yeaaaah, we allocate 2,334,604 symbols while processing that completion list. For reference, that's about 60x the number we make for the incomplete program itself, or around 7400 symbols per potential completion member.

[tun100]

Has the problem been solved? I still encountered this problem. The version I used is as follows:
[email protected], @types/[email protected], [email protected]
Vscode is code_1. 31.0 1549443364 _amd64. Deb

I wanna using _.chain([]).mapValues and when i type _.chain([]). ,it will give me intellisense, but seems it need loading 8s and more time.
Is there some settings i need to setup up in vscode? thanks!

[weswigham]

This should be fixed by #31377 in the next typescript@next and 3.5.