1951249 - [Gnome/Wayland][VSync] Painting stops every now and then on Linux

Status: RESOLVED FIXED

(Core :: Widget: Gtk, defect, P2)

Description

[Olli Pettay [:smaug][[e-mail]]]

Every now and then painting of a window stops on Fedora 40. Neither the parent process side nor content process side gets painted, but it is per window, not per whole Firefox. This is a relatively recent regression. Not sure if this could be an issue on OS side or has there been any changes to painting on Gecko side.
Opening a new tab or focusing another window and then back to original window helps.
For user the not-painting feels like a jank, scrolling doesn't work etc. which is why I thought initially that there is some long running CC or GC, but when I managed to get this to a performance profile (which I unfortunately didn't save), there was basically nothing running.

And this has happened on multiple different FF profiles, but I've used only this AMD 7840HS based laptop.

Comment 1

[Martin Stránský [:stransky] (ni? me)]

Please attach your about:support page.
Thanks.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

Attachment: aboutsupport.txt

Comment 3

[Martin Stránský [:stransky] (ni? me)]

Can you try to set widget.wayland.vsync.enabled to true, restart browser and check if you see it?
Thanks.

Comment 4

[Olli Pettay [:smaug][[e-mail]]]

Testing...

Comment 5

[Shmerl]

This happens for me in KDE too (Plasma 6.3.0) in 137.0b1.

widget.wayland.vsync.enabled is already set to true (seems to be default).

Comment 6

[Martin Stránský [:stransky] (ni? me)]

Also can you try to switch to software WebRender?

Comment 7

[Shmerl]

Just tried setting

gfx.webrender.compositor = false
gfx.webrender.compositor.force-enabled = false

It does help - GPU usage stopped when page is idle.

Comment 8

[Olli Pettay [:smaug][[e-mail]]]

So far with widget.wayland.vsync.enabled==false I haven't seen the issue.

Comment 9

[Martin Stránský [:stransky] (ni? me)]

