Investigate startup performance regression

[bpasero]

It seems that the exploration builds run slower. One theory is that maybe the disabled script streaming has an impact (this was needed to unblock sandbox working on Linux when running out of sources). Should validate if we actually load multiple scripts on startup that could now result in a waterfall without script streaming.

[bpasero]

Does not look so good:

I suggest to see if script streaming enabled on Windows helps.

[deepak1556]

Numbers on my local setup are not bad, although it is not 1:1 same setup as our perf bot since the bot runs the application as a service.

Stable 1.70.0

2343	Code	da76f93349	90e9a697-6490-41bd-a634-3a8dda36c4e41660050399473	NO_standard_start : Active editor is not a text editor
2008	Code	da76f93349	25b69d3a-e6a7-4a20-a43f-52318a06bf591660050427835	standard_start
1931	Code	da76f93349	c6a864db-6f51-4ea1-83d2-fd9acf80a03d1660050456743	standard_start
1962	Code	da76f93349	bff11f60-4f92-4f7a-94e6-1327302eb51e1660050490998	standard_start
1794	Code	da76f93349	f87d602d-7d18-4bbd-b7a0-ab53f31abac11660050519246	standard_start
1925	Code	da76f93349	3cc5e206-467f-43e3-9f1b-1536025a23701660050547070	standard_start
1985	Code	da76f93349	8e9aa434-fec4-4695-8cb5-7f868c5250911660050599940	standard_start

Insiders 1.71.0

2959	Code - Insiders	fe946068ba	4581ba9d-0ce0-423a-96b3-eb0352ec68961660057514331	NO_standard_start : Either cache data is rejected or not created
2178	Code - Insiders	fe946068ba	2de8372d-8419-4364-a18b-0596750fa9421660057554711	standard_start
2110	Code - Insiders	fe946068ba	43e1ba77-5eac-4fef-bedc-029d700be3b01660057583477	standard_start
2016	Code - Insiders	fe946068ba	53c18005-0912-479c-8166-374b3de846a21660057612731	standard_start
2052	Code - Insiders	fe946068ba	6827c41b-c5ea-4117-828a-b60ccc070ffe1660057642634	standard_start
2072	Code - Insiders	fe946068ba	4dc8dd13-2d24-43a6-bb21-f1bac0dda3101660057674277	standard_start
1823	Code - Insiders	fe946068ba	819c84da-4a7c-49a9-a525-a600f2e46b141660057702658	standard_start

[deepak1556]

Also, confirmed that script streaming is enabled in Electron 19 with current Insiders. Chrome trace with script streaming enabled and disabled shows it does not impact workbench load for product builds.

I will add some steps below to collect some relevant traces from the perf bot for further debugging.

[bpasero]

Thanks, just from the numbers it does look like for you 1.71.0 overall executes slower. To drill in we would probably have to check the numbers from the performance editor to see if there is a specific thing.

Btw will also try with my Surface Laptop once I am in the office and once it arrived.

To clarify: script streaming was just enabled for testing or are we generally back to script streaming?

[deepak1556]

script streaming was just enabled for testing or are we generally back to script streaming ?

It is enabled by default in Electron 19 since the update made to main branch.

To drill in we would probably have to check the numbers from the performance editor to see if there is a specific thing.

Yeah let me check on that.

[deepak1556]

Couple of traces that would help from the perf bot once @jrieken gets back from vacation,

1. For both stable and insiders separately, to get chrome startup trace start the application with --trace-startup --trace-startup-duration=20 --trace-startup-file=<absolute-path-to>/chrometrace.log, once the application is exited the trace will be generated at the location specified.

2. For both stable and insiders separately, to get windows performance trace (ETW)

• Open Windows Performance Recorder from system start menu
• Have the following settings

• Start the recorder
• Open the application
• Once the application has completely loaded, stop the recorder and save the profile
• Send the profile to Deepak.Mohan@microsoft.com since it will contain sensitive information.

[bpasero]

Fyi summary of my experiments:

• cannot reproduce a slowdown on my new Surface Laptop 3 with Windows 11 [1]
• running exploration build on the perf bot
  • same slowness when going back to Electron 18
  • same slowness when disabling sandbox and utility process

[1] Setup:

• simple TS project, package.json opened
• startup perf editor in second column
• same startup CLI flags as perf bot
• looking for workbench ready numbers

[bpasero]

I wonder if this could possibly be a result of opening VSCode in the background as a service, vs. opening it normally. We do pass the flags to disable Window occlusion and maybe support for that broke recently? Though I did try with Electron 18.3.5 and the slowness was still there...

I checked Kusto again and here are the 50th percentile ellapsed times over 50 days:

Insiders 1.70

Avg: 1875 (picking last 12 days)

Insiders 1.71:

Avg: 1.777

I do not really see a trend of slowness in 1.71.x tbh.

[deepak1556]

We do pass the flags to disable Window occlusion and maybe support for that broke recently?

Nope it is still supported, although this came up today from chromium folks and they are recommending embedders to disable the feature by default due to lock contentions for the window events. I will go ahead and make that change this iteration.

[jrieken]

For both stable and insiders separately, to get windows performance trace (ETW)

@deepak1556 The perf machine doesn't run stable the same way it runs insiders. So, it is unlikely to yield comparable results. Unless both run (stable/insiders) happen "with ui". Also, did you run these check locally and didn't see a difference? Doing things on the perf machine isn't quick and easy as I'll be walking around with an USB stick

[jrieken]

I do not really see a trend of slowness in 1.71.x tbh.

Me neither but the variation between the days is quite large (1.865 to 1.627 for 1.71)

[jrieken]

f5c96, today - https://az764295.vo.msecnd.net/insider/f5c96e2db885f43fe1adb4a6ebbdfecf095430a8/VSCode-win32-x64-1.71.0-insider.zip

