getEditsForFileRename can take a long time on large project

[mjbvz]

From microsoft/vscode#65112

TypeScript Version: 3.2.2

Search Terms:

• getEditsForFileRename
• update imports on rename

Repo

1. Using VS Code
2. With "typescript.updateImportsOnFileMove.enabled": "prompt" set
3. Open VS Code codebase
4. Open src/vs/base/common/paging.ts
5. Wait for js/ts intellisense to load
6. Rename the file

Bug:
It takes a long time before the update imports prompt is shown. I've attached to tsserver log (the name name was newPaging): tsserver.log.zip

Looks like there are two long running ops. Handling the project structure change:

Info 2083 [13:54:12.450] DirectoryWatcher:: Triggered with /Users/matb/projects/vscode/src/vs/base/common/paging.ts :: WatchInfo: /Users/matb/projects/vscode/src/vs 1 Project: /Users/matb/projects/vscode/src/tsconfig.json WatchType: Wild card directory
Info 2084 [13:54:12.452] Scheduled: /Users/matb/projects/vscode/src/tsconfig.json, Cancelled earlier one
Info 2085 [13:54:12.452] Scheduled: *ensureProjectForOpenFiles*, Cancelled earlier one
Info 2086 [13:54:12.452] Elapsed:: 2ms DirectoryWatcher:: Triggered with /Users/matb/projects/vscode/src/vs/base/common/paging.ts :: WatchInfo: /Users/matb/projects/vscode/src/vs 1 Project: /Users/matb/projects/vscode/src/tsconfig.json WatchType: Wild card directory
Info 2087 [13:54:12.452] DirectoryWatcher:: Triggered with /Users/matb/projects/vscode/src/vs/base/common/newPaging.ts :: WatchInfo: /Users/matb/projects/vscode/src/vs 1 Project: /Users/matb/projects/vscode/src/tsconfig.json WatchType: Wild card directory
Info 2088 [13:54:12.452] Scheduled: /Users/matb/projects/vscode/src/tsconfig.json, Cancelled earlier one
Info 2089 [13:54:12.453] Scheduled: *ensureProjectForOpenFiles*, Cancelled earlier one
Info 2090 [13:54:12.453] Elapsed:: 1ms DirectoryWatcher:: Triggered with /Users/matb/projects/vscode/src/vs/base/common/newPaging.ts :: WatchInfo: /Users/matb/projects/vscode/src/vs 1 Project: /Users/matb/projects/vscode/src/tsconfig.json WatchType: Wild card directory
Info 2091 [13:54:12.453] DirectoryWatcher:: Triggered with /Users/matb/projects/vscode/src/vs/base/common/paging.ts :: WatchInfo: /Users/matb/projects/vscode/src/vs 1 Project: /Users/matb/projects/vscode/src/tsconfig.json WatchType: Directory of Failed lookup locations in module resolution
Info 2092 [13:54:12.453] Elapsed:: 0ms DirectoryWatcher:: Triggered with /Users/matb/projects/vscode/src/vs/base/common/paging.ts :: WatchInfo: /Users/matb/projects/vscode/src/vs 1 Project: /Users/matb/projects/vscode/src/tsconfig.json WatchType: Directory of Failed lookup locations in module resolution
Info 2093 [13:54:12.453] DirectoryWatcher:: Triggered with /Users/matb/projects/vscode/src/vs/base/common/newPaging.ts :: WatchInfo: /Users/matb/projects/vscode/src/vs 1 Project: /Users/matb/projects/vscode/src/tsconfig.json WatchType: Directory of Failed lookup locations in module resolution
Info 2094 [13:54:12.453] Elapsed:: 0ms DirectoryWatcher:: Triggered with /Users/matb/projects/vscode/src/vs/base/common/newPaging.ts :: WatchInfo: /Users/matb/projects/vscode/src/vs 1 Project: /Users/matb/projects/vscode/src/tsconfig.json WatchType: Directory of Failed lookup locations in module resolution
Info 2095 [13:54:12.503] request:
    {"seq":41,"type":"request","command":"open","arguments":{"file":"/Users/matb/projects/vscode/src/vs/base/common/newPaging.ts","fileContent":"/*---------------------------------------------------------------------------------------------\n *  Copyright (c) Microsoft Corporation. All rights reserved.\n *  Licensed under the MIT License. See License.txt in the project root for license information.\n *--------------------------------------------------------------------------------------------*/\n\nimport { isArray } from 'vs/base/common/types';\nimport { CancellationToken, CancellationTokenSource } from 'vs/base/common/cancellation';\nimport { canceled } from 'vs/base/common/errors';\nimport { range } from 'vs/base/common/arrays';\n\n/**\n * A Pager is a stateless abstraction over a paged collection.\n */\nexport interface IPager<T> {\n\tfirstPage: T[];\n\ttotal: number;\n\tpageSize: number;\n\tgetPage(pageIndex: number, cancellationToken: CancellationToken): Promise<T[]>;\n}\n\ninterface IPage<T> {\n\tisResolved: boolean;\n\tpromise: Promise<void> | null;\n\tcts: CancellationTokenSource | null;\n\tpromiseIndexes: Set<number>;\n\telements: T[];\n}\n\nfunction createPage<T>(elements?: T[]): IPage<T> {\n\treturn {\n\t\tisResolved: !!elements,\n\t\tpromise: null,\n\t\tcts: null,\n\t\tpromiseIndexes: new Set<number>(),\n\t\telements: elements || []\n\t};\n}\n\n/**\n * A PagedModel is a stateful model over an abstracted paged collection.\n */\nexport interface IPagedModel<T> {\n\tlength: number;\n\tisResolved(index: number): boolean;\n\tget(index: number): T;\n\tresolve(index: number, cancellationToken: CancellationToken): Promise<T>;\n}\n\nexport function singlePagePager<T>(elements: T[]): IPager<T> {\n\treturn {\n\t\tfirstPage: elements,\n\t\ttotal: elements.length,\n\t\tpageSize: elements.length,\n\t\tgetPage: (pageIndex: number, cancellationToken: CancellationToken): Promise<T[]> => {\n\t\t\treturn Promise.resolve(elements);\n\t\t}\n\t};\n}\n\nexport class PagedModel<T> implements IPagedModel<T> {\n\n\tprivate pager: IPager<T>;\n\tprivate pages: IPage<T>[] = [];\n\n\tget length(): number { return this.pager.total; }\n\n\tconstructor(arg: IPager<T> | T[]) {\n\t\tthis.pager = isArray(arg) ? singlePagePager<T>(arg) : arg;\n\n\t\tconst totalPages = Math.ceil(this.pager.total / this.pager.pageSize);\n\n\t\tthis.pages = [\n\t\t\tcreatePage(this.pager.firstPage.slice()),\n\t\t\t...range(totalPages - 1).map(() => createPage<T>())\n\t\t];\n\t}\n\n\tisResolved(index: number): boolean {\n\t\tconst pageIndex = Math.floor(index / this.pager.pageSize);\n\t\tconst page = this.pages[pageIndex];\n\n\t\treturn !!page.isResolved;\n\t}\n\n\tget(index: number): T {\n\t\tconst pageIndex = Math.floor(index / this.pager.pageSize);\n\t\tconst indexInPage = index % this.pager.pageSize;\n\t\tconst page = this.pages[pageIndex];\n\n\t\treturn page.elements[indexInPage];\n\t}\n\n\tresolve(index: number, cancellationToken: CancellationToken): Promise<T> {\n\t\tif (cancellationToken.isCancellationRequested) {\n\t\t\treturn Promise.reject(canceled());\n\t\t}\n\n\t\tconst pageIndex = Math.floor(index / this.pager.pageSize);\n\t\tconst indexInPage = index % this.pager.pageSize;\n\t\tconst page = this.pages[pageIndex];\n\n\t\tif (page.isResolved) {\n\t\t\treturn Promise.resolve(page.elements[indexInPage]);\n\t\t}\n\n\t\tif (!page.promise) {\n\t\t\tpage.cts = new CancellationTokenSource();\n\t\t\tpage.promise = this.pager.getPage(pageIndex, page.cts.token)\n\t\t\t\t.then(elements => {\n\t\t\t\t\tpage.elements = elements;\n\t\t\t\t\tpage.isResolved = true;\n\t\t\t\t\tpage.promise = null;\n\t\t\t\t\tpage.cts = null;\n\t\t\t\t}, err => {\n\t\t\t\t\tpage.isResolved = false;\n\t\t\t\t\tpage.promise = null;\n\t\t\t\t\tpage.cts = null;\n\t\t\t\t\treturn Promise.reject(err);\n\t\t\t\t});\n\t\t}\n\n\t\tcancellationToken.onCancellationRequested(() => {\n\t\t\tif (!page.cts) {\n\t\t\t\treturn;\n\t\t\t}\n\n\t\t\tpage.promiseIndexes.delete(index);\n\n\t\t\tif (page.promiseIndexes.size === 0) {\n\t\t\t\tpage.cts.cancel();\n\t\t\t}\n\t\t});\n\n\t\tpage.promiseIndexes.add(index);\n\n\t\treturn page.promise.then(() => page.elements[indexInPage]);\n\t}\n}\n\nexport class DelayedPagedModel<T> implements IPagedModel<T> {\n\n\tget length(): number { return this.model.length; }\n\n\tconstructor(private model: IPagedModel<T>, private timeout: number = 500) { }\n\n\tisResolved(index: number): boolean {\n\t\treturn this.model.isResolved(index);\n\t}\n\n\tget(index: number): T {\n\t\treturn this.model.get(index);\n\t}\n\n\tresolve(index: number, cancellationToken: CancellationToken): Promise<T> {\n\t\treturn new Promise((c, e) => {\n\t\t\tif (cancellationToken.isCancellationRequested) {\n\t\t\t\treturn e(canceled());\n\t\t\t}\n\n\t\t\tconst timer = setTimeout(() => {\n\t\t\t\tif (cancellationToken.isCancellationRequested) {\n\t\t\t\t\treturn e(canceled());\n\t\t\t\t}\n\n\t\t\t\ttimeoutCancellation.dispose();\n\t\t\t\tthis.model.resolve(index, cancellationToken).then(c, e);\n\t\t\t}, this.timeout);\n\n\t\t\tconst timeoutCancellation = cancellationToken.onCancellationRequested(() => {\n\t\t\t\tclearTimeout(timer);\n\t\t\t\ttimeoutCancellation.dispose();\n\t\t\t\te(canceled());\n\t\t\t});\n\t\t});\n\t}\n}\n\n/**\n * Similar to array.map, `mapPager` lets you map the elements of an\n * abstract paged collection to another type.\n */\nexport function mapPager<T, R>(pager: IPager<T>, fn: (t: T) => R): IPager<R> {\n\treturn {\n\t\tfirstPage: pager.firstPage.map(fn),\n\t\ttotal: pager.total,\n\t\tpageSize: pager.pageSize,\n\t\tgetPage: (pageIndex, token) => pager.getPage(pageIndex, token).then(r => r.map(fn))\n\t};\n}\n\n/**\n * Merges two pagers.\n */\nexport function mergePagers<T>(one: IPager<T>, other: IPager<T>): IPager<T> {\n\treturn {\n\t\tfirstPage: [...one.firstPage, ...other.firstPage],\n\t\ttotal: one.total + other.total,\n\t\tpageSize: one.pageSize + other.pageSize,\n\t\tgetPage(pageIndex: number, token): Promise<T[]> {\n\t\t\treturn Promise.all([one.getPage(pageIndex, token), other.getPage(pageIndex, token)])\n\t\t\t\t.then(([onePage, otherPage]) => [...onePage, ...otherPage]);\n\t\t}\n\t};\n}","scriptKindName":"TS","projectRootPath":"/Users/matb/projects/vscode"}}
