Open Bug 1386549 Opened 2 years ago Updated 2 years ago

Delayed command execution

Categories

(Testing :: Marionette, enhancement, P3)

enhancement

Tracking

(Not tracked)

People

(Reporter: whimboo, Unassigned)

References

(Depends on 1 open bug)

Details

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.
Henrik,

I know you have been adding extra logging to things, have you done some in this area? (not expecting you to have)
Flags: needinfo?(hskupin)
Priority: -- → P3
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.
Depends on: 1394381
Flags: needinfo?(hskupin)
You need to log in before you can comment on or make changes to this bug.