1891766 - Perma Linux 18.04 x64 WebRender asan opt canvas [taskcluster:error] Task timeout after 1800 seconds. Force killing container (with patches from bug 1522790 applied)

Reporter

Description

•

10 months ago

treeherder

Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=454710056&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/C_LDio8cSc63eDAQz3xZSA/runs/0/artifacts/public/logs/live_backing.log

[task 2024-04-16T14:45:39.222Z] 14:45:39     INFO - TEST-OK | /html/canvas/element/text/2d.text.draw.fill.maxWidth.zero.html | took 1642ms
[task 2024-04-16T14:45:39.223Z] 14:45:39     INFO - TEST-START | /html/canvas/element/text/2d.text.draw.fill.unaffected.html
[task 2024-04-16T14:45:39.282Z] 14:45:39     INFO - Closing window b69d6963-7589-4099-90d8-65f8842ecf4b
[task 2024-04-16T14:45:39.750Z] 14:45:39     INFO - PID 998 | -----------------------------------------------------
[task 2024-04-16T14:45:39.752Z] 14:45:39     INFO - PID 998 | Suppressions used:
[task 2024-04-16T14:45:39.752Z] 14:45:39     INFO - PID 998 |   count      bytes template
[task 2024-04-16T14:45:39.753Z] 14:45:39     INFO - PID 998 |      31      16288 nsComponentManagerImpl
[task 2024-04-16T14:45:39.754Z] 14:45:39     INFO - PID 998 |       2        288 libfontconfig.so
[task 2024-04-16T14:45:39.756Z] 14:45:39     INFO - PID 998 |       1       9248 style::sharing::SHARING_CACHE_KEY
[task 2024-04-16T14:45:39.757Z] 14:45:39     INFO - PID 998 |       1       4112 style::bloom::BLOOM_KEY
[task 2024-04-16T14:45:39.758Z] 14:45:39     INFO - PID 998 | -----------------------------------------------------
[task 2024-04-16T14:45:39.985Z] 14:45:39     INFO - PID 998 | -----------------------------------------------------
[task 2024-04-16T14:45:39.986Z] 14:45:39     INFO - PID 998 | Suppressions used:
[task 2024-04-16T14:45:39.986Z] 14:45:39     INFO - PID 998 |   count      bytes template
[task 2024-04-16T14:45:39.986Z] 14:45:39     INFO - PID 998 |      31      16288 nsComponentManagerImpl
[task 2024-04-16T14:45:39.986Z] 14:45:39     INFO - PID 998 |       2        288 libfontconfig.so
[task 2024-04-16T14:45:39.986Z] 14:45:39     INFO - PID 998 |       1       9248 style::sharing::SHARING_CACHE_KEY
[task 2024-04-16T14:45:39.986Z] 14:45:39     INFO - PID 998 |       1       4112 style::bloom::BLOOM_KEY
[task 2024-04-16T14:45:39.986Z] 14:45:39     INFO - PID 998 | -----------------------------------------------------
[taskcluster:error] Task timeout after 1800 seconds. Force killing container.
[taskcluster 2024-04-16 14:45:41.802Z] === Task Finished ===
[taskcluster 2024-04-16 14:45:41.802Z] Unsuccessful task run with exit code: -1 completed in 1802.203 seconds

Serban Stanca [:SerbanS]

Updated

•

10 months ago

Severity: S4 → --

Flags: needinfo?(hskupin)

Priority: P5 → --

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

Assignee

Comment 1

•

10 months ago

•

Edited

Lets move to web-platform tests for now given that bug 1522790 is making changes in that component.

I tried to run ASAN builds locally on my Mac but I wasn't able to because of perma crashes during startup (see bug 1874251). As such I decided to push a try build with the Marionette trace logs enabled for now to see where we are spending most of the time. Maybe the logs will be helpful. If not I might have to find a way to do some gecko profiler runs.

Component: General → web-platform-tests

Product: Firefox Build System → Testing

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

Assignee

Comment 2

•

10 months ago