Info 2096 [13:54:12.503] Search path: /Users/matb/projects/vscode/src/vs/base/common
Info 2097 [13:54:12.504] ConfigFilePresence:: Current Watches: :: File: /Users/matb/projects/vscode/src/vs/base/common/tsconfig.json Currently impacted open files: RootsOfInferredProjects:  OtherOpenFiles: /Users/matb/projects/vscode/src/vs/base/common/newPaging.ts Status: File added to open files impacted by this config file
Info 2098 [13:54:12.504] ConfigFilePresence:: Current Watches: :: File: /Users/matb/projects/vscode/src/vs/base/common/jsconfig.json Currently impacted open files: RootsOfInferredProjects:  OtherOpenFiles: /Users/matb/projects/vscode/src/vs/base/common/newPaging.ts Status: File added to open files impacted by this config file
Info 2099 [13:54:12.508] ConfigFilePresence:: Current Watches: :: File: /Users/matb/projects/vscode/src/vs/base/tsconfig.json Currently impacted open files: RootsOfInferredProjects:  OtherOpenFiles: /Users/matb/projects/vscode/src/vs/base/common/newPaging.ts Status: File added to open files impacted by this config file
Info 2100 [13:54:12.508] ConfigFilePresence:: Current Watches: :: File: /Users/matb/projects/vscode/src/vs/base/jsconfig.json Currently impacted open files: RootsOfInferredProjects:  OtherOpenFiles: /Users/matb/projects/vscode/src/vs/base/common/newPaging.ts Status: File added to open files impacted by this config file
Info 2101 [13:54:12.508] ConfigFilePresence:: Current Watches: :: File: /Users/matb/projects/vscode/src/vs/tsconfig.json Currently impacted open files: RootsOfInferredProjects:  OtherOpenFiles: /Users/matb/projects/vscode/src/vs/editor/contrib/codeAction/lightBulbWidget.ts,/Users/matb/projects/vscode/src/vs/editor/contrib/codeAction/codeActionCommands.ts,/Users/matb/projects/vscode/src/vs/editor/contrib/codeAction/test/codeActionModel.test.ts,/Users/matb/projects/vscode/src/vs/base/common/newPaging.ts Status: File added to open files impacted by this config file
Info 2102 [13:54:12.508] ConfigFilePresence:: Current Watches: :: File: /Users/matb/projects/vscode/src/vs/jsconfig.json Currently impacted open files: RootsOfInferredProjects:  OtherOpenFiles: /Users/matb/projects/vscode/src/vs/editor/contrib/codeAction/lightBulbWidget.ts,/Users/matb/projects/vscode/src/vs/editor/contrib/codeAction/codeActionCommands.ts,/Users/matb/projects/vscode/src/vs/editor/contrib/codeAction/test/codeActionModel.test.ts,/Users/matb/projects/vscode/src/vs/base/common/newPaging.ts Status: File added to open files impacted by this config file
Info 2103 [13:54:12.509] ConfigFilePresence:: Current Watches: Config file for the program:: File: /Users/matb/projects/vscode/src/tsconfig.json Currently impacted open files: RootsOfInferredProjects:  OtherOpenFiles: /Users/matb/projects/vscode/src/vs/editor/contrib/codeAction/lightBulbWidget.ts,/Users/matb/projects/vscode/src/vs/editor/contrib/codeAction/codeActionCommands.ts,/Users/matb/projects/vscode/src/vs/editor/contrib/codeAction/test/codeActionModel.test.ts,/Users/matb/projects/vscode/src/vs/base/common/newPaging.ts Status: File added to open files impacted by this config file
Info 2104 [13:54:12.509] For info: /Users/matb/projects/vscode/src/vs/base/common/newPaging.ts :: Config file name: /Users/matb/projects/vscode/src/tsconfig.json
Info 2105 [13:54:12.645] Starting updateGraphWorker: Project: /Users/matb/projects/vscode/src/tsconfig.json
Info 2106 [13:54:18.532] Finishing updateGraphWorker: Project: /Users/matb/projects/vscode/src/tsconfig.json Version: 5 structureChanged: true Elapsed: 5887ms
Info 2107 [13:54:18.536] Project '/Users/matb/projects/vscode/src/tsconfig.json' (Configured) 0
Info 2107 [13:54:18.537] 	Files (1772)

