Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

getEditsForFileRename can take a long time on large project #29031

Closed
mjbvz opened this issue Dec 14, 2018 · 13 comments
Closed

getEditsForFileRename can take a long time on large project #29031

mjbvz opened this issue Dec 14, 2018 · 13 comments
Assignees
Labels
Bug A bug in TypeScript Domain: Performance Reports of unusually slow behavior Domain: TSServer Issues related to the TSServer Fixed A PR has been merged for this issue

Comments

@mjbvz
Copy link
Contributor

mjbvz commented Dec 14, 2018

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
Copy link
Contributor Author

mjbvz commented Dec 14, 2018

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 mjbvz changed the title getEditsForFileRename getEditsForFileRename can take a long time on large project Dec 14, 2018
@weswigham weswigham added Domain: Performance Reports of unusually slow behavior Domain: TSServer Issues related to the TSServer Bug A bug in TypeScript labels Dec 14, 2018
@mjbvz
Copy link
Contributor Author

mjbvz commented Jan 7, 2019

@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
Copy link
Member

@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
Copy link
Member

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.

@sheetalkamat
Copy link
Member

@DanielRosenwasser Do I need to port the fix somewhere?

@DanielRosenwasser DanielRosenwasser modified the milestones: TypeScript 3.3.1, TypeScript 3.2.5 Jan 9, 2019
@DanielRosenwasser
Copy link
Member

@mjbvz would VS Code adopt 3.2.5?

@mjbvz
Copy link
Contributor Author

mjbvz commented Jan 9, 2019

Sure, depending on when 3.2.5 would ship we could either pick it up by the end of January for VS Code 1.31 or in February for VS Code 1.32

@mjbvz
Copy link
Contributor Author

mjbvz commented Jan 9, 2019

Never mind, misread the version as 3.3.5. No, we do not plan to pick up any more TS 3.2.x releases.

@DanielRosenwasser
Copy link
Member

Then nope, no porting necessary.

@DanielRosenwasser
Copy link
Member

Awesome work Sheetal!

errendir added a commit to errendir/TypeScript that referenced this issue Jan 14, 2019
* origin/master: (1082 commits)
  Fix unneeded cast lints (microsoft#29383)
  Extracted compilerOptions setting to helper function
  Added codefix to enable experimentalDecorators in the user's config file
  Add tests for noLib with <reference lib> and bundling.
  Add tests for noLib with <reference lib>.
  Do not process library reference directives with noLib set.
  emit jsx type arguments
  Allow circular umd-merged-with-augmentation refs to resolve to the module as intended (microsoft#29335)
  Allow nonnull assertions in references (microsoft#29351)
  Accept new baselines
  Add regression tests
  Improve logic that determines when to resolve conditional types
  Update user baselines (microsoft#29336)
  Fix crash (microsoft#29333)
  Exclude JSDoc @extends from 'super()' checks (microsoft#29308)
  Fix existing test
  Verify that completion with new identifier location returns isNewIdentifierLocation: true Fixes microsoft#24009
  Fix the failing test case
  There is no need to check for file presence when trying to rename imports based on file rename Fixes microsoft#29031
  Fix gulp baseline-accept (microsoft#29301)
  ...
@OliverJAsh
Copy link
Contributor

Coming here from microsoft/vscode#65112 via microsoft/vscode#64986. Running TS 3.3.333, this still seems to be an issue. Unfortunately I can't easily share a repro because it's a large project…

@Niaro
Copy link

Niaro commented Apr 27, 2020

@mjbvz Yeap, this is still an issue. In a monorepo it takes a huge amount of time to update affected files.

@mjbvz
Copy link
Contributor Author

mjbvz commented Apr 27, 2020

@Niaro See #30535

If you still see this issue when using TypeScript 3.9+ in your workspace (install this extension to quickly test) please file a new issue with more information about your project

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug A bug in TypeScript Domain: Performance Reports of unusually slow behavior Domain: TSServer Issues related to the TSServer Fixed A PR has been merged for this issue
Projects
None yet
Development

No branches or pull requests

6 participants