Bug 1891766 Comment 3 Edit History

Note: The actual edited comment in the bug view page will always show the original commenter’s name and original timestamp.

Original comment by

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

on 2024-04-17 01:11:57 PDT

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](https://treeherder.mozilla.org/logviewer?job_id=454737879&repo=try&lineNumber=47085-47132)
```
[task 2024-04-16T19:24:56.719Z] 19:24:56     INFO - TEST-START | /html/canvas/element/shadows/2d.shadow.transform.1.html
[task 2024-04-16T19:24:56.721Z] 19:24:56     INFO - PID 996 | 1713295496720	Marionette	DEBUG	2 -> [0,15218,"Marionette:GetContext",{}]
[task 2024-04-16T19:24:56.721Z] 19:24:56     INFO - PID 996 | 1713295496720	Marionette	DEBUG	2 <- [1,15218,null,{"value":"content"}]
[task 2024-04-16T19:24:56.722Z] 19:24:56     INFO - PID 996 | 1713295496722	Marionette	DEBUG	2 -> [0,15219,"Marionette:SetContext",{"value":"content"}]
[task 2024-04-16T19:24:56.723Z] 19:24:56     INFO - PID 996 | 1713295496722	Marionette	DEBUG	2 <- [1,15219,null,{"value":null}]
[task 2024-04-16T19:24:56.725Z] 19:24:56     INFO - PID 996 | 1713295496724	Marionette	DEBUG	2 -> [0,15220,"WebDriver:GetWindowHandles",{}]
[task 2024-04-16T19:24:56.726Z] 19:24:56     INFO - PID 996 | 1713295496724	Marionette	DEBUG	2 <- [1,15220,null,["1760ffe9-666d-4a9e-8624-d29231c5c13f","2d21538b-bf71-4706-9230-bcfc86da3e10"]]
[task 2024-04-16T19:24:56.727Z] 19:24:56     INFO - PID 996 | 1713295496726	Marionette	DEBUG	2 -> [0,15221,"Marionette:SetContext",{"value":"content"}]
[task 2024-04-16T19:24:56.727Z] 19:24:56     INFO - PID 996 | 1713295496726	Marionette	DEBUG	2 <- [1,15221,null,{"value":null}]
[task 2024-04-16T19:24:56.728Z] 19:24:56     INFO - Closing window 2d21538b-bf71-4706-9230-bcfc86da3e10
[task 2024-04-16T19:24:56.729Z] 19:24:56     INFO - PID 996 | 1713295496728	Marionette	DEBUG	2 -> [0,15222,"WebDriver:SwitchToWindow",{"handle":"2d21538b-bf71-4706-9230-bcfc86da3e10","name":"2d21538b-bf71-4706-9230-bcfc86da3e10","focus":true}]
[task 2024-04-16T19:24:56.730Z] 19:24:56     INFO - PID 996 | 1713295496729	Marionette	DEBUG	2 <- [1,15222,null,{"value":null}]
[task 2024-04-16T19:24:56.752Z] 19:24:56     INFO - PID 996 | 1713295496735	Marionette	DEBUG	2 -> [0,15223,"WebDriver:CloseWindow",{}]
[task 2024-04-16T19:24:56.753Z] 19:24:56     INFO - PID 996 | 1713295496745	RemoteAgent	TRACE	Received DOM event TabClose for [object XULElement]
[task 2024-04-16T19:24:56.759Z] 19:24:56     INFO - PID 996 | 1713295496757	Marionette	TRACE	[10737418596] MarionetteCommands actor destroyed for window id 10737420020
[task 2024-04-16T19:24:56.760Z] 19:24:56     INFO - PID 996 | 1713295496758	Marionette	TRACE	[914] MarionetteCommands actor destroyed for window id 10737420021
[task 2024-04-16T19:24:56.765Z] 19:24:56     INFO - PID 996 | 1713295496764	Marionette	TRACE	Received observer notification message-manager-disconnect
[task 2024-04-16T19:24:56.768Z] 19:24:56     INFO - PID 996 | 1713295496766	Marionette	TRACE	Received observer notification message-manager-disconnect
[task 2024-04-16T19:24:56.768Z] 19:24:56     INFO - PID 996 | 1713295496767	Marionette	DEBUG	2 <- [1,15223,null,["1760ffe9-666d-4a9e-8624-d29231c5c13f"]]
[task 2024-04-16T19:24:56.772Z] 19:24:56     INFO - PID 996 | 1713295496771	Marionette	DEBUG	2 -> [0,15224,"WebDriver:SwitchToWindow",{"handle":"1760ffe9-666d-4a9e-8624-d29231c5c13f","name":"1760ffe9-666d-4a9e-8624-d29231c5c13f","focus":true}]
[task 2024-04-16T19:24:56.774Z] 19:24:56     INFO - PID 996 | 1713295496773	Marionette	DEBUG	2 <- [1,15224,null,{"value":null}]
[task 2024-04-16T19:24:56.786Z] 19:24:56     INFO - PID 996 | 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"}]
[task 2024-04-16T19:24:56.855Z] 19:24:56     INFO - PID 996 | 1713295496854	Marionette	DEBUG	2 <- [1,15225,null,{"value":null}]
[task 2024-04-16T19:24:56.857Z] 19:24:56     INFO - PID 996 | 1713295496856	Marionette	DEBUG	2 -> [0,15226,"Marionette:GetContext",{}]
[task 2024-04-16T19:24:56.858Z] 19:24:56     INFO - PID 996 | 1713295496856	Marionette	DEBUG	2 <- [1,15226,null,{"value":"content"}]
[task 2024-04-16T19:24:56.859Z] 19:24:56     INFO - PID 996 | 1713295496857	Marionette	DEBUG	2 -> [0,15227,"Marionette:SetContext",{"value":"content"}]
[task 2024-04-16T19:24:56.860Z] 19:24:56     INFO - PID 996 | 1713295496857	Marionette	DEBUG	2 <- [1,15227,null,{"value":null}]
[task 2024-04-16T19:24:56.862Z] 19:24:56     INFO - PID 996 | 1713295496858	Marionette	DEBUG	2 -> [0,15228,"WebDriver:GetWindowHandles",{}]
[task 2024-04-16T19:24:56.862Z] 19:24:56     INFO - PID 996 | 1713295496858	Marionette	DEBUG	2 <- [1,15228,null,["1760ffe9-666d-4a9e-8624-d29231c5c13f","985d9054-6b8a-417e-af30-423d9165ebfd"]]
[task 2024-04-16T19:24:56.862Z] 19:24:56     INFO - PID 996 | 1713295496859	Marionette	DEBUG	2 -> [0,15229,"Marionette:SetContext",{"value":"content"}]
[task 2024-04-16T19:24:56.862Z] 19:24:56     INFO - PID 996 | 1713295496859	Marionette	DEBUG	2 <- [1,15229,null,{"value":null}]
[task 2024-04-16T19:24:56.862Z] 19:24:56     INFO - PID 996 | 1713295496861	Marionette	DEBUG	2 -> [0,15230,"WebDriver:SwitchToWindow",{"handle":"985d9054-6b8a-417e-af30-423d9165ebfd","name":"985d9054-6b8a-417e-af30-423d9165ebfd","focus":true}]
[task 2024-04-16T19:24:56.865Z] 19:24:56     INFO - PID 996 | 1713295496863	Marionette	DEBUG	2 <- [1,15230,null,{"value":null}]
[task 2024-04-16T19:24:56.869Z] 19:24:56     INFO - PID 996 | 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"}]
[task 2024-04-16T19:24:56.873Z] 19:24:56     INFO - PID 996 | 1713295496872	Marionette	TRACE	[10737418597] MarionetteCommands actor created for window id 10737420025
[task 2024-04-16T19:24:56.881Z] 19:24:56     INFO - PID 996 | 1713295496879	Marionette	DEBUG	2 <- [1,15231,null,{"value":null}]
[task 2024-04-16T19:24:56.882Z] 19:24:56     INFO - PID 996 | 1713295496881	Marionette	DEBUG	2 -> [0,15232,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/html/canvas/element/shadows/2d.shadow.transform.1.html"}]
[task 2024-04-16T19:24:56.888Z] 19:24:56     INFO - PID 996 | 1713295496886	Marionette	TRACE	[10737418597] Received event beforeunload for about:blank
[task 2024-04-16T19:24:56.906Z] 19:24:56     INFO - PID 996 | 1713295496906	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 915
[task 2024-04-16T19:24:56.920Z] 19:24:56     INFO - PID 996 | 1713295496919	Marionette	TRACE	[915] Received event beforeunload for about:blank
[task 2024-04-16T19:24:56.924Z] 19:24:56     INFO - PID 996 | 1713295496923	Marionette	TRACE	[915] Received event pagehide for about:blank
[task 2024-04-16T19:24:57.016Z] 19:24:57     INFO - PID 996 | 1713295497014	Marionette	TRACE	[915] Received event DOMContentLoaded for http://web-platform.test:8000/html/canvas/element/shadows/2d.shadow.transform.1.html
[task 2024-04-16T19:24:57.017Z] 19:24:57     INFO - PID 996 | 1713295497015	Marionette	DEBUG	2 <- [1,15232,null,{"value":null}]
[task 2024-04-16T19:24:57.019Z] 19:24:57     INFO - PID 996 | 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"}]
[task 2024-04-16T19:24:57.029Z] 19:24:57     INFO - PID 996 | 1713295497028	Marionette	TRACE	[915] MarionetteCommands actor created for window id 10737420026
[task 2024-04-16T19:24:57.037Z] 19:24:57     INFO - PID 996 | 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](https://treeherder.mozilla.org/logviewer?job_id=454738925&repo=try&lineNumber=63056-63102)
```
[task 2024-04-16T19:55:37.762Z] 19:55:37     INFO - TEST-START | /html/canvas/element/shadows/2d.shadow.transform.1.html
[task 2024-04-16T19:55:37.771Z] 19:55:37     INFO - PID 996 | 1713297337770	Marionette	DEBUG	2 -> [0,10479,"Marionette:GetContext",{}]
[task 2024-04-16T19:55:37.773Z] 19:55:37     INFO - PID 996 | 1713297337770	Marionette	DEBUG	2 <- [1,10479,null,{"value":"content"}]
[task 2024-04-16T19:55:37.775Z] 19:55:37     INFO - PID 996 | 1713297337771	Marionette	DEBUG	2 -> [0,10480,"Marionette:SetContext",{"value":"content"}]
[task 2024-04-16T19:55:37.775Z] 19:55:37     INFO - PID 996 | 1713297337771	Marionette	DEBUG	2 <- [1,10480,null,{"value":null}]
[task 2024-04-16T19:55:37.777Z] 19:55:37     INFO - PID 996 | 1713297337772	Marionette	DEBUG	2 -> [0,10481,"WebDriver:GetWindowHandles",{}]
[task 2024-04-16T19:55:37.777Z] 19:55:37     INFO - PID 996 | 1713297337773	Marionette	DEBUG	2 <- [1,10481,null,["c881f87f-9359-4d4a-b682-520e8d120845","c401a14f-a1a7-43f3-9d1f-36b1295480f7"]]
[task 2024-04-16T19:55:37.777Z] 19:55:37     INFO - PID 996 | 1713297337774	Marionette	DEBUG	2 -> [0,10482,"Marionette:SetContext",{"value":"content"}]
[task 2024-04-16T19:55:37.780Z] 19:55:37     INFO - PID 996 | 1713297337774	Marionette	DEBUG	2 <- [1,10482,null,{"value":null}]
[task 2024-04-16T19:55:37.780Z] 19:55:37     INFO - Closing window c401a14f-a1a7-43f3-9d1f-36b1295480f7
[task 2024-04-16T19:55:37.780Z] 19:55:37     INFO - PID 996 | 1713297337776	Marionette	DEBUG	2 -> [0,10483,"WebDriver:SwitchToWindow",{"handle":"c401a14f-a1a7-43f3-9d1f-36b1295480f7","name":"c401a14f-a1a7-43f3-9d1f-36b1295480f7","focus":true}]
[task 2024-04-16T19:55:37.780Z] 19:55:37     INFO - PID 996 | 1713297337777	Marionette	DEBUG	2 <- [1,10483,null,{"value":null}]
[task 2024-04-16T19:55:37.780Z] 19:55:37     INFO - PID 996 | 1713297337778	Marionette	DEBUG	2 -> [0,10484,"WebDriver:CloseWindow",{}]
[task 2024-04-16T19:55:37.805Z] 19:55:37     INFO - PID 996 | 1713297337804	RemoteAgent	TRACE	Received DOM event TabClose for [object XULElement]
[task 2024-04-16T19:55:37.865Z] 19:55:37     INFO - PID 996 | 1713297337864	Marionette	TRACE	[1912] MarionetteCommands actor destroyed for window id 4090956349441
[task 2024-04-16T19:55:37.932Z] 19:55:37     INFO - PID 996 | 1713297337931	Marionette	TRACE	Received observer notification message-manager-disconnect
[task 2024-04-16T19:55:37.933Z] 19:55:37     INFO - PID 996 | 1713297337931	Marionette	DEBUG	2 <- [1,10484,null,["c881f87f-9359-4d4a-b682-520e8d120845"]]
[task 2024-04-16T19:55:37.979Z] 19:55:37     INFO - PID 996 | 1713297337978	Marionette	DEBUG	2 -> [0,10485,"WebDriver:SwitchToWindow",{"handle":"c881f87f-9359-4d4a-b682-520e8d120845","name":"c881f87f-9359-4d4a-b682-520e8d120845","focus":true}]
[task 2024-04-16T19:55:37.982Z] 19:55:37     INFO - PID 996 | 1713297337978	Marionette	DEBUG	2 <- [1,10485,null,{"value":null}]
[task 2024-04-16T19:55:37.986Z] 19:55:37     INFO - PID 996 | 1713297337982	Marionette	DEBUG	2 -> [0,10486,"WebDriver:NewWindow",{"type":"tab","focus":true,"private":false}]
[task 2024-04-16T19:55:37.999Z] 19:55:37     INFO - PID 996 | 1713297337998	RemoteAgent	TRACE	Received DOM event TabOpen for [object XULElement]
[task 2024-04-16T19:55:38.184Z] 19:55:38     INFO - PID 996 | 1713297338181	RemoteAgent	TRACE	[1913] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
[task 2024-04-16T19:55:38.188Z] 19:55:38     INFO - PID 996 | 1713297338181	RemoteAgent	TRACE	[1913] ProgressListener Setting unload timer (40000ms)
[task 2024-04-16T19:55:38.189Z] 19:55:38     INFO - PID 996 | 1713297338183	RemoteAgent	TRACE	[1913] ProgressListener Check loading state: isStart=1 isStop=0
[task 2024-04-16T19:55:38.190Z] 19:55:38     INFO - PID 996 | 1713297338183	RemoteAgent	TRACE	[1913] ProgressListener state=start: about:blank
[task 2024-04-16T19:55:38.190Z] 19:55:38     INFO - PID 996 | 1713297338184	RemoteAgent	TRACE	[1913] ProgressListener Cleared the unload timer
[task 2024-04-16T19:55:38.197Z] 19:55:38     INFO - PID 996 | 1713297338195	RemoteAgent	TRACE	[1913] ProgressListener Check loading state: isStart=0 isStop=16
[task 2024-04-16T19:55:38.198Z] 19:55:38     INFO - PID 996 | 1713297338195	RemoteAgent	TRACE	[1913] ProgressListener Ignore aborted navigation error to the initial document, real document will be loaded.
[task 2024-04-16T19:55:38.201Z] 19:55:38     INFO - PID 996 | 1713297338197	RemoteAgent	TRACE	[1913] ProgressListener Check loading state: isStart=1 isStop=0
[task 2024-04-16T19:55:38.358Z] 19:55:38     INFO - PID 996 | 1713297338357	RemoteAgent	TRACE	[1913] ProgressListener Check loading state: isStart=0 isStop=16
[task 2024-04-16T19:55:38.366Z] 19:55:38     INFO - PID 996 | 1713297338365	RemoteAgent	TRACE	[1913] ProgressListener state=stop: about:blank
[task 2024-04-16T19:55:38.368Z] 19:55:38     INFO - PID 996 | 1713297338367	RemoteAgent	TRACE	[1913] ProgressListener Stop: has error=false
[task 2024-04-16T19:55:38.378Z] 19:55:38     INFO - PID 996 | 1713297338377	Marionette	DEBUG	2 <- [1,10486,null,{"handle":"80f2af24-fb24-4ae1-b427-621a08faa9a0","type":"tab"}]
[task 2024-04-16T19:55:38.424Z] 19:55:38     INFO - PID 996 | 1713297338422	Marionette	DEBUG	2 -> [0,10487,"WebDriver:SwitchToWindow",{"handle":"80f2af24-fb24-4ae1-b427-621a08faa9a0","name":"80f2af24-fb24-4ae1-b427-621a08faa9a0","focus":true}]
[task 2024-04-16T19:55:38.458Z] 19:55:38     INFO - PID 996 | 1713297338457	Marionette	DEBUG	2 <- [1,10487,null,{"value":null}]
[task 2024-04-16T19:55:38.483Z] 19:55:38     INFO - PID 996 | 1713297338482	Marionette	DEBUG	2 -> [0,10488,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/html/canvas/element/shadows/2d.shadow.transform.1.html"}]
[task 2024-04-16T19:55:38.498Z] 19:55:38     INFO - PID 996 | 1713297338497	Marionette	TRACE	[1913] Received event beforeunload for about:blank
[task 2024-04-16T19:55:38.550Z] 19:55:38     INFO - PID 996 | 1713297338549	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 1914
[task 2024-04-16T19:55:38.591Z] 19:55:38     INFO - PID 996 | 1713297338590	Marionette	TRACE	[1914] Received event beforeunload for about:blank
[task 2024-04-16T19:55:38.613Z] 19:55:38     INFO - PID 996 | 1713297338612	Marionette	TRACE	[1914] Received event pagehide for about:blank
[task 2024-04-16T19:55:39.211Z] 19:55:39     INFO - PID 996 | 1713297339210	Marionette	TRACE	[1914] Received event DOMContentLoaded for http://web-platform.test:8000/html/canvas/element/shadows/2d.shadow.transform.1.html
[task 2024-04-16T19:55:39.213Z] 19:55:39     INFO - PID 996 | 1713297339212	Marionette	DEBUG	2 <- [1,10488,null,{"value":null}]
[task 2024-04-16T19:55:39.289Z] 19:55:39     INFO - PID 996 | 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"}]
[task 2024-04-16T19:55:39.308Z] 19:55:39     INFO - PID 996 | 1713297339307	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 27721
[task 2024-04-16T19:55:39.344Z] 19:55:39     INFO - PID 996 | 1713297339343	Marionette	TRACE	[1914] MarionetteCommands actor created for window id 4095251316737
```

Revision 1 by

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

on 2024-04-17 07:17:10 PDT

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](https://treeherder.mozilla.org/logviewer?job_id=454737879&repo=try&lineNumber=47085-47132)
```
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](https://treeherder.mozilla.org/logviewer?job_id=454738925&repo=try&lineNumber=63056-63102)
```
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
```

Back to Bug 1891766 Comment 3