1386549 - Delayed command execution

Status: RESOLVED WORKSFORME

(Remote Protocol :: Marionette, enhancement, P3)

Description

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

In a couple of cases I noticed that commands are mystically delayed in execution. Here an example of a get request with a following executeScript call:

[task 2017-07-22T02:32:29.695817Z] 02:32:29     INFO -  1500690749690	Marionette	DEBUG	Received DOM event "DOMContentLoaded" for "http://127.0.0.1:34501/slow_resource.html"
[task 2017-07-22T02:32:29.703637Z] 02:32:29     INFO -  1500690749698	Marionette	TRACE	1021 <- [1,2,null,{}]
[task 2017-07-22T02:32:34.120195Z] 02:32:34     INFO -  1500690754110	Marionette	TRACE	1021 -> [0,3,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"test_navigation.py","script":"return window.document.readyState;","sandbox":null,"line":107}]
[task 2017-07-22T02:32:34.178136Z] 02:32:34     INFO -  1500690754165	Marionette	TRACE	1021 <- [1,3,null,{"value":"complete"}]

Here the get request returned, and the immediate call to executeScript was performed 5s later! There is no wait, nothing.

We have to investigate where the bottleneck is located. Most likely it's somewhere in Marionette server or Firefox itself.

Affected tests will be added as dependencies.

Comment 1

[David Burns :automatedtester]

Henrik,

I know you have been adding extra logging to things, have you done some in this area? (not expecting you to have)

Comment 2

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

Not yet, but with bug 1394381 we will start using a logger in the Marionette client. It could lay the base for more logging output like this.

Comment 3

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

Not sure what triggered these delays 5 years ago but after checking a couple of jobs I'm not able to see it anymore. Maybe it was even that random that it is not worth spending time for investigation.