Zombie extension hosts running at 100%

[jrieken]

• over the last week I have seen zombie processes running at full CPU load
• when trying to debug them (via SIGUSR1) they die
• @deepak1556 analysed a crash dump and sees that this is because the EH is already in the process of shutting down
• the previous point matches the observation that no window reports its EH as having crashed

[deepak1556]

Can you take a process sample from the OS activity monitor, I hope the native stack can give a clue to what is happening.

[jrieken]

Just happening. This is the command line of such an EH

99701   ??  R    299:41.47 /Applications/Visual Studio Code - Insiders.app/Contents/Frameworks/Code - Insiders Helper (Plugin).app/Contents/MacOS/Code - Insiders Helper (Plugin) --type=utility --utility-sub-type=node.mojom.NodeService --lang=en-GB --service-sandbox-type=none --dns-result-order=ipv4first --inspect-port=0 --user-data-dir=/Users/jrieken/Library/Application Support/Code - Insiders --standard-schemes=vscode-webview,vscode-file --enable-sandbox --secure-schemes=vscode-webview,vscode-file --bypasscsp-schemes --cors-schemes=vscode-webview,vscode-file --fetch-schemes=vscode-webview,vscode-file --service-worker-schemes=vscode-webview --streaming-schemes --shared-files --field-trial-handle=1718379636,r,8003835085444679389,18150943907601750289,262144 --disable-features=CalculateNativeWinOcclusion,SpareRendererForSitePerProcess
99704   ??  S      0:04.19 /Applications/Visual Studio Code - Insiders.app/Contents/Frameworks/Code - Insiders Helper (Plugin).app/Contents/MacOS/Code - Insiders Helper (Plugin) --ms-enable-electron-run-as-node /Users/jrieken/.vscode-insiders/extensions/kisstkondoros.vscode-codemetrics-1.26.1/dist/server.js --node-ipc --clientProcessId=99701
99706   ??  S      0:03.39 /Applications/Visual Studio Code - Insiders.app/Contents/Frameworks/Code - Insiders Helper (Plugin).app/Contents/MacOS/Code - Insiders Helper (Plugin) --ms-enable-electron-run-as-node /Users/jrieken/.vscode-insiders/extensions/kisstkondoros.vscode-gutter-preview-0.30.0/dist/server.js --node-ipc --clientProcessId=99701
99750   ??  S      0:01.17 /Applications/Visual Studio Code - Insiders.app/Contents/Frameworks/Code - Insiders Helper (Plugin).app/Contents/MacOS/Code - Insiders Helper (Plugin) --ms-enable-electron-run-as-node /Users/jrieken/.vscode-insiders/extensions/ms-vscode.anycode-0.0.72/dist/anycode.server.node.js --node-ipc --clientProcessId=99701
16791 s034  S+     0:00.00 grep 99701

[jrieken]

@deepak1556 This the process sample EH-spin-sample.txt

[jrieken]

@connor4312 Not sure about the --inspect-port=0 part. Does this mean we run the EH under development or not?

[connor4312]

It looks like we set that for all local EH process launches. Just having inspect-port doesn't put the process in debug mode.

What you can do is use the "Debug: Attach to Node.js Process" command and select that process. This will fail, since the debugger won't then know what port it's listening on (if --inspect-port isn't given in the args, it always listens on 9229, and js-debug assumes that is what happens). But, then you can find it. AFter doing so you could grab a performance profile using the edge/chrome devtools on edge://inspect, or by attaching to that using an attach-type launch config VS Code and using the "take performance profile" command -- if the spin sample you recorded above isn't enough for Deepak to figure out what's going on.

[jrieken]

What you can do is use the "Debug: Attach to Node.js Process" command and select that process.

Does that use SIGUSR1? Asking cos I have tried that first and sending the signal kills the process. From the crash dumps we do know that the process already was shutting down

[deepak1556]

Attaching the symbolicated sample EH-spin-sample-symbolicated.txt

Going from the top, electron::NodeService::~NodeService() indicates the EH process is already in the shutdown phase and has started to destroy the Node.js environment node::FreeEnvironment(node::Environment*) . At this point, connecting via a debugger is not possible since the agent host will stop receiving connections due to the following check, so we cannot get perf profile from these processes.

Moving further down most of the sample time is spent in node::NodePlatform::DrainTasks which happens before the environment gets deleted, this flushes the pending tasks in the libuv event loop but one thing to note is that entering JS via these tasks is not allowed due to the scope. But there are GC tasks being executed v8::internal::FinalizationRegistryCleanupTask::RunInternal and v8::internal::Heap::CollectGarbage which can enter JS. I think the error calls node::errors::TriggerUncaughtException are from these callsites eventually leading to node::OnFatalError. At this point, I expect the process to abort and the main process should be able to reap the utility process but that is not happening.

There is another data point looking back at the screenshot from #194477 (comment), the zombie EH processes are titled utility-process and not extensionHost in the process explorer. We resolve the pids to respective titles based on a map maintained in the main process, the process explorer gets it periodically via the following ipc and the utility process related values are populated from here. We default to utility-process when the pid map no longer has an entry for the process which can only happen when onDidExitOrCrashOrKill got invoked which inturn suggests that the main process did receive an exit or crash signal from these EH hosts. @jrieken can you check the main process logs next time if it has any of the following entries for the corresponding zombie EH pid to validate this data

• vscode/src/vs/platform/utilityProcess/electron-main/utilityProcess.ts

  Line 310 in e6fb753

  this.log(`received exit event with code ${code}`, Severity.Info);

• vscode/src/vs/platform/utilityProcess/electron-main/utilityProcess.ts

  Line 322 in e6fb753

  this.log(`crashed with code ${details.exitCode} and reason '${details.reason}'`, Severity.Error);

• vscode/src/vs/platform/utilityProcess/electron-main/utilityProcess.ts

  Line 408 in e6fb753

  this.log('successfully killed the process', Severity.Info);

[deepak1556]

I attempted to setup a similar flow based on the stack with base Electron app but the utility process are cleaned up as expected. I can make a change in the destruction phase of the utility process to signal termination of isolate so that tasks which require to enter JS will not do so and I hope that resolves the long running draintask.

I won't be able to make a new insiders build with this change until I am back from vacation but I can provide a custom electron build for local testing with OSS. @jrieken would that help to validate incase you face similar issue with OSS as well ?

[connor4312]

From the crash dumps we do know that the process already was shutting down

Ah, my bad, skimmed over that part. Disregard.

(Yes, it sends SIGUSR1 on unix)

[jrieken]

2023-10-06 10:26:53.084 [info] Extension host with pid 19510 exited with code: 0, signal: unknown.

I am seeing this for PID-19510 which is currently spinning forever. Samples for this one EH-19510.txt

[nzhl]

i think i have the same issue on my mac. It happens from time to time and my workaround is simply killing vscode and then reopen it. But sometimes i don't realize it until my Mac has run out of battery, which can be quite annoying.