1982990 - Trying to resize the browser window on Linux 24.04 CI workers cause a 500ms delay

Reporter

Description

•

1 year ago

Quite a few tests are timing out after 500ms these days in Wdspec CI jobs on the new Linux 24.04 workers which call the WebDriver:SetWindowRect command for resizing the window. Here an example:

https://treeherder.mozilla.org/logviewer?job_id=521291792&repo=autoland&lineNumber=154827-154830

[task 2025-08-07T00:08:46.803+00:00] 00:08:46     INFO - PID 46704 | 1754525326802	Marionette	DEBUG	0 -> [0,84,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2025-08-07T00:08:46.804+00:00] 00:08:46     INFO - PID 46704 | 1754525326802	RemoteAgent	TRACE	Checking window geometry 1280x1077 @ (100, 100)
[task 2025-08-07T00:08:47.304+00:00] 00:08:47     INFO - PID 46704 | 1754525327303	Marionette	DEBUG	0 <- [1,84,null,{"x":100,"y":100,"width":1280,"height":1077}]
[task 2025-08-07T00:08:47.305+00:00] 00:08:47     INFO - PID 46704 | 1754525327304	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":1280,"height":1077}}

As it can be seen the window is not getting resized correctly but stays at its former dimensions. Note that this is not with Wayland but X11 as window manager. The suite was added via bug 1967504 about 3 months ago.

Emilio, are you aware of any window resizing issues on Ubuntu 24.04? I wonder why our code doesn't work, which calls window.resize(). I doubt that there are any kind of limitations present for X11 compared to Wayland.

We should investigate this issue quickly given that it affects all of the wdspec tests which modify the window position during the test and in teardown when we reset the position.

Flags: needinfo?(emilio)

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Updated

•

1 year ago

Blocks: 1524775

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Comment 1

•

1 year ago

I checked some other jobs on mozilla-central for debug builds and those do not show this issue:
https://treeherder.mozilla.org/logviewer?job_id=522303780&repo=mozilla-central&lineNumber=1637

Maybe this could be a misconfigured / bad worker? Not receiving the resize event could mean that the call to window.resize() did not trigger an actual resize on the system side.

I could try to push a try build with MOZ_LOG="widget:5" (is that the right one?) with a couple of retries if this would help.

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Updated

•

1 year ago

Blocks: 1878934

Emilio Cobos Álvarez [:emilio]

Assignee

Comment 2

•

1 year ago

It'd be MOZ_LOG=Widget:5, but yeah that'd help. One thing that could happen is that the resize event doesn't happen because the window has the right size already? But then moveTo would work so the code doesn't seem wrong per se...

Flags: needinfo?(emilio)

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Comment 3

•

1 year ago

It's not the case here. See the log excerpt above. The current size is 1280x1077 and we want to resize to 800x600. We timeout after 500ms with the window at the same size.

I pushed a try build with Widget:5 enabled:
https://treeherder.mozilla.org/jobs?repo=try&revision=4bad68f5b5b442520da66e621a721e0189714436

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Comment 4

•

1 year ago

•

Edited

So only a single test job out of 74 failed with resizing the window. But at least we now have some widget logs:
https://treeherder.mozilla.org/logviewer?job_id=522384211&repo=try&lineNumber=53034-53045

[task 2025-08-14T14:10:20.468+00:00] 14:10:20     INFO - PID 12541 | 1755180620466	Marionette	DEBUG	0 -> [0,1522,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2025-08-14T14:10:20.469+00:00] 14:10:20     INFO - PID 12541 | 1755180620466	RemoteAgent	TRACE	Checking window geometry 1280x1077 @ (100, 100)
[task 2025-08-14T14:10:20.469+00:00] 14:10:20     INFO - PID 12541 | [Parent 13986: Main Thread]: D/Widget [7f0f4431b600]: nsWindow::SetSizeMode 0
[task 2025-08-14T14:10:20.469+00:00] 14:10:20     INFO - PID 12541 | [Parent 13986: Main Thread]: D/Widget [7f0f4431b600]:     already set
[task 2025-08-14T14:10:20.470+00:00] 14:10:20     INFO - PID 12541 | [Parent 13986: Main Thread]: D/Widget [7f0f4431b600]: nsWindow::Resize 800.000000 600.000000
[task 2025-08-14T14:10:20.470+00:00] 14:10:20     INFO - PID 12541 | [Parent 13986: Main Thread]: D/Widget [7f0f4431b600]: nsWindow::ResizeInt w:800 h:600
[task 2025-08-14T14:10:20.471+00:00] 14:10:20     INFO - PID 12541 | [Parent 13986: Main Thread]: D/Widget [7f0f4431b600]:   ConstrainSize: w:800 h;600
[task 2025-08-14T14:10:20.471+00:00] 14:10:20     INFO - PID 12541 | [Parent 13986: Main Thread]: D/Widget [7f0f4431b600]:   resized 1 aSize [800, 600] mLastSizeRequest [800, 600] mBounds [1280, 1077]
[task 2025-08-14T14:10:20.472+00:00] 14:10:20     INFO - PID 12541 | [Parent 13986: Main Thread]: V/Widget [7f0f4431b600]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:10:20.472+00:00] 14:10:20     INFO - PID 12541 | [Parent 13986: Main Thread]: D/Widget [7f0f4431b600]: nsWindow::NativeMoveResize move 0 resize 1 to 100,100 -> 800 x 563
[task 2025-08-14T14:10:20.473+00:00] 14:10:20     INFO - PID 12541 | [Parent 13986: Main Thread]: D/Widget [7f0f4431b600]: nsWindow::SetInputRegion(0, 0)
[task 2025-08-14T14:10:20.968+00:00] 14:10:20     INFO - PID 12541 | 1755180620967	Marionette	DEBUG	0 <- [1,1522,null,{"x":100,"y":100,"width":1280,"height":1077}]

