getEditsForFileRename taking long time

[mjbvz]

TypeScript Version: 3.4.0-rc

Search Terms:

• getEditsForFileRename
• file move
• update imports

Repo

1. In the VS Code codebase
2. Open the file src/vs/editor/contrib/codeAction/codeAction.ts
3. Wait for js/ts language features to be fully initialized
4. Now rename this file to codeActionRenamed

Bug
This triggers a getEditsForFileRename request that takes between 5 and 10 seconds to resolve. Here's the tsserver.log.

[sheetalkamat]

@mjbvz I don't seem to see this either with vscode or insiders build from latest typescript build from master.
With vscode:

Info 8843 [15:43:2.305] request:
    {"seq":25,"type":"request","command":"getEditsForFileRename","arguments":{"file":"c:/github/vscode/src/vs/editor/contrib/codeAction/codeActionRename.ts","oldFilePath":"c:/github/vscode/src/vs/editor/contrib/codeAction/codeAction.ts","newFilePath":"c:/github/vscode/src/vs/editor/contrib/codeAction/codeActionRename.ts"}}
Perf 8844 [15:43:2.673] 25::getEditsForFileRename: elapsed time (in milliseconds) 367.1587

With insiders:

Info 8851 [15:46:54.377] request:
    {"seq":30,"type":"request","command":"getEditsForFileRename","arguments":{"oldFilePath":"c:/github/vscode/src/vs/editor/contrib/codeAction/codeAction.ts","newFilePath":"c:/github/vscode/src/vs/editor/contrib/codeAction/codeActionRenamed.ts"}}
Perf 8852 [15:46:54.706] 30::getEditsForFileRename: elapsed time (in milliseconds) 329.2082

[mjbvz]

I still see this using TS 3.4.1 but I think the long running request is actually the configure request we send before requesting getEditsForFileRename. Here's the VS Code timing of that request before getEditsForFileRename:

[Trace  - 10:53:31 AM] Sending request: configure (42). Response expected: yes. Current queue length: 3
Arguments: {
    "formatOptions": {
        "tabSize": 4,
        "indentSize": 4,
        "convertTabsToSpaces": false,
        "newLineCharacter": "\n",
        "insertSpaceAfterCommaDelimiter": true,
        "insertSpaceAfterConstructor": false,
        "insertSpaceAfterSemicolonInForStatements": true,
        "insertSpaceBeforeAndAfterBinaryOperators": true,
        "insertSpaceAfterKeywordsInControlFlowStatements": true,
        "insertSpaceAfterFunctionKeywordForAnonymousFunctions": true,
        "insertSpaceBeforeFunctionParenthesis": false,
        "insertSpaceAfterOpeningAndBeforeClosingNonemptyParenthesis": false,
        "insertSpaceAfterOpeningAndBeforeClosingNonemptyBrackets": false,
        "insertSpaceAfterOpeningAndBeforeClosingNonemptyBraces": true,
        "insertSpaceAfterOpeningAndBeforeClosingTemplateStringBraces": false,
        "insertSpaceAfterOpeningAndBeforeClosingJsxExpressionBraces": false,
        "insertSpaceAfterTypeAssertion": false,
        "placeOpenBraceOnNewLineForFunctions": false,
        "placeOpenBraceOnNewLineForControlBlocks": false
    },
    "preferences": {
        "quotePreference": "single",
        "importModuleSpecifierPreference": "non-relative",
        "allowTextChangesInNewFiles": true,
        "providePrefixAndSuffixTextForRename": true,
        "allowRenameOfImportPath": true
    }
}
[Trace  - 10:53:31 AM] Response received: configure (42). Request took 6795 ms. Success: true 

We make a global configure request to ensure that any edited files have the expected configuration for settings like quotes (as we do not know which files are going to be touched before hand).

You should see the file rename dialog taking a long time to show up in VS Code. I don't know where this delay actually shows up on the tsserver as the logs show that the configure request itself is pretty quick.

[sheetalkamat]

Looked a little bit into this. From tsserver point of view neither configure nor getEditsForRename take long..

Perf 2120 [12:2:0.935] 33::configure: async elapsed time (in milliseconds) 0.4259
Perf 2122 [12:2:1.439] 34::getEditsForFileRename: elapsed time (in milliseconds) 502.5104

Its the updateOpen request before this that needs to process opening and closing of the file that's renamed (It is done only once but it does take some time since its a big project)

Info 2101 [12:1:53.912] Starting updateGraphWorker: Project: c:/github/vscode/src/tsconfig.json
Info 2102 [12:2:0.916] Finishing updateGraphWorker: Project: c:/github/vscode/src/tsconfig.json Version: 2 structureChanged: true Elapsed: 7004ms

[sheetalkamat]

I think we could add another array to updateOpen for rename where we can reuse the parsed source file at least if texts are same? I will experiment with that and post back if that has better results.

[sheetalkamat]

Investigating this further seems like most time is gone in module resolution.. The interesting fact is that the number of files in program (2172) > the limit of files(256) for which we will iterate through each resolution and invalidate the only changed resolution..

For initial program::
Info 4430 [14:37:51.152] ResolveModule time: 5.76s

For program with rename on FS for codeActionRenamed::
Info 6754 [14:38:15.17] ResolveModule time: 4.53s        

Complete time information for rename::
Info 6742 [14:38:15.17] Files:                                                                                2172
Info 6743 [14:38:15.17] Lines:                                                                              688383
Info 6744 [14:38:15.17] Nodes:                                                                             3395193
Info 6745 [14:38:15.17] Identifiers:                                                                       1152337
Info 6746 [14:38:15.17] Symbols:                                                                            401143
Info 6747 [14:38:15.17] Types:                                                                                  76
Info 6748 [14:38:15.17] Memory used:                                                                       742979K
Info 6749 [14:38:15.17] Assignability cache size:                                                                0
Info 6750 [14:38:15.17] Identity cache size:                                                                     0
Info 6751 [14:38:15.17] Subtype cache size:                                                                      0
Info 6752 [14:38:15.17] Strict subtype cache size:                                                               0
Info 6753 [14:38:15.17] ResolveTypeReference time:                                                           0.10s
Info 6754 [14:38:15.17] ResolveModule time:                                                                  4.53s
Info 6755 [14:38:15.17] Parse time:                                                                          0.00s
Info 6756 [14:38:15.17] Parse c:/github/vscode/src/vs/editor/contrib/codeAction/codeActionRenamed.ts time:   0.00s
Info 6757 [14:38:15.17] Program time:                                                                        5.18s
Info 6758 [14:38:15.17] Bind time:                                                                           0.00s
Info 6759 [14:38:15.17] Total time:                                                                          5.18s

Looking into how we can optimize resolveModules when program contains large number of files in it.

[sheetalkamat]

While the root cause is discovered, it would need few prototypes to see how best we can handle.

• Try create as many resuse of resolutions as possible so its easier to invalidate. I think this could make life significantly efficient..
• keep track of moduleName folders timestamp to invalidate when number of files are large.. (would work well for node_modules but not so much for classic resolution.. If we could do this we wouldn't need to discard resolutions between two creations..