1768871 - Perma js/xpconnect/tests/marionette/test_preloader_telemetry.py TestScriptPreloader.test_preloader_requests_histogram | AssertionError: 144 not greater than 154.5 when Gecko 102 merges to Beta on 2022-05-30

Status: VERIFIED FIXED

(Core :: XPConnect, defect)

Description

[bszekely]

Central-as-beta simulation
How to run these simulations
Failure log:

[task 2022-05-11T13:06:01.724Z] 13:06:01     INFO -  Child process with id "3072" has been marked as detached because it is no longer in the managed process group. Keeping reference to the process id "3099" which is the new child process.
[task 2022-05-11T13:06:01.724Z] 13:06:01     INFO -  1652274361723	Marionette	DEBUG	1 -> [0,3,"Marionette:GetContext",{}]
[task 2022-05-11T13:06:01.724Z] 13:06:01     INFO -  1652274361723	Marionette	DEBUG	1 <- [1,3,null,{"value":"content"}]
[task 2022-05-11T13:06:01.724Z] 13:06:01     INFO -  1652274361724	Marionette	DEBUG	1 -> [0,4,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-05-11T13:06:01.724Z] 13:06:01     INFO -  1652274361724	Marionette	DEBUG	1 <- [1,4,null,{"value":null}]
[task 2022-05-11T13:06:01.725Z] 13:06:01     INFO -  1652274361725	Marionette	DEBUG	1 -> [0,5,"WebDriver:ExecuteScript",{"script":"const name = arguments[0];\n                const snapshot = Services.telemetry.get ... newSandbox":true,"sandbox":"default","line":90,"filename":"tests/js/xpconnect/tests/marionette/test_preloader_telemetry.py"}]
[task 2022-05-11T13:06:01.726Z] 13:06:01     INFO -  1652274361726	Marionette	TRACE	[29] MarionetteCommands actor created for window id 4
[task 2022-05-11T13:06:01.728Z] 13:06:01     INFO -  1652274361727	Marionette	DEBUG	1 <- [1,5,null,{"value":{"0":307,"1":12,"2":144,"3":0}}]
[task 2022-05-11T13:06:01.728Z] 13:06:01     INFO -  1652274361728	Marionette	DEBUG	1 -> [0,6,"Marionette:SetContext",{"value":"content"}]
[task 2022-05-11T13:06:01.728Z] 13:06:01     INFO -  1652274361728	Marionette	DEBUG	1 <- [1,6,null,{"value":null}]
[task 2022-05-11T13:06:01.729Z] 13:06:01     INFO -  1652274361729	Marionette	DEBUG	1 -> [0,7,"Marionette:GetContext",{}]
[task 2022-05-11T13:06:01.729Z] 13:06:01     INFO -  1652274361729	Marionette	DEBUG	1 <- [1,7,null,{"value":"content"}]
[task 2022-05-11T13:06:01.729Z] 13:06:01     INFO -  1652274361729	Marionette	DEBUG	1 -> [0,8,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-05-11T13:06:01.730Z] 13:06:01     INFO -  1652274361729	Marionette	DEBUG	1 <- [1,8,null,{"value":null}]
[task 2022-05-11T13:06:01.730Z] 13:06:01     INFO -  1652274361730	Marionette	DEBUG	1 -> [0,9,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2022-05-11T13:06:01.777Z] 13:06:01     INFO -  1652274361776	Marionette	DEBUG	1 <- [1,9,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAPpCAYAAABKf4CHAAAgAElEQVR4XuzdCZwdVZk34JOVBAg7iuy7IOsAAgooKIgwI6DggoAbOiiIo ... AAAQIECBAgQIAAAQIECBD4BRyAv50kAQIECBAgQIAAAQIECBAgQIAAgbyAAzA/kYIECBAgQIAAAQIECBAgQIAAAQIEfoEBh+hVTNrgbeoAAAAASUVORK5CYII="}]
[task 2022-05-11T13:06:01.778Z] 13:06:01     INFO -  1652274361777	Marionette	DEBUG	1 -> [0,10,"Marionette:SetContext",{"value":"content"}]
[task 2022-05-11T13:06:01.778Z] 13:06:01     INFO -  1652274361777	Marionette	DEBUG	1 <- [1,10,null,{"value":null}]
[task 2022-05-11T13:06:01.778Z] 13:06:01     INFO -  1652274361778	Marionette	DEBUG	1 -> [0,11,"Marionette:GetContext",{}]
[task 2022-05-11T13:06:01.779Z] 13:06:01     INFO -  1652274361778	Marionette	DEBUG	1 <- [1,11,null,{"value":"content"}]
[task 2022-05-11T13:06:01.779Z] 13:06:01     INFO -  1652274361779	Marionette	DEBUG	1 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2022-05-11T13:06:01.779Z] 13:06:01     INFO -  1652274361779	Marionette	DEBUG	1 <- [1,12,null,{"value":null}]
[task 2022-05-11T13:06:01.780Z] 13:06:01     INFO -  1652274361779	Marionette	DEBUG	1 -> [0,13,"WebDriver:GetPageSource",{}]
[task 2022-05-11T13:06:01.782Z] 13:06:01     INFO -  1652274361781	Marionette	TRACE	[31] MarionetteCommands actor created for window id 4294967297
[task 2022-05-11T13:06:01.783Z] 13:06:01     INFO -  1652274361782	Marionette	DEBUG	1 <- [1,13,null,{"value":"<html><head></head><body></body></html>"}]
[task 2022-05-11T13:06:01.783Z] 13:06:01     INFO -  1652274361783	Marionette	DEBUG	1 -> [0,14,"Marionette:SetContext",{"value":"content"}]
[task 2022-05-11T13:06:01.783Z] 13:06:01     INFO -  1652274361783	Marionette	DEBUG	1 <- [1,14,null,{"value":null}]
[task 2022-05-11T13:06:01.829Z] 13:06:01     INFO - TEST-UNEXPECTED-FAIL | js/xpconnect/tests/marionette/test_preloader_telemetry.py TestScriptPreloader.test_preloader_requests_histogram | AssertionError: 144 not greater than 153.5
[task 2022-05-11T13:06:01.829Z] 13:06:01     INFO - Traceback (most recent call last):
[task 2022-05-11T13:06:01.829Z] 13:06:01     INFO -   File "/opt/worker/tasks/task_165227200552814/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 202, in run
[task 2022-05-11T13:06:01.829Z] 13:06:01     INFO -     testMethod()
[task 2022-05-11T13:06:01.829Z] 13:06:01     INFO -   File "/opt/worker/tasks/task_165227200552814/build/tests/marionette/tests/js/xpconnect/tests/marionette/test_preloader_telemetry.py", line 50, in test_preloader_requests_histogram
[task 2022-05-11T13:06:01.829Z] 13:06:01     INFO -     self.assertSimilar(misses, hits)
[task 2022-05-11T13:06:01.829Z] 13:06:01     INFO -   File "/opt/worker/tasks/task_165227200552814/build/tests/marionette/tests/js/xpconnect/tests/marionette/test_preloader_telemetry.py", line 58, in assertSimilar
[task 2022-05-11T13:06:01.829Z] 13:06:01     INFO -     self.assertGreater(lhs, rhs / 2)
[task 2022-05-11T13:06:01.829Z] 13:06:01     INFO - TEST-INFO took 14335ms
[task 2022-05-11T13:06:01.830Z] 13:06:01     INFO -  1652274361785	Marionette	DEBUG	1 -> [0,15,"WebDriver:DeleteSession",{}]
[task 2022-05-11T13:06:01.830Z] 13:06:01     INFO -  1652274361786	Marionette	DEBUG	1 <- [1,15,null,{"value":null}]
[task 2022-05-11T13:06:01.830Z] 13:06:01     INFO -  1652274361786	Marionette	DEBUG	Closed connection 1
[task 2022-05-11T13:06:01.831Z] 13:06:01     INFO - TEST-START | layout/base/tests/marionette/test_accessiblecaret_cursor_mode.py 

