search

microsoft / vscode

Visual Studio Code
https://code.visualstudio.com
MIT License
163.33k stars 28.9k forks source link

Investigate startup performance regression #156864

Closed bpasero closed 2 years ago

bpasero commented 2 years ago

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 commented 2 years ago

Does not look so good:

image

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

deepak1556 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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)

Screenshot 2022-08-10 174956

bpasero commented 2 years ago

Fyi summary of my experiments:

[1] Setup:

bpasero commented 2 years ago

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

image

Avg: 1875 (picking last 12 days)

Insiders 1.71:

image

Avg: 1.777

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

deepak1556 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

@jrieken https://github.com/microsoft/vscode/issues/156864#issuecomment-1209564631 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 commented 2 years ago

🤷 It's really tricky - I manually compared the build from https://github.com/microsoft/vscode/issues/156864#issuecomment-1219546192 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 commented 2 years ago

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 commented 2 years ago

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

Screenshot 2022-08-23 at 12 59 03

Other things maybe have an impact

jrieken commented 2 years ago

@mjbvz I have https://github.com/microsoft/vscode/pull/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 commented 2 years ago

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

jrieken commented 2 years ago

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 commented 2 years ago

@jrieken can you get the Windows Performance Recorder trace (Point 2 in https://github.com/microsoft/vscode/issues/156864#issuecomment-1210363558) 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 commented 2 years ago

Looking at the T_windowload regression:

image

I feel like the most recent perf regression is from Aug 16th to 17th which puts us here: https://github.com/microsoft/vscode/compare/8e42bda5487a953d59fab7792eedd4ca209cabba...dd0ed9381aa5d0d43159463ccad1f7e060021580

Where https://github.com/microsoft/vscode/commit/2857051bb4e1bd7177c0d48b468b665c5a53b3c1 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:

https://github.com/microsoft/vscode/blob/947ca7189ce92c27dcbd93cbe819ba6ea044a98f/src/vs/platform/windows/electron-main/windowImpl.ts#L298-L300

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 commented 2 years ago

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:

bpasero commented 2 years ago

https://github.com/microsoft/vscode/pull/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 commented 2 years ago

https://github.com/microsoft/vscode/pull/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 commented 2 years ago

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

image

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