Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug]: Performance regression in 24.x #37454

Closed
3 tasks done
Prinzhorn opened this issue Mar 1, 2023 · 18 comments
Closed
3 tasks done

[Bug]: Performance regression in 24.x #37454

Prinzhorn opened this issue Mar 1, 2023 · 18 comments

Comments

@Prinzhorn
Copy link
Contributor

Preflight Checklist

Electron Version

24.0.0-alpha.6

What operating system are you using?

Ubuntu

Operating System Version

Linux alex-NUC11PAHi7 5.19.0-31-generic #32-Ubuntu SMP PREEMPT_DYNAMIC Fri Jan 20 15:20:08 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

What arch are you using?

x64

Last Known Working Electron version

23.1.1

Expected Behavior

24 as fast as 23

Actual Behavior

Slower

Testcase Gist URL

https://gist.github.com/419cb8aed0be96a28afa3077be0db4ee

Additional Information

I just did some entirely unrelated debugging in Fiddle and found a noticeable delay when using 24.

In the Fiddle I'm consistently getting ~70ms (50 to 80) for 23.1.1 and ~200ms (180 to 210) for any 24 alpha (1 through 6).

For anything more complex it is way more noticeable, but the hello world Fiddle is enough as PoC.

@VerteDinde
Copy link
Member

@Prinzhorn Sorry, just want to verify - I took a look at the gist, is the specific measurement here for time to start/time to load webContents? Just wanted to make sure we're looking at the right thing as we debug 👀 Thanks for reporting this!

@Prinzhorn
Copy link
Contributor Author

Prinzhorn commented Mar 2, 2023

I chose this event seemingly at random. What I noticed was that it took longer than expected to launch a Fiddle with 24.x and this was the first event I tried to make this measurable. So no, unfortunately I cannot narrow it down any further. It's just what I felt, I think opening the window is as fast as usual but then the window is blank for longer than with 23.x. That's what I originally noticed (content showing slower than with 23)

@Prinzhorn
Copy link
Contributor Author

Prinzhorn commented Mar 2, 2023

Here's a slightly updated Fiddle. I won't go any further to avoid duplicate work. And frankly I don't know what other events could be used best to narrow this down further. But it appears it's actually the loading itself.

https://gist.github.com/7fb4af51631340ef4bb2f21033c977c0

v23
did-start-loading: 1.358ms
did-finish-load: 75.106ms

v24
did-start-loading: 1.489ms
did-finish-load: 204.044ms

@nornagon
Copy link
Member

nornagon commented Mar 2, 2023

I don't see this on macOS:

v22
did-start-loading: 2.505ms
did-finish-load: 254.832ms

v23
did-start-loading: 2.747ms
did-finish-load: 262.561ms

v24
did-start-loading: 2.707ms
did-finish-load: 244.948ms

So I guess this is Linux-specific..?

@Prinzhorn
Copy link
Contributor Author

So I guess this is Linux-specific..?

I could not reproduce in a Windows VM either.

Out of curiosity I added one more metric: https://gist.github.com/ac076574ef7e619cc7a1c304a4f9b031

v23
did-start-loading: 1.114ms
got-request: 15.619ms
did-finish-load: 62.397ms

v24
did-start-loading: 1.784ms
got-request: 68.516ms
did-finish-load: 180.419ms

Not sure this helps, because it makes it look like things are "just slow"? Because the requests takes longer to arrive but then it also takes longer to finish loading.

@nornagon
Copy link
Member

Can you also try measuring the time from app boot until did-finish-load? I wonder if some other initialization got moved around and you're now measuring that too, when you weren't previously.

@Prinzhorn
Copy link
Contributor Author

Prinzhorn commented Mar 17, 2023

Like this? It appears that v24 is slower in general, it's not just the slice I'm measuring (not WebContents related at all). Are there like debug symbols in the v24 Linux build or anything along those lines that make this slow in general?

const { app, protocol, BrowserWindow } = require('electron')
const path = require('path')

function createWindow () {
  // Create the browser window.
  const mainWindow = new BrowserWindow({
    width: 800,
    height: 600,
    webPreferences: {
      preload: path.join(__dirname, 'preload.js')
    }
  })

  protocol.registerFileProtocol('atom', (request, callback) => {
    console.timeEnd('got-request');
    callback(path.join(__dirname, 'index.html'));
  })

  console.time('did-start-loading');
  console.time('did-finish-load');
  console.time('got-request');

  mainWindow.webContents.on('did-start-loading', () => {
    console.timeEnd('did-start-loading');
  });

  mainWindow.webContents.on('did-finish-load', () => {
    console.timeEnd('did-finish-load');
    app.quit();
  });

  // and load the index.html of the app.
  mainWindow.loadURL('atom://');
}

app.whenReady().then(() => {
  createWindow()
})
v23.1.4

 $ time ./node_modules/.bin/electron index.js 
did-start-loading: 1.352ms
got-request: 14.323ms
did-finish-load: 74.712ms

real	0m0,305s
user	0m0,220s
sys	0m0,039s

v24.0.0-beta.3

 $ time ./node_modules/.bin/electron index.js 
