Update to 1.82.0, VSCode takes more time to kill processes after quit

[hua03]

Type: Bug

In this video, I quit VSCode at 7 seconds, but it (Dock Icon) was killed at 12 seconds.

2023-09-11.15.15.06.mov

VS Code version: Code 1.82.0 (8b617bd, 2023-09-06T22:09:41.364Z)
OS version: Darwin x64 22.5.0
Modes:

System Info

Item	Value
CPUs	Intel(R) Core(TM) i5-1038NG7 CPU @ 2.00GHz (8 x 2000)
GPU Status	2d_canvas: enabled canvas_oop_rasterization: disabled_off direct_rendering_display_compositor: disabled_off_ok gpu_compositing: enabled multiple_raster_threads: enabled_on opengl: enabled_on rasterization: enabled raw_draw: disabled_off_ok video_decode: enabled video_encode: enabled vulkan: disabled_off webgl: enabled webgl2: enabled webgpu: enabled
Load (avg)	3, 3, 3
Memory (System)	32.00GB (13.43GB free)
Process Argv	--crash-reporter-id 25337f27-0fd6-4ad2-a343-d23e45e01d53
Screen Reader	no
VM	0%

Extensions (2)

Extension	Author (truncated)	Version
astro-vscode	ast	2.3.3
vscode-language-pack-zh-hans	MS-	1.82.2023090609

A/B Experiments

vsliv368cf:30146710
vsreu685:30147344
python383:30185418
vspor879:30202332
vspor708:30202333
vspor363:30204092
vslsvsres303:30308271
vserr242:30382549
pythontb:30283811
vsjup518:30340749
pythonptprofiler:30281270
vshan820:30294714
vstes263:30335439
vscod805cf:30301675
binariesv615:30325510
bridge0708:30335490
bridge0723:30353136
vsaa593:30376534
pythonvs932:30410667
vsclangdc:30486549
c4g48928:30535728
dsvsc012cf:30540253
pynewext54:30695312
azure-dev_surveyone:30548225
vsccc:30803844
2e4cg342:30602488
f6dab269:30613381
2i9eh265:30646982
showlangstatbar:30737416
0bi6i642:30831757
pythonfmttext:30731395
fixshowwlkth:30771522
showindicator:30805244
pythongtdpath:30769146
i26e3531:30792625
pythonnosmt12:30797651
pythonidxptcf:30805731
pythonnoceb:30805159
dsvsc013:30795093
dsvsc014:30804076
diffeditorv1:30821571
dsvsc015:30829745

[jungaretti]

#192753 and #172967 include lots of information about this bug

[deepak1556]

Initial findings:

• Main process is delayed waiting on the shutdownPromise to resolve.
• Delay comes from exiting long running extension host in waitForExit
• Profiling the extension host shows that the Node.js is delayed in its cleanup of exit callbacks at https://github.com/nodejs/node/blob/b45e196bec407c9db30ffe5490bb86be692a1579/src/env.cc#L1180-L1186
• ⚠️ Disabling telemetry resolves the slow shutdown of the extension host "telemetry.telemetryLevel": "off"

@bpasero @lramos15 this is a return of #172967 but we have reliable repro this time. @lramos15 do we run any telemetry network requests from inside the extension host, if so can you point me to the code.

[bpasero]

Great findings 👏 , I am not sure if this is relevant here, but I do have noticed for quite some time now that quitting "Code OSS" (i.e. when I run out of sources and develop) takes a lot longer now to return back to the terminal. I was almost about to file an issue but maybe its the same? Would this repro even out of sources?

[deepak1556]

Yup it repos in out of sources as well as the product builds

[lramos15]

@lramos15 this is a return of #172967 but we have reliable repro this time. @lramos15 do we run any telemetry network requests from inside the extension host, if so can you point me to the code.

Extensions can run telemetry from within the ext host (including built-in ones), but our core telemetry is all proxied over IPC

vscode/src/vs/workbench/api/browser/mainThreadTelemetry.ts

Lines 16 to 17 in f766dc2

	@extHostNamedCustomer(MainContext.MainThreadTelemetry)
	export class MainThreadTelemetry extends Disposable implements MainThreadTelemetryShape {

[deepak1556]

Extensions can run telemetry from within the ext host (including built-in ones)

Where do the network requests for these originate from, do they still get issued from the shared process ? Can you point to this code path as well.

[lramos15]

Where do the network requests for these originate from, do they still get issued from the shared process ? Can you point to this code path as well.

I'm just talking about how each extension can send telemetry by instantiating its own reporter which uses the built-in http node module.

[deepak1556]

Regression started with @vscode/extension-telemetry version bump in ecb0c80, all versions >= 0.8.2 are affected. Bisect revealed the following commit microsoft/vscode-extension-telemetry@c31b67b as the trigger.

Further debugging narrowed it to the following callsite https://github.com/microsoft/vscode-extension-telemetry/blob/80cfe9538a0f1512de3fe8b4a1e1f1e34d9b2efa/src/common/1dsClientFactory.ts#L80-L85 which queues network requests when disposing the telemetry client causing the event loop to be busy.

Currently we have logic in extension host destruction code path to wait for 5s and allow extensions to cleanly dispose themselves before killing the extension host via process.exit, refs

vscode/src/vs/workbench/api/common/extHostExtensionService.ts

Lines 268 to 278 in 1edc9a7

	// Give extensions at most 5 seconds to wrap up any async deactivate, then exit
	Promise.race([timeout(5000), extensionsDeactivated]).finally(() => {
	if (this._hostUtils.pid) {
	this._logService.info(`Extension host with pid ${this._hostUtils.pid} exiting with code ${code}`);
	} else {
	this._logService.info(`Extension host exiting with code ${code}`);
	}
	this._logService.flush();
	this._logService.dispose();
	this._hostUtils.exit(code);
	});

. We are now always hitting this timeout on quitting the application due to the telemetry request flushing.

One thing I found interesting is that, the old applicationinsights package has a nice utility to signal that the process is exiting in their flush API which then stores the data to disk synchronoushly if opted otherwise destorys itself immediately without any IO, refs https://github.com/microsoft/ApplicationInsights-node.js/blob/aaafbfd8ffbc454d4a5c30cda4492891410b9f66/Library/Channel.ts#L80-L88. I couldn't find a similar utility in the 1DS package. Maybe thats what we need to address this issue sanely from the package side. For the short term I suggest to revert the shutdown flushing to avoid impacting application shutdown behavior.

@lramos15 I leave to you to decide the best way forward for this issue.

[justschen]

on m2 pro - speed for close out in the dock is somewhat variable (not sure if this is an issue, it's still faster, but anywhere from 3-4 seconds).

[lramos15]

on m2 pro - speed for close out in the dock is somewhat variable (not sure if this is an issue, it's still faster, but anywhere from 3-4 seconds).

Did you disable all extensions?

[justschen]

correction: works fine in insiders, very quick within 2 seconds of quitting.