13b17, last fast - https://az764295.vo.msecnd.net/insider/13ba7bb446a638d37ebccb1a7d74e31c32bb9790/VSCode-win32-x64-1.70.0-insider.zip

3104d, fast - https://az764295.vo.msecnd.net/insider/3104db414c8fedcf6e4493f14da7df0b7413853a/VSCode-win32-x64-1.70.0-insider.zip

---

fast - https://az764295.vo.msecnd.net/insider/9925e5d4d3d355758cd09d26868f0c12a0006828/VSCode-win32-x64-1.70.0-insider.zip
slow - https://az764295.vo.msecnd.net/insider/052d5b0027f6c9d64c8ca35955cb5117ba94d5d7/VSCode-win32-x64-1.70.0-insider.zip

[deepak1556]

@jrieken #156864 (comment) are the results from my machine. I have got some perf traces from @bpasero device, I will compare that with runs from my machine.

@bpasero tried some exploration runs recently reverting to Electron 18 and it still showed slower numbers on the perf bot, pointing to a perf regression from the application. When Electron 19 was still in exploration in July we had some normal runs until https://vscodeteam.slack.com/archives/C3NBSM7K3/p1658318274765939 when both insiders on Electron 18 and exploration on Electron 19 started showing slower numbers on the perf machine since then, wondering if bisecting on that range would highlight offending commit.

[jrieken]

🤷 It's really tricky - I manually compared the build from #156864 (comment) on my mac, an arm windonw vm, and the perf machine but I couldn't see a clear trend here

My suspicion is that it's a combination of things. On a high note: mac (at least) is significantly faster now. Almost by 1 second, I guess that's because of the improved crash reporter

[bpasero]

On a high note: mac (at least) is significantly faster now. Almost by 1 second, I guess that's because of the improved crash reporter

👍 , this is a good reminder to filter Kusto queries to only Windows when investigating perf-bot, otherwise the results will be flawed. I also noticed that macOS ellapsed time really seems to have improved, probably because of the crash reporter perf fix.

[jrieken]

Just looking the perf machine telemetry shows a slow-down between insiders of the 3rd and 5th of August. This is all commits: https://github.com/microsoft/vscode/commits/main?since=2022-08-03&until=2022-08-05. The E19 adoption happened then but also other things. Perf Machine Telemetry

Other things maybe have an impact

• @mjbvz 508486f - According to http://jsben.ch/U1qqw AbortSignal is much slower than add/remove (~10%)
• @mjbvz 85c03e0 - Similar, http://jsben.ch/P90a6, not sure what the overall impact is but perf of the new variant is only 17% of the old one

[jrieken]

@mjbvz I have #158892 to revert both changes. In addition to the jsben.ch-numbers is see a slowdown in real world perf, not as drastic but consistent. On my M1 pro macbook it's just a delta of ~3ms but my suspicion is that this can easily be 20 or 30ms on the 10 year old perf machine. It's kinda desperate but there is something that slows down everything, so common util functions are a good guess

[mjbvz]

hm, possibly but I can't view those benchmarks as the site appears compromised (it tries to redirect right away)

[jrieken]

https://vscodeteam.slack.com/archives/C3NBSM7K3/p1661330838069859 - looks like we pulled back ~30ms with today's insiders. Confirms my assumption about perf differences between my machine 🏃 and the perf bot 👴

[deepak1556]

@jrieken can you get the Windows Performance Recorder trace (Point 2 in #156864 (comment)) from the perf bot when you have some time this week. It will help me compare the traces from my machine and @bpasero to see for any v8 execution slowdown in the runtime.

[bpasero]

Looking at the T_windowload regression:

I feel like the most recent perf regression is from Aug 16th to 17th which puts us here: 8e42bda...dd0ed93

Where 2857051 stands up to me. As it turns out, even though we had flipped the default of WCO to be enabled on Windows by default, it was not enabled until this commit. This will set titleBarOverlay option on BrowserWindow for Windows, thus could impact the time it takes to create a BrowserWindow here:

vscode/src/vs/platform/windows/electron-main/windowImpl.ts

Lines 298 to 300 in 947ca71

	mark('code/willCreateCodeBrowserWindow');
	this._win = new BrowserWindow(options);
	mark('code/didCreateCodeBrowserWindow');

Unfortunately it does not look like we are tracking ellapsedBrowserWindowCreate in Kusto, at least I could not find it. If we had access to that number, we could tell apart if the regression is somewhere else or in the window creation code (which blocks sync in Electron).

[bpasero]

I am not able to get us back to <2.5s by just reverting to Electron 18 based on the exploration builds that ran in the perf machine so this will be a task of continued investigation:

• where we have regressed by code changes from us
• where we can improve perf by looking into profile data (main, renderer)

[bpasero]

#160957 bundles our main files into single files, avoiding multiple require calls that have to go to disk. It covers main.js, cli.js (and also our server startup files).

Before we would have 10ish require calls for things like loader.js which are then all inlined to the file. The only file we still have to load from disk is product.json because it is changed after minification task.

[bpasero]

#161095 does the same for the files we require via non-async <script> tags in workbench.html. This requires us to ship 2 versions of the HTML files, depending on running out of sources vs. built.

The net result is that there will only be 1 blocking <script> tag and not 4.

[bpasero]

I think it is fair to close this issue, we are back with good numbers:

We will list individual changes that went in during this milestone in our release notes: https://github.com/microsoft/vscode-docs/blob/vnext/release-notes/v1_72.md#improved-startup-performance

We will also continue to improve startup performance: https://github.com/microsoft/vscode/issues?q=is%3Aopen+is%3Aissue+label%3Aperf-startup