(In reply to Olli Pettay [:smaug][[e-mail]] from comment #8)

So far with widget.wayland.vsync.enabled==false I haven't seen the issue.

Great, thanks for testing. Looks like there's a bug in processing wl_surface frame callbacks then. We've landed various fixes recently there, can you test Firefox 136 and/or latest nightly if you still see it?

If you see it with nightly I'll ask for vsync logs then.
Thanks.

Comment 10

[Martin Stránský [:stransky] (ni? me)]

(In reply to Shmerl from comment #7)

Just tried setting

gfx.webrender.compositor = false
gfx.webrender.compositor.force-enabled = false

It does help - GPU usage stopped when page is idle.

That's completely different issue, please file as blocker of Bug 1642854 (Linux/HDR/layered rendering).
Thanks.

Comment 11

[Shmerl]

(In reply to Martin Stránský [:stransky] (ni? me) from comment #10)

That's completely different issue, please file as blocker of Bug 1642854 (Linux/HDR/layered rendering).
Thanks.

Yeah, sorry I got confused since I had two related issues opened. Should I file that blocker about higher than normal GPU usage when hardware webrdender path is used or about content corruptions with it (jankiness as described above)?

Comment 12

[Martin Stránský [:stransky] (ni? me)]

(In reply to Shmerl from comment #11)

(In reply to Martin Stránský [:stransky] (ni? me) from comment #10)

That's completely different issue, please file as blocker of Bug 1642854 (Linux/HDR/layered rendering).
Thanks.

Yeah, sorry I got confused since I had two related issues opened. Should I file that blocker about higher than normal GPU usage when hardware webrdender path is used or about content corruptions with it (jankiness as described above)?

Please stop reporting any bugs with gfx.webrender.compositor / gfx.webrender.compositor.force-enabled. This is not hardware Webrender, this is experimental layered rendering. Hardware WebRender has been enabled by default for all users for 4 years.

Comment 13

[Olli Pettay [:smaug][[e-mail]]]

(In reply to Martin Stránský [:stransky] (ni? me) from comment #9)

(In reply to Olli Pettay [:smaug][[e-mail]] from comment #8)

So far with widget.wayland.vsync.enabled==false I haven't seen the issue.

Great, thanks for testing. Looks like there's a bug in processing wl_surface frame callbacks then. We've landed various fixes recently there, can you test Firefox 136 and/or latest nightly if you still see it?

I use basically only Nightly. The issue happens in 138 and I saw it also in 137.

Comment 14

[Martin Stránský [:stransky] (ni? me)]

Please set widget.wayland.vsync.enabled to true and run on terminal as:

MOZ_LOG="WidgetVSync:5" firefox

if you see the freeze, please check if Firefox is printing Vsync events to terminal. Also please copy the lines around the freeze.
Thanks.

Comment 15

[Olli Pettay [:smaug][[e-mail]]]

I think the part of the log captured the time when there was a stop in painting. See that WaylandVsyncSource::HiddenWindowCallback().
Looks like bug 1934497 changed some of the relevant code relatively recently.

[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource frame callback, routed 0 time 263972988
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::VisibleWindowCallback() time 263972988
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::CalculateVsyncRateLocked start fps 89.490242
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: new fps 89.630135 correction 0.017440
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource frame callback, routed 0 time 263972999
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::VisibleWindowCallback() time 263972999
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::CalculateVsyncRateLocked start fps 89.630135
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: new fps 89.756409 correction 0.015696
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource frame callback, routed 0 time 263973011
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::VisibleWindowCallback() time 263973011
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::CalculateVsyncRateLocked start fps 89.756409
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: new fps 89.069885 correction 0.085873
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource frame callback, routed 0 time 263973021
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::VisibleWindowCallback() time 263973021
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::CalculateVsyncRateLocked start fps 89.069885
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: new fps 90.054176 correction 0.122714
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource frame callback, routed 0 time 263973032
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::VisibleWindowCallback() time 263973032
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::CalculateVsyncRateLocked start fps 90.054176
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: new fps 90.138947 correction 0.010443
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::DisableVsync fps 90.138947
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::HiddenWindowCallback(): quit, mVsyncEnabled 0 mWaylandSurface 7fddb30a2a00
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::EnableVsync fps 90.138947
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3eb2900]: WaylandVsyncSource::EnableVsync fps 33.237671
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3099900]: WaylandVsyncSource frame callback, routed 0 time 263984735
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3099900]: WaylandVsyncSource::VisibleWindowCallback() time 263984735
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3099900]: WaylandVsyncSource::CalculateVsyncRateLocked start fps 9.437446
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3099900]: new fps 4.718723 correction 105.960873
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3099900]: WaylandVsyncSource::SetHiddenWindowVSync()
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3fd5a00]: WaylandVsyncSource::EnableVsync fps 31.336401
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3eb2900]: WaylandVsyncSource frame callback, routed 0 time 263984753
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3eb2900]: WaylandVsyncSource::VisibleWindowCallback() time 263984753
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3eb2900]: WaylandVsyncSource::CalculateVsyncRateLocked start fps 33.237671
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3eb2900]: new fps 16.618835 correction 30.086345
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3eb2900]: WaylandVsyncSource::SetHiddenWindowVSync()
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource frame callback, routed 0 time 263984753
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::VisibleWindowCallback() time 263984753
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::CalculateVsyncRateLocked start fps 90.138947
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: new fps 45.069473 correction 11.093984
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::SetHiddenWindowVSync()

Comment 16

[Olli Pettay [:smaug][[e-mail]]]

Looks like I get similar looking log whenever first scrolling using touchpad/two fingers and then stop scrolling. But when the painting stopped for longer period, the log was stuck at HiddenWindowCallback.

(I'm trying to capture another log to ensure it looks similar to the one in the previous comment.)

Comment 17

[Olli Pettay [:smaug][[e-mail]]]

Got it again, or some variant of it. I wonder if it it is possible that it is somehow related hit testing / event targeting either somewhere in wayland/gnome level or in Gecko?
It seems to happen when I use Super+arrow keys to move a window around but not changing the cursor position and then using two finger scrolling.

But the issue I had when I filed this bug was/is different, since there I was just scrolling a page and it stopped working. No need to move window or anything.

Comment 18

[Martin Stránský [:stransky] (ni? me)]

[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::DisableVsync fps 90.138947
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::HiddenWindowCallback(): quit, mVsyncEnabled 0 mWaylandSurface 7fddb30a2a00
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddb7c31d00]: WaylandVsyncSource::EnableVsync fps 90.138947
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3eb2900]: WaylandVsyncSource::EnableVsync fps 33.237671
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3099900]: WaylandVsyncSource frame callback, routed 0 time 263984735
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3099900]: WaylandVsyncSource::VisibleWindowCallback() time 263984735
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3099900]: WaylandVsyncSource::CalculateVsyncRateLocked start fps 9.437446
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3099900]: new fps 4.718723 correction 105.960873
[Parent 2693266: Main Thread]: D/WidgetVSync [7fddc3099900]: WaylandVsyncSource::SetHiddenWindowVSync()

Looks like we're getting 'HiddenWindowCallback' although the window is still visible. I'll look at the vsync code how's that possible.
Thanks for the logs.

