1244837 - Bug 1238744 caused a massive slowdown in Marionette performance starting with Firefox 46.0a1

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect)

Description

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

Today I did a full run of our firefox-ui-tests and noticed that testing got so painful slow. While version 38.0 was e.g. opening and closing tabs that fast that you nearly weren't able to see it, it takes about 500ms for such a single action now. I could come with better numbers in a bit.

I will also do some testing and maybe I can clearly see in which version we have this decrease. Given that the client I'm using is the same, the reason should be somewhere in Marionette or maybe in Firefox.

Comment 1

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

Even the test location has been changed, the output below is the identical set of tests. Here we have a difference in execution time of factor 6!

$ time firefox-ui-functional --binary /mozilla/bin/esr38/firefox firefox_puppeteer/tests/test_tabbar.py
real	0m7.472s
user	0m6.060s
sys	0m0.640s

$ time firefox-ui-functional --binary /mozilla/bin/nightly/firefox firefox_ui_tests/firefox_ui_tests/puppeteer/test_tabbar.py
real	0m43.660s
user	0m14.384s
sys	0m2.268s

Comment 2

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

Ok, Aurora is not that bad:

real	0m12.333s
user	0m12.248s
sys	0m0.832s

So this is a really recent regression in Firefox 47.0a1.

Comment 3

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

[Tracking Requested - why for this release]:
Execution time for tests exploded by a factor of 4-6 times. This would also cause a huge bottle neck on testing machines.

I wonder if we should have Talos tests for Marionette.

Comment 4

[Joel Maher ( :jmaher ) (UTC -8)]

lets determine the cause- I assume mozregression could help us bisect?  There is value in tracking our test times and looking for any job (build/test) that increases by >10%.

Comment 5

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

I just noticed that my local Aurora was not up2date and I was still running a 45.0a2 version. After upgrading it I can see the same slowness. So this is a regression in early 46.0a1 then.

Comment 6

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

I run mozregression and the builds have been nailed down to bug 1238744.

Comment 7

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

You can run the above tests also via:

mach firefox-ui-test testing/firefox-ui/tests/firefox_ui_tests/puppeteer/test_tabbar.py

Comment 8

[Andreas Tolfsen ❲:ato❳]

The slowdown seems to be when the interactions.Interactions#isVisible method is called: https://dxr.mozilla.org/mozilla-central/source/testing/marionette/interactions.js#258

Comment 9

[Andreas Tolfsen ❲:ato❳]

Sorry, I spoke too soon.  I believe it’s related to the retries to get the accessibility object: https://dxr.mozilla.org/mozilla-central/source/testing/marionette/accessibility.js#112

It appears that we are always doing accessibility checks now, but that they only surface when the raiseAccessibilityExceptions capability is set to true.  I’m not sure this is necessary.  Perhaps we can disable accessibility checks altogether if the capability is not set?

Comment 10

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

(In reply to Andreas Tolfsen (:ato) from comment #9)
> true.  I’m not sure this is necessary.  Perhaps we can disable accessibility
> checks altogether if the capability is not set?

As what I got from the discussion last week on IRC that is how it should work. And in fx ui tests we definitely don't have enabled the accessibility capability.

Comment 11

[Yura Zenevich [:yzen] (please use "needinfo")]

Ill take a look at it today/tomorrow.

Comment 12

[Yura Zenevich [:yzen] (please use "needinfo")]

Attachment: MozReview Request: Bug 1244837 - only performing multiple attempts to retrieve an accessible object iff raisesAccessibilityExceptions capability is set to true. r=ato

---
 testing/marionette/accessibility.js                  | 18 ++++++++++++++++++
 .../marionette/tests/unit/test_accessibility.py      | 20 ++++++++++++++++++--
 testing/marionette/driver.js                         |  8 ++++++--
 3 files changed, 42 insertions(+), 4 deletions(-)

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

Comment 13

[Yura Zenevich [:yzen] (please use "needinfo")]

Comment on attachment 8715463 [details]
MozReview Request: Bug 1244837 - only performing multiple attempts to retrieve an accessible object iff raisesAccessibilityExceptions capability is set to true. r=ato

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

Comment 14

[Andreas Tolfsen ❲:ato❳]

Comment on attachment 8715463 [details]
MozReview Request: Bug 1244837 - only performing multiple attempts to retrieve an accessible object iff raisesAccessibilityExceptions capability is set to true. r=ato

https://reviewboard.mozilla.org/r/33467/#review30285

Comment 15

[Yura Zenevich [:yzen] (please use "needinfo")]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2564c91f9a5c

Comment 16

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/2564c91f9a5c

Comment 17

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

This works fine in latest Nightly builds. Thank you for the fix!

As noted this is a huge performance regression in Marionette test-only code. So we need this uplifted to mozilla-aurora.

Comment 18

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/198eac9a427a