Please note that a backout has been requested. Once done we can flip the dependency in blocking bug 1522790 because it needs to be investigated and fixed if necessary before a re-landing of the patches.

Flags: needinfo?(hskupin)

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

Assignee

Comment 3

•

10 months ago

•

Edited

For now here the trace logs from Marionette as comparison between the old and the new behavior. As it can be seen the test duration increased from 320ms to 1656ms, which is around 5x slower.

Without the change: /html/canvas/element/shadows/2d.shadow.transform.1.html | took 320ms

1713295496720	Marionette	DEBUG	2 -> [0,15218,"Marionette:GetContext",{}]
1713295496720	Marionette	DEBUG	2 <- [1,15218,null,{"value":"content"}]
1713295496722	Marionette	DEBUG	2 -> [0,15219,"Marionette:SetContext",{"value":"content"}]
1713295496722	Marionette	DEBUG	2 <- [1,15219,null,{"value":null}]
1713295496724	Marionette	DEBUG	2 -> [0,15220,"WebDriver:GetWindowHandles",{}]
1713295496724	Marionette	DEBUG	2 <- [1,15220,null,["1760ffe9-666d-4a9e-8624-d29231c5c13f","2d21538b-bf71-4706-9230-bcfc86da3e10"]]
1713295496726	Marionette	DEBUG	2 -> [0,15221,"Marionette:SetContext",{"value":"content"}]
1713295496726	Marionette	DEBUG	2 <- [1,15221,null,{"value":null}]
1713295496728	Marionette	DEBUG	2 -> [0,15222,"WebDriver:SwitchToWindow",{"handle":"2d21538b-bf71-4706-9230-bcfc86da3e10","name":"2d21538b-bf71-4706-9230-bcfc86da3e10","focus":true}]
1713295496729	Marionette	DEBUG	2 <- [1,15222,null,{"value":null}]
1713295496735	Marionette	DEBUG	2 -> [0,15223,"WebDriver:CloseWindow",{}]
1713295496745	RemoteAgent	TRACE	Received DOM event TabClose for [object XULElement]
1713295496757	Marionette	TRACE	[10737418596] MarionetteCommands actor destroyed for window id 10737420020
1713295496758	Marionette	TRACE	[914] MarionetteCommands actor destroyed for window id 10737420021
1713295496764	Marionette	TRACE	Received observer notification message-manager-disconnect
1713295496766	Marionette	TRACE	Received observer notification message-manager-disconnect
1713295496767	Marionette	DEBUG	2 <- [1,15223,null,["1760ffe9-666d-4a9e-8624-d29231c5c13f"]]
1713295496771	Marionette	DEBUG	2 -> [0,15224,"WebDriver:SwitchToWindow",{"handle":"1760ffe9-666d-4a9e-8624-d29231c5c13f","name":"1760ffe9-666d-4a9e-8624-d29231c5c13f","focus":true}]
1713295496773	Marionette	DEBUG	2 <- [1,15224,null,{"value":null}]
1713295496784	Marionette	DEBUG	2 -> [0,15225,"WebDriver:ExecuteScript",{"script":"window.open('about:blank', '1c3d1920-d3c9-436a-9a43-1604ca05d24c', 'noopener')","args":[],"newSandbox":false,"sandbox":null,"line":94,"filename":"tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py"}]
1713295496854	Marionette	DEBUG	2 <- [1,15225,null,{"value":null}]
1713295496856	Marionette	DEBUG	2 -> [0,15226,"Marionette:GetContext",{}]
1713295496856	Marionette	DEBUG	2 <- [1,15226,null,{"value":"content"}]
1713295496857	Marionette	DEBUG	2 -> [0,15227,"Marionette:SetContext",{"value":"content"}]
1713295496857	Marionette	DEBUG	2 <- [1,15227,null,{"value":null}]
1713295496858	Marionette	DEBUG	2 -> [0,15228,"WebDriver:GetWindowHandles",{}]
1713295496858	Marionette	DEBUG	2 <- [1,15228,null,["1760ffe9-666d-4a9e-8624-d29231c5c13f","985d9054-6b8a-417e-af30-423d9165ebfd"]]
1713295496859	Marionette	DEBUG	2 -> [0,15229,"Marionette:SetContext",{"value":"content"}]
1713295496859	Marionette	DEBUG	2 <- [1,15229,null,{"value":null}]
1713295496861	Marionette	DEBUG	2 -> [0,15230,"WebDriver:SwitchToWindow",{"handle":"985d9054-6b8a-417e-af30-423d9165ebfd","name":"985d9054-6b8a-417e-af30-423d9165ebfd","focus":true}]
1713295496863	Marionette	DEBUG	2 <- [1,15230,null,{"value":null}]
1713295496867	Marionette	DEBUG	2 -> [0,15231,"WebDriver:ExecuteAsyncScript",{"script":"const [resolve] = arguments;\n\nif (document.readyState != \"complete\") {\n  window.addEventListener(\"load\", () => {\n    resolve();\n  }, { once: true });\n} else {\n  resolve();\n}","args":[],"newSandbox":false,"sandbox":null,"scriptTimeout":null,"line":94,"filename":"tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py"}]
1713295496872	Marionette	TRACE	[10737418597] MarionetteCommands actor created for window id 10737420025
1713295496879	Marionette	DEBUG	2 <- [1,15231,null,{"value":null}]
1713295496881	Marionette	DEBUG	2 -> [0,15232,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/html/canvas/element/shadows/2d.shadow.transform.1.html"}]
1713295496886	Marionette	TRACE	[10737418597] Received event beforeunload for about:blank
1713295496906	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 915
1713295496919	Marionette	TRACE	[915] Received event beforeunload for about:blank
1713295496923	Marionette	TRACE	[915] Received event pagehide for about:blank
1713295497014	Marionette	TRACE	[915] Received event DOMContentLoaded for http://web-platform.test:8000/html/canvas/element/shadows/2d.shadow.transform.1.html
1713295497015	Marionette	DEBUG	2 <- [1,15232,null,{"value":null}]
1713295497017	Marionette	DEBUG	2 -> [0,15233,"WebDriver:ExecuteAsyncScript",{"script":"// We have to set the url here to ensure we get the same escaping as in the harness\n// and also to handle the case where the test changes the fragment\nwindow.__wptrunner_url = arguments[0];\nwindow.__wptrunner_testdriver_callback = arguments[arguments.length - 1];\nwindow.__wptrunner_process_next_event();","args":["/html/canvas/element/shadows/2d.shadow.transform.1.html"],"newSandbox":false,"sandbox":null,"scriptTimeout":null,"line":94,"filename":"tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py"}]
1713295497028	Marionette	TRACE	[915] MarionetteCommands actor created for window id 10737420026
1713295497036	Marionette	DEBUG	2 <- [1,15233,null,{"value":["/html/canvas/element/shadows/2d.shadow.transform.1.html","complete",[0,null,null,[["Shadows take account of transformations",0,null,null]]]]}]

With the change: /html/canvas/element/shadows/2d.shadow.transform.1.html | took 1656ms

1713297337770	Marionette	DEBUG	2 -> [0,10479,"Marionette:GetContext",{}]
1713297337770	Marionette	DEBUG	2 <- [1,10479,null,{"value":"content"}]
1713297337771	Marionette	DEBUG	2 -> [0,10480,"Marionette:SetContext",{"value":"content"}]
1713297337771	Marionette	DEBUG	2 <- [1,10480,null,{"value":null}]
1713297337772	Marionette	DEBUG	2 -> [0,10481,"WebDriver:GetWindowHandles",{}]
1713297337773	Marionette	DEBUG	2 <- [1,10481,null,["c881f87f-9359-4d4a-b682-520e8d120845","c401a14f-a1a7-43f3-9d1f-36b1295480f7"]]
1713297337774	Marionette	DEBUG	2 -> [0,10482,"Marionette:SetContext",{"value":"content"}]
1713297337774	Marionette	DEBUG	2 <- [1,10482,null,{"value":null}]
1713297337776	Marionette	DEBUG	2 -> [0,10483,"WebDriver:SwitchToWindow",{"handle":"c401a14f-a1a7-43f3-9d1f-36b1295480f7","name":"c401a14f-a1a7-43f3-9d1f-36b1295480f7","focus":true}]
1713297337777	Marionette	DEBUG	2 <- [1,10483,null,{"value":null}]
1713297337778	Marionette	DEBUG	2 -> [0,10484,"WebDriver:CloseWindow",{}]
1713297337804	RemoteAgent	TRACE	Received DOM event TabClose for [object XULElement]
1713297337864	Marionette	TRACE	[1912] MarionetteCommands actor destroyed for window id 4090956349441
1713297337931	Marionette	TRACE	Received observer notification message-manager-disconnect
1713297337931	Marionette	DEBUG	2 <- [1,10484,null,["c881f87f-9359-4d4a-b682-520e8d120845"]]
1713297337978	Marionette	DEBUG	2 -> [0,10485,"WebDriver:SwitchToWindow",{"handle":"c881f87f-9359-4d4a-b682-520e8d120845","name":"c881f87f-9359-4d4a-b682-520e8d120845","focus":true}]
1713297337978	Marionette	DEBUG	2 <- [1,10485,null,{"value":null}]
1713297337982	Marionette	DEBUG	2 -> [0,10486,"WebDriver:NewWindow",{"type":"tab","focus":true,"private":false}]
1713297337998	RemoteAgent	TRACE	Received DOM event TabOpen for [object XULElement]
1713297338181	RemoteAgent	TRACE	[1913] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
1713297338181	RemoteAgent	TRACE	[1913] ProgressListener Setting unload timer (40000ms)
1713297338183	RemoteAgent	TRACE	[1913] ProgressListener Check loading state: isStart=1 isStop=0
1713297338183	RemoteAgent	TRACE	[1913] ProgressListener state=start: about:blank
1713297338184	RemoteAgent	TRACE	[1913] ProgressListener Cleared the unload timer
1713297338195	RemoteAgent	TRACE	[1913] ProgressListener Check loading state: isStart=0 isStop=16
1713297338195	RemoteAgent	TRACE	[1913] ProgressListener Ignore aborted navigation error to the initial document, real document will be loaded.
1713297338197	RemoteAgent	TRACE	[1913] ProgressListener Check loading state: isStart=1 isStop=0
1713297338357	RemoteAgent	TRACE	[1913] ProgressListener Check loading state: isStart=0 isStop=16
1713297338365	RemoteAgent	TRACE	[1913] ProgressListener state=stop: about:blank
1713297338367	RemoteAgent	TRACE	[1913] ProgressListener Stop: has error=false
1713297338377	Marionette	DEBUG	2 <- [1,10486,null,{"handle":"80f2af24-fb24-4ae1-b427-621a08faa9a0","type":"tab"}]
1713297338422	Marionette	DEBUG	2 -> [0,10487,"WebDriver:SwitchToWindow",{"handle":"80f2af24-fb24-4ae1-b427-621a08faa9a0","name":"80f2af24-fb24-4ae1-b427-621a08faa9a0","focus":true}]
1713297338457	Marionette	DEBUG	2 <- [1,10487,null,{"value":null}]
1713297338482	Marionette	DEBUG	2 -> [0,10488,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/html/canvas/element/shadows/2d.shadow.transform.1.html"}]
1713297338497	Marionette	TRACE	[1913] Received event beforeunload for about:blank
1713297338549	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 1914
1713297338590	Marionette	TRACE	[1914] Received event beforeunload for about:blank
1713297338612	Marionette	TRACE	[1914] Received event pagehide for about:blank
1713297339210	Marionette	TRACE	[1914] Received event DOMContentLoaded for http://web-platform.test:8000/html/canvas/element/shadows/2d.shadow.transform.1.html
1713297339212	Marionette	DEBUG	2 <- [1,10488,null,{"value":null}]
1713297339285	Marionette	DEBUG	2 -> [0,10489,"WebDriver:ExecuteAsyncScript",{"script":"// We have to set the url here to ensure we get the same escaping as in the harness\n// and also to handle the case where the test changes the fragment\nwindow.__wptrunner_url = arguments[0];\nwindow.__wptrunner_testdriver_callback = arguments[arguments.length - 1];\nwindow.__wptrunner_process_next_event();","args":["/html/canvas/element/shadows/2d.shadow.transform.1.html"],"newSandbox":false,"sandbox":null,"scriptTimeout":null,"line":94,"filename":"tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py"}]
1713297339307	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 27721
1713297339343	Marionette	TRACE	[1914] MarionetteCommands actor created for window id 4095251316737

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

Assignee

Comment 4

•

10 months ago

Lets not track this bug as regression but as a blocker for the patches on bug 1522790 to get landed.

Blocks: 1522790

Keywords: intermittent-failure, intermittent-testcase, regression

No longer regressed by: 1522790

Summary: Perma Linux 18.04 x64 WebRender asan opt canvas [taskcluster:error] Task timeout after 1800 seconds. Force killing container. → Perma Linux 18.04 x64 WebRender asan opt canvas [taskcluster:error] Task timeout after 1800 seconds. Force killing container (with patches from bug 1522790 applied)

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

Assignee

Comment 5

•

10 months ago

I'm also not able to run ASAN builds locally on Linux due to bug 1891991.

Comment 6

•

10 months ago

Time durations from various Marionette commands that have noticeable differences in the log as pasted in comment 3:

WebDriver:CloseWindow: 32ms vs. 153ms
WebDriver:ExecuteScript (window.open) vs. WebDriver:NewWindow: 95 ms vs. 469ms
WebDriver:Navigate: 134ms vs. 730ms

As it looks like most of the extra time is spent here for navigation which seems to be slow overall.

Checking earlier tests in the log shows that the very first test has the same duration, but starting with the second one we can see the slowness.

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

Assignee

Comment 7

•

10 months ago

Here are two profiles generated by running an ASAN build locally:

Without the patch using window.open(): https://share.firefox.dev/4aFQIkO
With the patch using Marionette:NewWindow: https://share.firefox.dev/3QbYBX1

Comment hidden (Intermittent Failures Robot)

BugBot [:suhaib / :marco/ :calixte]

Comment 9

•

9 months ago

The severity field is not set for this bug.
:jgraham, could you have a look please?

For more information, please visit BugBot documentation.

Flags: needinfo?(james)

James Graham [:jgraham]

Updated

•

9 months ago

Severity: -- → S3

Flags: needinfo?(james)

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

Assignee

Comment 10

•

9 months ago

As a workaround for now we could consider to add another parameter to the new window command of Marionette which allows clients to not have to wait for the initial about:blank page to be loaded. Lets see if this makes a difference for ASAN builds. I've pushed a try build:

https://treeherder.mozilla.org/jobs?repo=try&revision=dcee5ad5289c98d3764895a1ea2f4aee03148898

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

Assignee

Comment 11

•

8 months ago

I actually missed to comment here, but this workaround doesn't help as well. This needs further investigation.

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

Assignee

Comment 12

•

5 months ago

The problem was identified on bug 1914191 and I'm going to wait for the patches to land before pushing my patch from bug 1522790 again. That means we should not run into this issue anymore.

Given that the originally happening perma failure doesn't exist anymore lets close this bug.

Assignee: nobody → hskupin

Status: NEW → RESOLVED

Closed: 5 months ago

Resolution: --- → FIXED

Bugzilla

Perma Linux 18.04 x64 WebRender asan opt canvas [taskcluster:error] Task timeout after 1800 seconds. Force killing container (with patches from bug 1522790 applied)

Categories

(Testing :: web-platform-tests, defect)

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

Details

Crash Data

Security

(public)

User Story

Description

Updated

Comment 1

Comment 2

Comment 3

Comment 4

Comment 5

Comment 6

Comment 7

Comment 8

Comment 9

Updated

Comment 10

Comment 11

Comment 12