did-start-loading: 1.217ms
libva error: vaGetDriverNameByIndex() failed with unknown libva error, driver_name = (null)
got-request: 61.945ms
did-finish-load: 162.879ms

real	0m0,404s
user	0m0,251s
sys	0m0,163s

If I quit() in did-start-loading I get this:

v23.1.4

 $ time ./node_modules/.bin/electron index.js 
did-start-loading: 1.609ms
got-request: 15.61ms

real	0m0,232s
user	0m0,167s
sys	0m0,059s

v24.0.0-beta.3

did-start-loading: 1.37ms
libva error: vaGetDriverNameByIndex() failed with unknown libva error, driver_name = (null)
got-request: 76.883ms

real	0m0,358s
user	0m0,235s
sys	0m0,105s

It might be worth noting that v24 spits out libva error: vaGetDriverNameByIndex() failed with unknown libva error, driver_name = (null) which 23 does not.

@Prinzhorn
Copy link
Contributor Author

Prinzhorn commented Mar 17, 2023

If I look at the following it might be related to the window? I'll look into that.

const { app } = require('electron')
app.quit();
v23.1.4

$ time ./node_modules/.bin/electron index.js 

real	0m0,230s
user	0m0,149s
sys	0m0,014s


v24.0.0-beta.3

$ time ./node_modules/.bin/electron index.js 

real	0m0,218s
user	0m0,145s
sys	0m0,027s

Edit: unfortunately I'm not well and can't look into this any further now.

@Prinzhorn
Copy link
Contributor Author

whenReady() takes the same time in both. As does new BrowserWindow(). That means the time is lost after loadURL is called. So maybe it is an issue with WebContents after all. As seen from the original measurements it takes longer for the request to arrive in registerFileProtocol but then it also takes longer to did-finish-load. So both the networking part as well as the rendering are slower?

@Prinzhorn
Copy link
Contributor Author

I wonder why this does not block stable? The time it takes for did-finish-load / ready-to-show has tripled. At least for me this will block upgrading to 24.

@AsherGlick
Copy link

I have been experiencing an issue that might be similar, but not limited to v24 it seems to have originated back in v13

version time till ready-to-show
11.5.0 208.279931ms
12.0.18 202.472953ms
12.1.2 203.189695ms
12.2.3 200.051848ms
13.0.1 1434.257709ms
13.6.9 1461.610284ms
14.0.2 1459.188428ms
23.2.0 1546.604452ms
24.0.0-beta.5 1601.363980ms

I have a intel integrated gpu and a discrete nvidia gpu that was recently disabled prompting me to start seeing this issue.

I have also checked the most recent version of chromium available to my machine at this time Chromium 111.0.5563.110 and it seems to load faster than electron.

Maybe this info will help you pin down when/where yours occurs.

@ckerr
Copy link
Member

ckerr commented Mar 28, 2023

I just did some triage on 37736, which as @Prinzhorn has pointed out is probably a duplicate of this ticket.

If this is the same as 37736, it was introduced in v24.0.0-nightly.20230202...v24.0.0-nightly.20230203 which happily only has two commits between them:

  1. Chromium roll chore: bump chromium to 111.0.5560.0 (main) #36820. A roll would usually be the prime suspect; but here, the other commit is:
  2. refactor: process event emitting for sandboxed renderers #37109 which sounds sus in the context of this bug report.

@jkleinsc
Copy link
Contributor

@jkleinsc
Copy link
Contributor

FYI... some more context. Looking at 25.0.0 nightlies, it looks like the issue was fixed in v25.0.0-nightly.20230322
Here's the diff to the previous nightly which has the problem: v25.0.0-nightly.20230321...v25.0.0-nightly.20230322.

So it looks like this chromium roll fixed the issue:

@jkleinsc
Copy link
Contributor

Looks like it is a V8 issue. This CL appears to have fixed the issue in the nightlies: https://chromium-review.googlesource.com/c/chromium/src/+/4355892.

I'll try to isolate it down to figure out which V8 commit fixes the issue:

https://chromium.googlesource.com/v8/v8/+log/596d10a8..90ff6c03

@jkleinsc jkleinsc self-assigned this Mar 30, 2023
@jkleinsc
Copy link
Contributor

Ok... pretty sure I found the cause and fix.

I'm testing a cherry-pick to 24 and will update once I can test it.

@jkleinsc
Copy link
Contributor

Ok - I just tested it. https://chromium-review.googlesource.com/c/v8/v8/+/4338176 fixes the issue. I'm going to throw the fix into the 24 chromium roll here: #37767.

@Prinzhorn
Copy link
Contributor Author

Legend

jkleinsc added a commit that referenced this issue Mar 31, 2023
* chore: bump chromium in DEPS to 112.0.5615.49

* fix: Store the thread stack start in TLS.

https://chromium-review.googlesource.com/c/v8/v8/+/4338176

Fixes #37454

---------

Co-authored-by: electron-roller[bot] <84116207+electron-roller[bot]@users.noreply.github.com>
Co-authored-by: John Kleinschmidt <jkleinsc@electronjs.org>
@nornagon nornagon closed this as completed Apr 4, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
No open projects
Status: Fixed for Next Release
Development

No branches or pull requests

7 participants