UpdateProjectIfDirty is slow on large projects

[dbaeumer]

🔎 Search Terms

UpdateProjectIfDirty language server slow

🕗 Version & Regression Information

• tested the version that ships with VS Code

⏯ Playground Link

No response

💻 Code

Steps to reproduce:

• clone VS Code (https://github.com/microsoft/vscode.git)
• npm install
• open VS Code on the vscode repository
• open file task.constribution.ts
• open the TS server log
• add a new line to _ignoreEventForUpdateRunningTasksCount

Observe: updateGraphWorker takes roughly 300ms on my machine

I took a performance trace and a lot of time is spent in GC and getNormalizedAbsolutePath. I added a simply unbound cache to the method like

const pathCache = new Map();
function getNormalizedAbsolutePath(fileName, currentDirectory) {
  let cache = pathCache.get(currentDirectory);
  if (cache === undefined) {
    cache = new Map();
    pathCache.set(currentDirectory, cache);
  }
  let normalized = cache.get(fileName);
  if (normalized === undefined) {
    normalized = getPathFromPathComponents(getNormalizedPathComponents(fileName, currentDirectory));
    cache.set(fileName, normalized);
  }
  return normalized;
}

which cuts the time for updateGraphWorker in half. However there are still some GCs going on and a lot of time is now spent in verifyCompilerOptions / getNormalizedPathComponents.

🙁 Actual behavior

Takes 300ms to update on key stroke

🙂 Expected behavior

Adding a new line should be even in large project only cost a couple of ms :-)

Additional information about the issue

No response

[dbaeumer]

Doing a comparable cache in getNormalizedPathComponents brings the time down to 75ms.

vscode-profile-2024-11-28-09-36-24.cpuprofile
vscode-profile-2024-11-28-12-42-42.cpuprofile
vscode-profile-2024-11-28-15-29-10.cpuprofile

Here are also some of the CPU profiles I captured.

[DanielRosenwasser]

This might make things a bit easier to iterate on.

git clone https://github.com/microsoft/vscode
cd vscode

npm ci --ignore-scripts
npm install @typescript/server-replay --no-save --ignore-scripts

cat > replay-script.txt << EOF
{"seq": 1, "type": "request", "command": "updateOpen", "arguments": { "changedFiles": [],"closedFiles":[],"openFiles":[{"file":"@PROJECT_ROOT@/src/vs/workbench/contrib/tasks/browser/task.contribution.ts","projectRootPath":"@PROJECT_ROOT@"}]} }
{"seq": 2, "type": "request", "command": "updateOpen", "arguments": { "changedFiles": [{ "fileName": "@PROJECT_ROOT@/src/vs/workbench/contrib/tasks/browser/task.contribution.ts", "textChanges": [{ "newText": "\n\t\t", "start": { "line": 146, "offset": 78 }, "end": { "line": 146, "offset": 78 } }] }], "closedFiles": [], "openFiles": [] } }
{"seq": 3, "type": "request", "command": "geterr", "arguments": { "delay": 0, "files": [ { "file": "@PROJECT_ROOT@/src/vs/workbench/contrib/tasks/browser/task.contribution.ts"} ] } }
EOF

npx tsreplay ./ replay-script.txt ./node_modules/typescript/lib/tsserver.js --logDir ./

[DanielRosenwasser]

@dbaeumer what platform have you experienced this on? On a Linux Codespace, I'm seeing something like 80ms. I'm guessing you might be hitting this on Windows though.

[dbaeumer]

@DanielRosenwasser I was hitting this on WSL on my laptop. But even 80ms is a lot for a space in a file. When I looked at the code I was under the impression that most of the things that are done around path computations are 'unnecessary'.

[DanielRosenwasser]

Just to keep you updated, @andrewbranch will be looking into this.

[andrewbranch]

I get 95ms on WSL on a dev box. Should the difference between a dev box and your laptop be 3x+? @dbaeumer can you send a TS Server log?

[dbaeumer]

I can produce a server log. But even 95 ms is IMO a lot considering that most of the work is around normalizing paths that are already normalized.

[dbaeumer]

Here is a tsserver.log from my laptop running on a power adapter. I see times between 170 and 300 ms.

tsserver.zip

[DanielRosenwasser]

Thanks, we'll take a look!

Just to test things out, #60754 (comment) and #60755 (comment) each have a build you can try out. Can you give us a sense of if either of these fix the issue on your side? If you can profile while running to give us a sense of where the remaining major work is, that would be helpful.

[dbaeumer]

Times for build 60754 were between 78 - 150 ms with server plugins enabled.
Times for build 60755 were between 66 - 109 ms with server plugins enabled.

[DanielRosenwasser]

@dbaeumer great! Can you let us know how the two fixes combine? I've readied a build over at #60800 (comment)

[DanielRosenwasser]

It would also be helpful to see if the latest changes at #60755 (comment) still get the same wins overall. Thanks for your patience on this.

[dbaeumer]

@DanielRosenwasser was busy the whole day with a recovery build. Will look into it first thing tomorrow.

[dbaeumer]

Build from #60800 results in times between 65 and 110 ms

[dbaeumer]

For 60755 times were between 172ms and 87ms

Would there be any way for me to automate this so that I can run something in a loop. I am wondering because JIT might have some impact on this as well.

[dbaeumer]

When I debugged / traced this I was wondering if it is necessary to create a new program at all in most cases. I know reusing stuff can be tricky but a lot of changes happen inside code which don't change the structure of a program.

[jakebailey]

Would there be any way for me to automate this so that I can run something in a loop. I am wondering because JIT might have some impact on this as well.

You can use https://www.npmjs.com/package/@typescript/server-harness which is what #60633 (comment) is using under the hood.

When I debugged / traced this I was wondering if it is necessary to create a new program at all in most cases. I know reusing stuff can be tricky but a lot of changes happen inside code which don't change the structure of a program.

That is what Program is doing; it's a snapshot and we carry state between them (Andrew's PR is affecting the perf of that process)