We do not get a resize event. In cases when resizing works it looks like the following:

[task 2025-08-14T14:01:52.171+00:00] 14:01:52     INFO - PID 1282 | 1755180112169	Marionette	DEBUG	0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2025-08-14T14:01:52.172+00:00] 14:01:52     INFO - PID 1282 | 1755180112171	RemoteAgent	TRACE	Checking window geometry 1280x1077 @ (66, 32)
[task 2025-08-14T14:01:52.175+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::SetSizeMode 0
[task 2025-08-14T14:01:52.175+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]:     already set
[task 2025-08-14T14:01:52.175+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::Resize 800.000000 600.000000
[task 2025-08-14T14:01:52.175+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::ResizeInt w:800 h:600
[task 2025-08-14T14:01:52.176+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]:   ConstrainSize: w:800 h;600
[task 2025-08-14T14:01:52.180+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]:   resized 1 aSize [800, 600] mLastSizeRequest [1280, 1077] mBounds [1280, 1077]
[task 2025-08-14T14:01:52.180+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.180+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::NativeMoveResize move 0 resize 1 to 0,0 -> 800 x 563
[task 2025-08-14T14:01:52.180+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::SetInputRegion(0, 0)
[task 2025-08-14T14:01:52.181+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::OnVisibilityNotifyEvent [7fceba409800] state 0x1
[task 2025-08-14T14:01:52.184+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: configure event 66,69 -> 800 x 563 direct mGdkWindow scale 1 (scaled size 800 x 563)
[task 2025-08-14T14:01:52.187+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: RecomputeBounds(0)
[task 2025-08-14T14:01:52.187+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.522+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.522+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: bounds: (x=0, y=0, w=1280, h=1040) -> (x=66, y=32, w=1280, h=1040) ((x=66, y=32, w=1280, h=1040) unconstrained)
[task 2025-08-14T14:01:47.522+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: margin: (t=0, r=0, b=0, l=0) -> (t=0, r=0, b=0, l=0)
[task 2025-08-14T14:01:47.522+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::CheckForRollup() aAlwaysRollup 1
[task 2025-08-14T14:01:47.537+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: configure event 0,0 -> 1280 x 1040 direct mGdkWindow scale 1 (scaled size 1280 x 1040)
[task 2025-08-14T14:01:47.540+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: RecomputeBounds(0)
[task 2025-08-14T14:01:47.543+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.544+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.547+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: bounds: (x=66, y=32, w=1280, h=1040) -> (x=0, y=0, w=29, h=67) ((x=0, y=0, w=29, h=67) unconstrained)
[task 2025-08-14T14:01:47.547+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: margin: (t=0, r=0, b=0, l=0) -> (t=0, r=0, b=0, l=0)
[task 2025-08-14T14:01:47.547+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::CheckForRollup() aAlwaysRollup 1
[task 2025-08-14T14:01:47.548+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::DispatchResized() size [29, 67]
[task 2025-08-14T14:01:47.553+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: GtkCompositorWidget::NotifyClientSizeChanged() to 29 x 67
[task 2025-08-14T14:01:47.554+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: configure event 192,74 -> 1280 x 1040 direct mGdkWindow scale 1 (scaled size 1280 x 1040)
[task 2025-08-14T14:01:47.554+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: RecomputeBounds(0)
[task 2025-08-14T14:01:47.554+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.554+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.555+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: bounds: (x=0, y=0, w=29, h=67) -> (x=0, y=0, w=29, h=67) ((x=0, y=0, w=29, h=67) unconstrained)
[task 2025-08-14T14:01:47.556+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: margin: (t=0, r=0, b=0, l=0) -> (t=0, r=0, b=0, l=0)
[task 2025-08-14T14:01:47.556+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: configure event 0,0 -> 1280 x 1040 direct mGdkWindow scale 1 (scaled size 1280 x 1040)
[task 2025-08-14T14:01:47.557+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: RecomputeBounds(0)
[task 2025-08-14T14:01:47.558+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.559+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.559+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: bounds: (x=0, y=0, w=29, h=67) -> (x=66, y=32, w=1280, h=1077) ((x=66, y=32, w=1280, h=1077) unconstrained)
[task 2025-08-14T14:01:47.560+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: margin: (t=0, r=0, b=0, l=0) -> (t=37, r=0, b=0, l=0)
[task 2025-08-14T14:01:47.561+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::CheckForRollup() aAlwaysRollup 1
[task 2025-08-14T14:01:47.561+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::DispatchResized() size [1280, 1077]
[task 2025-08-14T14:01:47.561+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: GtkCompositorWidget::NotifyClientSizeChanged() to 1280 x 1040
[task 2025-08-14T14:01:47.562+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: OnPropertyNotifyEvent(_NET_FRAME_EXTENTS)
[task 2025-08-14T14:01:47.563+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: configure event 66,69 -> 1280 x 1040 direct mGdkWindow scale 1 (scaled size 1280 x 1040)
[task 2025-08-14T14:01:47.563+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: RecomputeBounds(0)
[task 2025-08-14T14:01:47.564+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.565+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.566+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: bounds: (x=66, y=32, w=1280, h=1077) -> (x=66, y=32, w=1280, h=1077) ((x=66, y=32, w=1280, h=1077) unconstrained)
[task 2025-08-14T14:01:47.567+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: margin: (t=37, r=0, b=0, l=0) -> (t=37, r=0, b=0, l=0)
[task 2025-08-14T14:01:47.567+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::OnVisibilityNotifyEvent [7fceba409800] state 0x0
[task 2025-08-14T14:01:47.569+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: OnContainerFocusInEvent
[task 2025-08-14T14:01:47.569+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]:   nsWindow::SetUrgencyHint widget 7fceb8047e60
[task 2025-08-14T14:01:47.591+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: Events sent from focus in event
[task 2025-08-14T14:01:47.592+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::OnWindowStateEvent for 7fceb8047e60 changed 0x80 new_window_state 0x15480
[task 2025-08-14T14:01:47.592+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: 	early return because no interesting bits changed
[task 2025-08-14T14:01:47.592+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::OnWindowStateEvent for 7fceb786e690 changed 0x80 new_window_state 0x15480
[task 2025-08-14T14:01:47.594+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::SetHasMappedToplevel(1)
[task 2025-08-14T14:01:47.597+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: 	quick return because IS_MOZ_CONTAINER(aWidget) is true
[task 2025-08-14T14:01:47.597+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget moz_container_size_allocate [7fceba409800] 0,0 -> 1280 x 1040
[task 2025-08-14T14:01:47.597+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::OnContainerSizeAllocate 0,0 -> 1280 x 1040
[task 2025-08-14T14:01:47.598+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.598+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.599+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::OnExposeEvent GdkWindow [7fceb786cfc0] XID [0x1a00013]
[task 2025-08-14T14:01:47.600+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: MaybeRecomputeBounds 1
[task 2025-08-14T14:01:47.601+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: RecomputeBounds(1)
[task 2025-08-14T14:01:47.601+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.603+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.603+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: bounds: (x=66, y=32, w=1280, h=1077) -> (x=66, y=32, w=1280, h=1077) ((x=66, y=32, w=1280, h=1077) unconstrained)
[task 2025-08-14T14:01:47.606+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: margin: (t=37, r=0, b=0, l=0) -> (t=37, r=0, b=0, l=0)
[task 2025-08-14T14:01:47.607+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:47.610+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::RequestRepaint()
[task 2025-08-14T14:01:47.611+00:00] 14:01:47     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: redirect painting to OMTC rendering...
[task 2025-08-14T14:01:50.050+00:00] 14:01:50     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: MaybeRecomputeBounds 0
[task 2025-08-14T14:01:50.054+00:00] 14:01:50     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: MaybeRecomputeBounds 0
[task 2025-08-14T14:01:50.898+00:00] 14:01:50     INFO - PID 1282 | [Parent 1313, sqldb:places.sqlite #3] WARNING: Suboptimal indexes for the SQL statement 0x7fcea59dcc40 (http://mzl.la/1FuID0j).: file /builds/worker/checkouts/gecko/storage/mozStoragePrivateHelpers.cpp:114
[task 2025-08-14T14:01:50.923+00:00] 14:01:50     INFO - PID 1282 | [Parent 1313, sqldb:places.sqlite #3] WARNING: Suboptimal indexes for the SQL statement 0x7fcea59dcc40 (http://mzl.la/1FuID0j).: file /builds/worker/checkouts/gecko/storage/mozStoragePrivateHelpers.cpp:114
[task 2025-08-14T14:01:50.974+00:00] 14:01:50     INFO - PID 1282 | [Parent 1313, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp:1215
[task 2025-08-14T14:01:51.040+00:00] 14:01:51     INFO - PID 1282 | [Parent 1313, Main Thread] WARNING: NS_ENSURE_TRUE(mNameHashtable.Get(aName, &index)) failed: file /builds/worker/checkouts/gecko/storage/mozStorageRow.cpp:91
[task 2025-08-14T14:01:51.673+00:00] 14:01:51     INFO - PID 1282 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmplmes5e1_.mozrunner/runtests_leaks_1183_utility_pid1501.log
[task 2025-08-14T14:01:51.702+00:00] 14:01:51     INFO - PID 1282 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmplmes5e1_.mozrunner/runtests_leaks_1183_tab_pid1509.log
[task 2025-08-14T14:01:51.723+00:00] 14:01:51     INFO - PID 1282 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmplmes5e1_.mozrunner/runtests_leaks_1183_tab_pid1516.log
[task 2025-08-14T14:01:51.776+00:00] 14:01:51     INFO - PID 1282 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2025-08-14T14:01:51.777+00:00] 14:01:51     INFO - PID 1282 | [Child 1516, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:479
[task 2025-08-14T14:01:51.987+00:00] 14:01:51     INFO - PID 1282 | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmplmes5e1_.mozrunner/runtests_leaks_1183_tab_pid1556.log
[task 2025-08-14T14:01:52.099+00:00] 14:01:52     INFO - PID 1282 | 1755180112098	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2025-08-14T14:01:52.100+00:00] 14:01:52     INFO - PID 1282 | 1755180112098	RemoteAgent	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2025-08-14T14:01:52.100+00:00] 14:01:52     INFO - PID 1282 | 1755180112099	Marionette	DEBUG	Waiting for initial application window
[task 2025-08-14T14:01:52.113+00:00] 14:01:52     INFO - PID 1282 | 1755180112112	RemoteAgent	TRACE	[9] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
[task 2025-08-14T14:01:52.113+00:00] 14:01:52     INFO - PID 1282 | 1755180112112	RemoteAgent	TRACE	[9] ProgressListener Setting unload timer (40000ms)
[task 2025-08-14T14:01:52.114+00:00] 14:01:52     INFO - PID 1282 | 1755180112113	RemoteAgent	TRACE	[9] Wait for initial navigation: isInitial=false, isLoadingDocument=false
[task 2025-08-14T14:01:52.115+00:00] 14:01:52     INFO - PID 1282 | 1755180112113	RemoteAgent	TRACE	[9] Document already finished loading: about:blank
[task 2025-08-14T14:01:52.116+00:00] 14:01:52     INFO - PID 1282 | 1755180112114	RemoteAgent	TRACE	[9] ProgressListener Stop: has error=false url=about:blank
[task 2025-08-14T14:01:52.141+00:00] 14:01:52     INFO - PID 1282 | 1755180112139	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"280a042d-2824-4342-89ec-74a45eb966b2","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"143.0a1","platformName":"linux","unhandledPromptBehavior":"dismiss and notify","userAgent":"Mozilla/5.0 (X11; Linux x86_64; rv:143.0) Gecko/20100101 Firefox/143.0","moz:buildID":"20250812210356","moz:headless":false,"moz:platformVersion":"6.14.0-1011-gcp","moz:processID":1313,"moz:profile":"/tmp/tmplmes5e1_.mozrunner","moz:shutdownTimeout":60000,"pageLoadStrategy":"normal","timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"setWindowRect":true,"strictFileInteractability":false,"moz:accessibilityChecks":false,"moz:webdriverClick":true,"moz:windowless":false,"webSocketUrl":"ws://127.0.0.1:9222/session/280a042d-2824-4342-89ec-74a45eb966b2","proxy":{}}}]
[task 2025-08-14T14:01:52.151+00:00] 14:01:52     INFO - PID 1282 | 1755180112149	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"280a042d-2824-4342-89ec-74a45eb966b2","capabilities":{"acceptInsecureCerts":false,"browserNa ...  rv:143.0) Gecko/20100101 Firefox/143.0","webSocketUrl":"ws://127.0.0.1:9222/session/280a042d-2824-4342-89ec-74a45eb966b2"}}}
[task 2025-08-14T14:01:52.160+00:00] 14:01:52     INFO - PID 1282 | 1755180112159	RemoteAgent	INFO	Perform WebSocket upgrade for incoming connection from 127.0.0.1:47882
[task 2025-08-14T14:01:52.165+00:00] 14:01:52     INFO - PID 1282 | 1755180112163	webdriver::server	DEBUG	-> POST /session/280a042d-2824-4342-89ec-74a45eb966b2/window/rect {"width": 800, "height": 600}
[task 2025-08-14T14:01:52.169+00:00] 14:01:52     INFO - PID 1282 | 1755180112167	RemoteAgent	DEBUG	WebDriverBiDiConnection b8bae355-3108-4d76-9dab-3d9184612143 accepted
[task 2025-08-14T14:01:52.169+00:00] 14:01:52     INFO - PID 1282 | 1755180112167	WebDriver BiDi	DEBUG	Connection b8bae355-3108-4d76-9dab-3d9184612143 attached to session 280a042d-2824-4342-89ec-74a45eb966b2
[task 2025-08-14T14:01:52.171+00:00] 14:01:52     INFO - PID 1282 | 1755180112169	Marionette	DEBUG	0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2025-08-14T14:01:52.172+00:00] 14:01:52     INFO - PID 1282 | 1755180112171	RemoteAgent	TRACE	Checking window geometry 1280x1077 @ (66, 32)
[task 2025-08-14T14:01:52.175+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::SetSizeMode 0
[task 2025-08-14T14:01:52.175+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]:     already set
[task 2025-08-14T14:01:52.175+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::Resize 800.000000 600.000000
[task 2025-08-14T14:01:52.175+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::ResizeInt w:800 h:600
[task 2025-08-14T14:01:52.176+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]:   ConstrainSize: w:800 h;600
[task 2025-08-14T14:01:52.180+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]:   resized 1 aSize [800, 600] mLastSizeRequest [1280, 1077] mBounds [1280, 1077]
[task 2025-08-14T14:01:52.180+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.180+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::NativeMoveResize move 0 resize 1 to 0,0 -> 800 x 563
[task 2025-08-14T14:01:52.180+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::SetInputRegion(0, 0)
[task 2025-08-14T14:01:52.181+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::OnVisibilityNotifyEvent [7fceba409800] state 0x1
[task 2025-08-14T14:01:52.184+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: configure event 66,69 -> 800 x 563 direct mGdkWindow scale 1 (scaled size 800 x 563)
[task 2025-08-14T14:01:52.187+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: RecomputeBounds(0)
[task 2025-08-14T14:01:52.187+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.187+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.187+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: bounds: (x=66, y=32, w=1280, h=1077) -> (x=66, y=32, w=800, h=600) ((x=66, y=32, w=800, h=600) unconstrained)
[task 2025-08-14T14:01:52.187+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: margin: (t=37, r=0, b=0, l=0) -> (t=37, r=0, b=0, l=0)
[task 2025-08-14T14:01:52.187+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::DispatchResized() size [800, 600]
[task 2025-08-14T14:01:52.188+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: GtkCompositorWidget::NotifyClientSizeChanged() to 800 x 563
[task 2025-08-14T14:01:52.188+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::OnVisibilityNotifyEvent [7fceba409800] state 0x0
[task 2025-08-14T14:01:52.189+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget moz_container_size_allocate [7fceba409800] 0,0 -> 800 x 563
[task 2025-08-14T14:01:52.190+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::OnContainerSizeAllocate 0,0 -> 800 x 563
[task 2025-08-14T14:01:52.190+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.195+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.195+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::OnExposeEvent GdkWindow [7fceb786cfc0] XID [0x1a00013]
[task 2025-08-14T14:01:52.195+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: MaybeRecomputeBounds 1
[task 2025-08-14T14:01:52.195+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: RecomputeBounds(1)
[task 2025-08-14T14:01:52.204+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.204+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.204+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: bounds: (x=66, y=32, w=800, h=600) -> (x=66, y=32, w=800, h=600) ((x=66, y=32, w=800, h=600) unconstrained)
[task 2025-08-14T14:01:52.204+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: margin: (t=37, r=0, b=0, l=0) -> (t=37, r=0, b=0, l=0)
[task 2025-08-14T14:01:52.204+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.205+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: nsWindow::RequestRepaint()
[task 2025-08-14T14:01:52.228+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.228+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.229+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.229+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.229+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.229+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.230+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: V/Widget [7fceba409800]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:01:52.231+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: redirect painting to OMTC rendering...
[task 2025-08-14T14:01:52.442+00:00] 14:01:52     INFO - PID 1282 | 1755180112441	RemoteAgent	TRACE	Received DOM event resize for [object Window]
[task 2025-08-14T14:01:52.443+00:00] 14:01:52     INFO - PID 1282 | 1755180112441	RemoteAgent	TRACE	Checking window geometry 800x600 @ (66, 32)
[task 2025-08-14T14:01:52.443+00:00] 14:01:52     INFO - PID 1282 | 1755180112441	RemoteAgent	TRACE	Requested window geometry matches
[task 2025-08-14T14:01:52.450+00:00] 14:01:52     INFO - PID 1282 | [Parent 1313: Main Thread]: D/Widget [7fceba409800]: MaybeRecomputeBounds 0
[task 2025-08-14T14:01:52.451+00:00] 14:01:52     INFO - PID 1282 | 1755180112450	Marionette	DEBUG	0 <- [1,2,null,{"x":66,"y":32,"width":800,"height":600}]

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Comment 5

•

1 year ago

Interesting is the mLastSizeRequest [800, 600] part of the widget log. Could it be that the X server is confused and already thinks that the window has a 800x600 size and doesn't do anything?

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Comment 6

•

1 year ago

Actually it was not the very first request to resize the window. Here it is:

https://treeherder.mozilla.org/logviewer?job_id=522384211&repo=try&lineNumber=1826-1837

[task 2025-08-14T14:00:47.603+00:00] 14:00:47     INFO - PID 1308 | 1755180047601	Marionette	DEBUG	0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2025-08-14T14:00:47.604+00:00] 14:00:47     INFO - PID 1308 | 1755180047603	RemoteAgent	TRACE	Checking window geometry 1280x1077 @ (192, 62)
[task 2025-08-14T14:00:47.606+00:00] 14:00:47     INFO - PID 1308 | [Parent 1339: Main Thread]: D/Widget [7f815041ae00]: nsWindow::SetSizeMode 0
[task 2025-08-14T14:00:47.606+00:00] 14:00:47     INFO - PID 1308 | [Parent 1339: Main Thread]: D/Widget [7f815041ae00]:     already set
[task 2025-08-14T14:00:47.606+00:00] 14:00:47     INFO - PID 1308 | [Parent 1339: Main Thread]: D/Widget [7f815041ae00]: nsWindow::Resize 800.000000 600.000000
[task 2025-08-14T14:00:47.607+00:00] 14:00:47     INFO - PID 1308 | [Parent 1339: Main Thread]: D/Widget [7f815041ae00]: nsWindow::ResizeInt w:800 h:600
[task 2025-08-14T14:00:47.608+00:00] 14:00:47     INFO - PID 1308 | [Parent 1339: Main Thread]: D/Widget [7f815041ae00]:   ConstrainSize: w:800 h;600
[task 2025-08-14T14:00:47.608+00:00] 14:00:47     INFO - PID 1308 | [Parent 1339: Main Thread]: D/Widget [7f815041ae00]:   resized 1 aSize [800, 600] mLastSizeRequest [1280, 1077] mBounds [1280, 1077]
[task 2025-08-14T14:00:47.611+00:00] 14:00:47     INFO - PID 1308 | [Parent 1339: Main Thread]: V/Widget [7f815041ae00]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-14T14:00:47.615+00:00] 14:00:47     INFO - PID 1308 | [Parent 1339: Main Thread]: D/Widget [7f815041ae00]: nsWindow::NativeMoveResize move 0 resize 1 to 0,0 -> 800 x 563
[task 2025-08-14T14:00:47.615+00:00] 14:00:47     INFO - PID 1308 | [Parent 1339: Main Thread]: D/Widget [7f815041ae00]: nsWindow::SetInputRegion(0, 0)
[task 2025-08-14T14:00:48.105+00:00] 14:00:48     INFO - PID 1308 | 1755180048104	Marionette	DEBUG	0 <- [1,2,null,{"x":192,"y":62,"width":1280,"height":1077}]

This doesn't cause a resize of the window but internally we think the window was resized. We seem to store the expected size in mLastSizeRequest even before we get an ACK from the system that the window was indeed resized:

https://searchfox.org/mozilla-central/rev/ce0d41b6033e2a104904327a43edf730245f5241/widget/gtk/nsWindow.cpp#1109

As result any further request to set the window to the same size will be aborted early because Gecko thinks that we already have that requested size.

Emilio, can you please check if that is correct? We should probably move this bug to Core :: Widget : Gtk.

Flags: needinfo?(emilio)

Emilio Cobos Álvarez [:emilio]

Assignee

Comment 7

•

1 year ago

We don't think the window was resized, mLastSizeRequest is just that, the last size that got requested. But we remember that we last asked for an 800x600 window and it didn't get honored, so we don't try again.

In that log you quote there, we try to resize to 800x600, and the compositor just ignores it it seems, since we get a configure with the old size here afterwards, when we move the window.

Flags: needinfo?(emilio)

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Comment 8

•

1 year ago

(In reply to Emilio Cobos Álvarez (:emilio) from comment #7)

We don't think the window was resized, mLastSizeRequest is just that, the last size that got requested. But we remember that we last asked for an 800x600 window and it didn't get honored, so we don't try again.

This is unfortunate. In our wdspec test suite we use 800x600 as the default window size that we want resize to during teardown. If a test modifies the value to some other dimension and that gets accepted, but the next request for 800x600 is failing, all the following tests will operate on the window with the former dimension, which can certainly have an impact on test results like with wrapping. I assume there is no chance to get around that?

In that log you quote there, we try to resize to 800x600, and the compositor just ignores it it seems, since we get a configure with the old size here afterwards, when we move the window.

Given that it fails so rarely I actually wonder if that is a one-time ignorance or would happen every time we are trying to set the dimension. Is there a way (maybe some other logs) to figure out why the compositor might have ignored the request?

Flags: needinfo?(emilio)

Emilio Cobos Álvarez [:emilio]

Assignee

Comment 9

•

1 year ago

Do you know if the request was in an odd state like window minimized, or out of focus or something? Not sure without reproducing it otherwise.

Flags: needinfo?(emilio)

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Updated

•

1 year ago

Blocks: 1977154

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Comment 10

•

1 year ago

(In reply to Emilio Cobos Álvarez (:emilio) from comment #9)

Do you know if the request was in an odd state like window minimized, or out of focus or something? Not sure without reproducing it otherwise.

No, it's happening as well for the first call after Firefox was started the very first time on the worker, and then it continues across the whole job in CI even through we are restarting Firefox at certain times. Because of that behavior I was assuming that the worker has some bad configuration, setting, or status.

https://treeherder.mozilla.org/logviewer?job_id=522384211&repo=try&lineNumber=1826-1838

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Updated

•

1 year ago

Severity: -- → S3

Priority: -- → P3

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Comment 11

•

1 year ago

With widget logs it seems like we get more details:
https://treeherder.mozilla.org/logviewer?job_id=522734153&repo=try&task=EefRp4C3ROWiGBRTJ9lydA.0&lineNumber=1876-1922

[task 2025-08-18T11:44:23.703+00:00] 11:44:23     INFO - PID 1306 | 1755517463700	Marionette	DEBUG	0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2025-08-18T11:44:23.708+00:00] 11:44:23     INFO - PID 1306 | 1755517463705	RemoteAgent	TRACE	Checking window geometry 1280x1077 @ (66, 32)
[task 2025-08-18T11:44:23.710+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: D/Widget [7fea5681c600]: nsWindow::SetSizeMode 0
[task 2025-08-18T11:44:23.713+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: D/Widget [7fea5681c600]:     already set
[task 2025-08-18T11:44:23.713+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: D/Widget [7fea5681c600]: nsWindow::Resize 800.000000 600.000000
[task 2025-08-18T11:44:23.715+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: D/Widget [7fea5681c600]: nsWindow::ResizeInt w:800 h:600
[task 2025-08-18T11:44:23.717+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: D/Widget [7fea5681c600]:   ConstrainSize: w:800 h;600
[task 2025-08-18T11:44:23.719+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: D/Widget [7fea5681c600]:   resized 1 aSize [800, 600] mLastSizeRequest [1280, 1077] mBounds [1280, 1077]
[..]
[task 2025-08-18T11:44:23.765+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: D/Widget [7fea5681c600]: nsWindow::RequestRepaint()
[task 2025-08-18T11:44:23.838+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: V/Widget [7fea5681c600]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-18T11:44:23.839+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: V/Widget [7fea5681c600]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-18T11:44:23.841+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: V/Widget [7fea5681c600]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-18T11:44:23.843+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: V/Widget [7fea5681c600]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-18T11:44:23.845+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: V/Widget [7fea5681c600]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-18T11:44:23.845+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: V/Widget [7fea5681c600]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-18T11:44:23.850+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: V/Widget [7fea5681c600]: nsWindow::GdkCeiledScaleFactor(): ceiled scale 1
[task 2025-08-18T11:44:23.853+00:00] 11:44:23     INFO - PID 1306 | [Parent 1337: Main Thread]: D/Widget [7fea5681c600]: redirect painting to OMTC rendering...
[task 2025-08-18T11:44:24.217+00:00] 11:44:24     INFO - PID 1306 | 1755517464216	RemoteAgent	TRACE	Received DOM event resize for [object Window]
[task 2025-08-18T11:44:24.220+00:00] 11:44:24     INFO - PID 1306 | 1755517464216	RemoteAgent	TRACE	Checking window geometry 800x600 @ (66, 32)
[task 2025-08-18T11:44:24.221+00:00] 11:44:24     INFO - PID 1306 | 1755517464216	RemoteAgent	TRACE	Requested window geometry matches
[task 2025-08-18T11:44:24.231+00:00] 11:44:24     INFO - PID 1306 | [Parent 1337: Main Thread]: D/Widget [7fea5681c600]: MaybeRecomputeBounds 0
[task 2025-08-18T11:44:24.243+00:00] 11:44:24     INFO - PID 1306 | 1755517464235	Marionette	DEBUG	0 <- [1,2,null,{"x":66,"y":32,"width":800,"height":600}]

Emilio, there is a big gap right after redirect painting to OMTC rendering which seems to be related to the startup issue you found and reported on 1965637. Could this be the case? If yes, we will generally have the problem of slow rendering whenever the window size is changing.

Flags: needinfo?(emilio)

Emilio Cobos Álvarez [:emilio]

Assignee

Comment 12

•

1 year ago

Seems unlikely if it happens for every window resize. A profile would be great.

Flags: needinfo?(emilio)

Kash Shampur [:kshampur] ⌚EST

Updated

•

20 days ago

Updated

•

20 days ago

Comment 13

•

18 days ago

Attached file Diagnostic log snippet. — Details

Ok, so I tracked this down on CI, since Kush was seeing unconditional tresize timeouts, see bug 2008057. It seems like a Mutter bug, since the GTK frame clock is stuck at 1, see the attached snippet log.

Relevant section of the diagnostic patch:

+void nsWindow::LogFrameClockState() {
+#ifdef MOZ_LOGGING
+  if (!LOG_ENABLED() || !mShell) {
+    return;
+  }
+  GdkFrameClock* clock = gtk_widget_get_frame_clock(GTK_WIDGET(mShell));
+  if (!clock) {
+    LOG("  frame clock: none");
+    return;
+  }
+  // If the counter stops advancing across resize requests, GTK's frame clock
+  // is frozen (waiting for _NET_WM_FRAME_DRAWN or a ConfigureNotify) and
+  // gtk_window_resize() requests are never flushed to X (bug 1982990).
+  LOG("  frame clock: counter %lld frame time %lld us",
+      (long long)gdk_frame_clock_get_frame_counter(clock),
+      (long long)gdk_frame_clock_get_frame_time(clock));
+#endif
+}

GTK has some opt out for frame synchronization which would work here. Using gdk_window_resize would also work (since it bypasses the gtk_window_resize sync) but seems a bit more risky.

Emilio Cobos Álvarez [:emilio]

Assignee

Comment 14

•

18 days ago

Attached file Bug 1982990 - Skip GDK frame clock synchronization on X11. r=stransky! — Details

See the comments on the bug. The TLDR is that gtk_window_resize waits
for the GTK frame clock via gtk_widget_queue_resize_no_redraw:

https://gitlab.gnome.org/GNOME/gtk/-/blob/b30343717dc9b02cf157d2ea87da585d8d518845/gtk/gtkwindow.c#L5436

On automation that never advances (that waits for _NET_WM_FRAME_DRAWN,
and the counter is stuck at 1...). Since GTK has an opt-out for this
precise mechanism, and the benefit we get from it seems not-huge, I
think this is probably the least risky?

Alternatives would be:

Try to get an updated mutter on CI or so, in case this is fixed in
the ubuntu repos already (hopefully?).
Go through gdk_window_resize rather than gtk_window_resize on X11,
which skips the gtk wait and does a direct X11 request. That is
closer to what gtk_window_move does, but I'm a bit worried about some
GTK state getting out of sync due to that.

Phabricator Automation

Updated

•

18 days ago

Assignee: nobody → emilio

Status: NEW → ASSIGNED

Emilio Cobos Álvarez [:emilio]

Assignee

Updated

•

18 days ago

Blocks: 2008057

Comment 15

•

18 days ago

https://treeherder.mozilla.org/jobs?repo=try&landoInstance=lando-prod-2025&landoCommitID=87546 is talos with the last version (xpc::IsInAutomation()), because I'm not 100% sure that'd return true there.

https://treeherder.mozilla.org/jobs?repo=try&revision=0585a8aef21882a93d91a0e39ad05be995defb60 is a green try run with the previous (unconditional version) and https://treeherder.mozilla.org/jobs?repo=try&revision=5cd85735373cc7a3a9d4602235b95080fe0b640b a try run with talos tresize that enabled unconditionally.

Pulsebot

Comment 16

•

18 days ago

Pushed by ealvarez@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/571e8708dd06 https://hg.mozilla.org/integration/autoland/rev/51bc57dbb9e4 Skip GDK frame clock synchronization on X11. r=stransky,gtk-reviewers

Sandor Molnar[:smolnar]

Comment 17

•

17 days ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/51bc57dbb9e4

Status: ASSIGNED → RESOLVED

Closed: 17 days ago

status-firefox157: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 157 Branch

Henrik Skupin [:whimboo][⌚️UTC+2]

Reporter

Comment 18

•

15 days ago

Moving bug to Core :: Widget: GTK given that the landed fix is outside of the Remote Agent. Thanks Emilio!

Component: Agent → Widget: Gtk

Product: Remote Protocol → Core

Kash Shampur [:kshampur] ⌚EST

Updated

•

14 days ago

Blocks: 2008059

Updated

•

8 days ago

QA Whiteboard: [qa-triage-done-c158/b157]

Diagnostic log snippet. 18 days ago Emilio Cobos Álvarez [:emilio] 6.69 KB, text/plain		Details
Bug 1982990 - Skip GDK frame clock synchronization on X11. r=stransky! 18 days ago Emilio Cobos Álvarez [:emilio] 48 bytes, text/x-phabricator-request		Details \| Review