Comment 1

[bszekely]

Hi Jon, this started perma failing on today's beta sim, it might be from bug 1432901, could you please take a look?

Comment 3

[Intermittent Failures Robot]

6 failures in 3317 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 6

Platform and build breakdown:

• macosx1015-64-shippable-qr: 5
  • opt: 5
• macosx1015-64-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1768871&startday=2022-05-09&endday=2022-05-15&tree=all

Comment 4

[Jon Coppeard (:jonco)]

The failing test is checking whether the number of startup cache hits and misses are within a factor of two of each other (in the method 'assertSimilar'). The comments indicate this is so we notice if the ratio changes too much.

Previously the number of misses was just over half the number of hits but the number of misses has now decreased slightly triggering this failure.

I don't know exactly what changed to cause this, but the changeset responsible is that for bug 1726465, a marionette change. I found this by building a release-as-beta simulation locally.

Probably the test needs to be updated.

Comment 5

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

Hi Doug, we talked about such a failure a while ago but then I got this test working with my patches for bug 1726465 on mozilla-central.

I'm not sure why it's now starting to fail for beta simulations. Maybe there is some kind of feature which is not enabled on release channels yet which causes this? It's puzzling for me and I'm not sure which approach to use here. Maybe you could give me some information? Maybe updating the boundary checks would be enough as what Jon proposed? Thanks.

Comment 6

[Alex Thayer [:alexical] (she/her)]

So far the test has only provided negative value. It's been a problem a number of times and it has not caught any actual problem with the way the cache is being hit or missed in the wild. I feel like we should cut our losses and remove the test.

Comment 7

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

Thanks Doug! In that case I'll go ahead and provide a patch.

Comment 8

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

Attachment: Bug 1768871 - Remove Marionette test js/xpconnect/tests/marionette/test_preloader_telemetry.py

Turns out that this test didn't provide any value since it was
added. As such lets get it removed.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d198d46fd60f
Remove Marionette test js/xpconnect/tests/marionette/test_preloader_telemetry.py r=webdriver-reviewers,dthayer,jdescottes

Comment 10

[Atila Butkovits]

https://hg.mozilla.org/mozilla-central/rev/d198d46fd60f

Comment 11

[Cristina Cozmuta (:CrissCozmuta)]

The patch was verified in today's beta-sim