And the getEditsForFileRename call:

    {"seq":43,"type":"request","command":"getEditsForFileRename","arguments":{"file":"/Users/matb/projects/vscode/src/vs/base/common/newPaging.ts","oldFilePath":"/Users/matb/projects/vscode/src/vs/base/common/paging.ts","newFilePath":"/Users/matb/projects/vscode/src/vs/base/common/newPaging.ts"}}
Perf 2118 [13:54:24.595] 43::getEditsForFileRename: elapsed time (in milliseconds) 6049.1891
Info 2119 [13:54:24.595] response:
    {"seq":0,"type":"response","command":"getEditsForFileRename","request_seq":43,"success":true,"body":[{"fileName":"/Users/matb/projects/vscode/src/vs/base/browser/ui/list/listPaging.ts","textChanges":[{"start":{"line":11,"offset":30},"end":{"line":11,"offset":51},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/base/test/common/paging.test.ts","textChanges":[{"start":{"line":7,"offset":37},"end":{"line":7,"offset":58},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/platform/extensionManagement/common/extensionManagement.ts","textChanges":[{"start":{"line":8,"offset":25},"end":{"line":8,"offset":46},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/platform/extensionManagement/node/extensionGalleryService.ts","textChanges":[{"start":{"line":15,"offset":25},"end":{"line":15,"offset":46},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/workbench/parts/extensions/common/extensions.ts","textChanges":[{"start":{"line":9,"offset":25},"end":{"line":9,"offset":46},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/workbench/parts/extensions/electron-browser/extensionsActions.ts","textChanges":[{"start":{"line":39,"offset":29},"end":{"line":39,"offset":50},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/workbench/parts/extensions/node/extensionsWorkbenchService.ts","textChanges":[{"start":{"line":14,"offset":52},"end":{"line":14,"offset":73},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/workbench/parts/extensions/electron-browser/extensionsViews.ts","textChanges":[{"start":{"line":11,"offset":69},"end":{"line":11,"offset":90},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/workbench/parts/extensions/test/electron-browser/extensionsActions.test.ts","textChanges":[{"start":{"line":24,"offset":25},"end":{"line":24,"offset":46},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/workbench/parts/extensions/test/electron-browser/extensionsTipsService.test.ts","textChanges":[{"start":{"line":33,"offset":25},"end":{"line":33,"offset":46},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/workbench/parts/extensions/test/electron-browser/extensionsViews.test.ts","textChanges":[{"start":{"line":24,"offset":25},"end":{"line":24,"offset":46},"newText":"vs/base/common/newPaging"}]},{"fileName":"/Users/matb/projects/vscode/src/vs/workbench/parts/extensions/test/electron-browser/extensionsWorkbenchService.test.ts","textChanges":[{"start":{"line":25,"offset":25},"end":{"line":25,"offset":46},"newText":"vs/base/common/newPaging"}]}]}

[mjbvz]

Quick API usage question: do we (VS Code) need to actually open the new file (newPaging.ts in this case) on TypeScript before we call getEditsForFileRename? Not sure if that would fix the issue but I want to double check this

[mjbvz]

@DanielRosenwasser Can we investigate this for TS 3.3.5 or for 3.4? The delay currently causes a poor user experience, especially in large projects like VS Code

[sheetalkamat]

@mjbvz The quick look at the log shows that the newPaging.ts was open before calling getEditsForFileRename. I also noticed you had two configured projects open instead of just the paging.ts one. getEditsForFileRename will go through all projects to find if it needs any edits.
On my machine with just paging.ts open doing rename was about 2s and with all the files that you had open, (with 2 config projects open) it took 3s so the other project definitely changes the numbers as expected.

I haven't look at the code in detail for this so now looking to see how things can be improved.

[sheetalkamat]

https://github.com/Microsoft/TypeScript/blob/master/src/services/getEditsForFileRename.ts#L216 this seems to be the culprit with 4727ms of 5671ms spent to check if file exists on old file.