[PerfSampleError]

[vscodenpa]

[PerfSampleError] by <<renderer>> in createImageBitmap
at createImageBitmap
at createImageBitmap in vscode-file://vscode-app//node_modules.asar/xterm-addon-image/lib/xterm-addon-image.js:2:32040
at _createPlaceHolder in vscode-file://vscode-app//node_modules.asar/xterm-addon-image/lib/xterm-addon-image.js:2:36594
at _open in vscode-file://vscode-app//node_modules.asar/xterm-addon-image/lib/xterm-addon-image.js:2:35610
at s in vscode-file://vscode-app//node_modules.asar/xterm-addon-image/lib/xterm-addon-image.js:2:31218
at activate in vscode-file://vscode-app//node_modules.asar/xterm-addon-image/lib/xterm-addon-image.js:2:50158
at loadAddon in vscode-file://vscode-app//node_modules.asar/xterm/lib/xterm.js:1:247802
at loadAddon in vscode-file://vscode-app//node_modules.asar/xterm/lib/xterm.js:1:277222
at lb in out/vs/workbench/workbench.desktop.main.js:1836:18083

Go to Errors Site

[Tyriar]

@jerch FYI I think this means there was a case where this took >10% of a 5 second period (so >500ms) of time that was profiled:

vscode/src/vs/workbench/contrib/performance/electron-sandbox/rendererAutoProfiler.ts

Line 78 in 6ea4677

const profile = await nativeHostService.profileRenderer(sessionId, 5000);

vscode/src/vs/platform/profiling/electron-sandbox/profileAnalysisWorker.ts

Lines 31 to 37 in 6ea4677

	if (samples.length === 0 || samples[0].percentage < 10) {
	// ignore this profile because 90% of the time is spent inside "special" frames
	// like idle, GC, or program
	return { kind: ProfilingOutput.Irrelevant, samples: [] };
	}
	return { kind: ProfilingOutput.Interesting, samples };

I guess the image was just really large? Full screen window + tall terminal + 4k monitor?

I'm seeing this happened 146 time on 127 machines for the latest stable, so over about 6 days.

[Tyriar]

Not sure how actionable this is.

[jerch]

I guess the image was just really large? Full screen window + tall terminal + 4k monitor?

Well one of my bigger local test images is 6000x4000px and accounts for ~25MB sixel-encoded - and the overall throughput from term.write to the image finally showing up is ~40MB/s. So a 4k screenshot would get into the +100ms realms for sure.

Still this should not happen during normal image decoding, as all the decoders work chunkwise and return control flow to the sequence parser after one chunk has been processed. Could it be, that the test inserts all the bytes of one big image into one term.write call? Because I dont split chunks further, they just get processed as they flow in assuming that any data provider for term.write already has the data split in chunks by other means (the PTY typically splits data in 4k to 65k byte chunks).

[Tyriar]

Could it be, that the test inserts all the bytes of one big image into one term.write call?

If it was write that wouldn't explain why createImageBitmap is the expensive call though 🤔. I'm going to close this as it's complaining about a browser API call taking too much time and we don't have enough info.

[jerch]

Ah ok, I did not know that it only means the runtime of that call.

Is the measured time here raw runtime of that call (from call to resolve), or mainthread blocking time? Because the latter should not happen due to being an async call, ofc the first can happen, if the image is quite big.

[Tyriar]

I think I misinterpreted it initially and it means that there was 500ms+ of blocking time (10% of 5 seconds) and the biggest consumer of that (top bottom up profile entry) was createImageBitmap.

[Tyriar]

This is relatively new though and something might be going wrong with the measurement. The async thing in particular confuses me.

[jerch]

500ms+ of blocking time

Eww, well thats not good. Sadly I dont understand the line numbers the stacktrace gives, so idk which code path ran into that bad timing. From the callback at least it seems to be triggered right from initial addon startup, which makes me wonder, how thats even possible? Wouldn't the terminal (+addon) be spawned much earlier in terms of event loop invocations, before any real data arrives at it?

[Tyriar]

Wouldn't the terminal (+addon) be spawned much earlier in terms of event loop invocations, before any real data arrives at it?

I think you're on to something here. The terminal is started after the "restored" phase which is probably when the perf sample stuff kicks in. There could be an unbounded amount of terminals being restored, across multiple windows (some could be on the same CPU if that matters), each one could have 4 canvases being created. Maybe createImageBitmap, while small, just happens to be the longest call out of all of them?

[jerch]

Hmm, sounds plausible. It still makes me wonder, even if it had to restore like 20+ terminals at once, why would createImageBitmap that long initially?

Ah well, no clue - I'd say if its not a pressing issue we should track that in the xterm.js repo once the addon got added. Maybe some of my init path stuff creates a high workload, and we are able to defer it somehow.

[jerch]

Might have found the issue taking pretty long during startup - seems thats related to the on-the-fly placeholder generation, which currently happens during addon init. Should be able to defer that as well.

[jerch]

jerch/xterm-addon-image#56 should remove most of the addon init burden, its lit. down to a few variable assigments. Everything else got deferred.

Note that this wont help with blocking time, if there is a rather big single term.write(really_big_image_data) call going on somewhere. If thats an issue, then we might have to look at the incoming write buffer logic of xtermjs, and whether there should be a split logic for overly big chunks (cannot really orchestrate that from deep within parser handlers).