1256439 - Marionette slowdown (runs twice that long) since implicit waits have been landed

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

We had bug 1244837 which fixed a massive slowdown for Firefox 47.0a1 and 46.0a2. But in the last days I can still see that Marionette runs about twice that long for me on my local machine and also all taskcluster builds. We are really wasting lots of machine power here. I wish we would have a perf test for comparison that we no longer cause those regressions.

I will have a look at mozregression now.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Here a comparison for the same kind of test:

SUMMARY (46.0a2)
-------
 0:18.47 LOG: MainThread INFO passed: 10
 0:18.47 LOG: MainThread INFO failed: 0
 0:18.47 LOG: MainThread INFO todo: 0
 0:18.52 SUITE_END: MainThread 

SUMMARY (47.0a2)
-------
 0:55.06 LOG: MainThread INFO passed: 10
 0:55.06 LOG: MainThread INFO failed: 0
 0:55.06 LOG: MainThread INFO todo: 0
 0:55.10 SUITE_END: MainThread

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Something in that pushlog (retrieved via nightly tester tools) should have caused it:

https://hg.mozilla.org/releases/mozilla-aurora/pushloghtml?fromchange=383d2c72f4c77a81d44704272dcfbbe3c8cafca8&tochange=0b81120cfc00bfc33091dab4340b2e109a0964c1

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Regression started with this merge from inbound to mozilla-central:

https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=ad029c4e30b017efb2a255294b4528071d951430&tochange=c1e0d1890cfee9d86c8d566b0490053f21e0afc6

Testing changesets (aa5e5a12ce63 and 52b85b8b8c14) around the patch landing date of bug 1250102 gave me the real regression range.

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Maybe the reason is the following default interval?

> function implicitlyWaitFor(func, timeout, interval = 100) {

This could definitely slow down everything.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Ok, that's definitely the problem here:
https://dxr.mozilla.org/mozilla-central/source/testing/marionette/element.js#668

Shortening the interval to 10ms makes it faster so all in all it takes about 20s instead of 55s in my local build.

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Using 0s for the interval is even worse the latest Firefox beta: 16s vs 9s

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Hm. Just a side-note for this method. Do we leak a timer instance given that we only cancel it when resolving the promise?

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

The underlying issue here is the initial wait time of 100ms before the function gets evaluated the first time. I do not see why this is necessary. Instead we should do the first evaluation immediately and only wait if the callback fails. This will restore the former performance of Marionette and leaves all tests as passing.

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

I will take it.

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Here a measure of our firefox-ui-functional tests on my local machine with and without the upcoming fix.

Without fix:
 5:32.17 LOG: MainThread INFO passed: 92
 5:32.17 LOG: MainThread INFO failed: 0
 5:32.17 LOG: MainThread INFO todo: 1
 5:32.21 SUITE_END: MainThread 

With fix:
 2:44.97 LOG: MainThread INFO passed: 92
 2:44.97 LOG: MainThread INFO failed: 0
 2:44.97 LOG: MainThread INFO todo: 1
 2:44.99 SUITE_END: MainThread 

Those are 332s vs. 165s. So we can indeed speed-up Marionette by a factor of 2x.

I'm wrestling through exiting Marionette unit tests now given that a lot of them fail on my machine.

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Attachment: MozReview Request: Bug 1256439 - Run implicit wait callback once before start polling. r?automatedtester

As of now the implicit wait method waits the default interval before doing the first check against the passed in callback. This is not necessary and it can be changed for an immediate check. If that one fails we can still enter the timer driven loop and continue to wait.

Review commit: https://reviewboard.mozilla.org/r/40093/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/40093/

Comment 12

[Andreas Tolfsen ❲:ato❳]

https://reviewboard.mozilla.org/r/40093/#review36585

This change looks good to me, but can you please rename the commit message to be more descriptive?  Instead of explaining what it should not do, try to explain the change.

E.g. “Run implicit wait function once before polling” or something similar, and then explain what it’s doing wrong in the commit message.

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Comment on attachment 8730697 [details]
MozReview Request: Bug 1256439 - Run implicit wait callback once before start polling. r?automatedtester

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/40093/diff/1-2/

Comment 14

[David Burns :automatedtester]

Comment on attachment 8730697 [details]
MozReview Request: Bug 1256439 - Run implicit wait callback once before start polling. r?automatedtester

https://reviewboard.mozilla.org/r/40093/#review36743

Comment 15

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/7314496982c0

Comment 16

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/7314496982c0

Comment 17

[Henrik Skupin [:whimboo][⌚️UTC+2] (away 10/03 - 10/13)]

Test-only change which fixes a regression in Marionette which is also necessary on current aurora.

Comment 18

[David Burns :automatedtester]

This has already been uplifted to Aurora https://hg.mozilla.org/releases/mozilla-aurora/rev/0a61b7f086d7