Comment 19

[Martin Stránský [:stransky] (ni? me)]

Hm, I was wrong. If we get hidden window callback, it prints something like "WaylandVsyncSource::HiddenWindowCallback() we're hidden".

Comment 20

[Martin Stránský [:stransky] (ni? me)]

Please run on terminal with MOZ_LOG="Widget:5" and try to filter out 'nsWindow::OnExposeEvent'.

If Firefox is frozen, is it painted again after 'nsWindow::OnExposeEvent' ?

It's also possible that we don't paint main window for some reason:
https://searchfox.org/mozilla-central/rev/391e86d9a0d82b655fc0ace236da04949970fb01/widget/gtk/nsWindow.cpp#3900

that may be also present in the log (reason why we skip painting).
Thanks.

Comment 22

[Martin Stránský [:stransky] (ni? me)]

Or run it on terminal as:

MOZ_LOG="Widget:5 WidgetVsync:5" firefox > log.txt 2>&1

when you see the freeze, please switch to terminal, quit firefox by ctrl+c and attach the log.txt file here.
Thanks.

Comment 23

[Olli Pettay [:smaug][[e-mail]]]

Attachment: log_small.txt

I believe the last key_press is from the ctrl+tab to focus terminal. Before that I was trying to scroll the page using two finger scrolling. Nothing was re-painted. Immediately when focus starts to move to another window, painting happens again.

Comment 24

[Martin Stránský [:stransky] (ni? me)]

(In reply to Martin Stránský [:stransky] (ni? me) from comment #22)

Or run it on terminal as:

MOZ_LOG="Widget:5 WidgetVsync:5" firefox > log.txt 2>&1

when you see the freeze, please switch to terminal, quit firefox by ctrl+c and attach the log.txt file here.
Thanks.

Sorry, the log comment is incorrect. It's WidgetVSync, so:

MOZ_LOG="Widget:5 WidgetVSync:5" firefox > log.txt 2>&1

Comment 25

[Martin Stránský [:stransky] (ni? me)]

I think I've got it from downstream: https://bugzilla.redhat.com/show_bug.cgi?id=2357706

We should reset hidden vsycn timer when vsync is enabled/disabled:

[Parent 1231517: Main Thread]: D/WidgetVSync [7fbc8f8fd600]: WaylandVsyncSource::DisableVsync fps 3.615839
[Parent 1231517: Main Thread]: D/WidgetVSync [7fbc8f8fd600]: WaylandVsyncSource::EnableVsync fps 3.615839
[Parent 1231517: Main Thread]: D/WidgetVSync [7fbc8f8fd600]: WaylandVsyncSource::HiddenWindowCallback() we're hidden, time since last VSync 1002 ms

That's obviously wrong, we can't mark window hidden right after vsync enable.

Comment 26

[Martin Stránský [:stransky] (ni? me)]

Attachment: Bug 1951249 [Wayland] Reset VSync state if VSync is enabled/disabled r?emilio

Comment 27

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/29a85f973190
[Wayland] Reset VSync state if VSync is enabled/disabled r=emilio

Comment 28

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/29a85f973190

Comment 29

[Martin Stránský [:stransky] (ni? me)]

Can you please test latest nightly if it's fixed for you?
Thanks.

Comment 30

[BugBot [:suhaib / :marco/ :calixte]]

The patch landed in nightly and beta is affected.
:stransky, is this bug important enough to require an uplift?

• If yes, please nominate the patch for beta approval.
• If no, please set status-firefox138 to wontfix.

For more information, please visit BugBot documentation.

Comment 31

[Martin Stránský [:stransky] (ni? me)]

Comment on attachment 9478149 [details]
Bug 1951249 [Wayland] Reset VSync state if VSync is enabled/disabled r?emilio

Beta/Release Uplift Approval Request

• User impact if declined/Reason for urgency: Firefox freeze, reported by various users/bug reports. Finally catch and fixed.
• Is this code covered by automated tests?: No
• Has the fix been verified in Nightly?: No
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Medium
• Why is the change risky/not risky? (and alternatives if risky): Updated VSync code which is always a bit tricky, but the patch doesn't look very risky/complicated to me. Just clear up and reset VSync state when it's enabled and disabled.
• String changes made/needed:
• Is Android affected?: Yes

Comment 32

[Dianna Smith [:diannaS]]

Comment on attachment 9478149 [details]
Bug 1951249 [Wayland] Reset VSync state if VSync is enabled/disabled r?emilio

Approved for 138.0b7

Comment 33

[Pulsebot]

https://hg.mozilla.org/releases/mozilla-beta/rev/adaa3d4bbbe2