1705181 - Intermittent org.mozilla.geckoview.test.SessionLifecycleTest#asyncScriptsSuspendedWhileInactive | java.lang.AssertionError: requestAnimationFrame should be called about once a second

Status: RESOLVED FIXED

(GeckoView :: General, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=336527703&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/NVZyaDHLRu6X5j14r35IUQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2021-04-14T18:11:32.156Z] 18:11:32     INFO -  04-14 19:11:30.904 D/GeckoViewProgress( 3169): receiveMessage: MozAfterPaint
[task 2021-04-14T18:11:32.156Z] 18:11:32     INFO -  04-14 19:11:30.971 E/GeckoSessionTestRule( 3169): after evaluate
[task 2021-04-14T18:11:32.157Z] 18:11:32     INFO -  04-14 19:11:30.972 D/GeckoViewConsole( 3169): onEvent GeckoView:WebExtension:PortMessageFromApp {"message":{"id":"3ab8a4c2-b26f-4a3b-860c-2ce6114667a6","args":{"oldPrefs":{"privacy.reduceTimerPrecision":true,"layout.throttled_frame_rate":null}},"type":"RestorePrefs"}}
[task 2021-04-14T18:11:32.157Z] 18:11:32     INFO -  04-14 19:11:30.978 E/GeckoSessionTestRule( 3169): after performTestEndCheck
[task 2021-04-14T18:11:32.157Z] 18:11:32     INFO -  04-14 19:11:30.980 D/GeckoViewContent( 3169): handleEvent: DOMWindowClose
[task 2021-04-14T18:11:32.157Z] 18:11:32     INFO -  04-14 19:11:30.982 D/GeckoViewConsole( 3169): onEvent GeckoView:WebExtension:List null
[task 2021-04-14T18:11:32.157Z] 18:11:32     INFO -  04-14 19:11:30.988 E/GeckoSessionTestRule( 3169): test_end c5ee677f-bc83-49bd-9e28-2d35f3d0f059 asyncScriptsSuspendedWhileInactive(org.mozilla.geckoview.test.SessionLifecycleTest)
[task 2021-04-14T18:11:32.157Z] 18:11:32  WARNING -  TEST-UNEXPECTED-FAIL | org.mozilla.geckoview.test.SessionLifecycleTest.asyncScriptsSuspendedWhileInactive | java.lang.AssertionError: requestAnimationFrame should be called about once a second
[task 2021-04-14T18:11:32.157Z] 18:11:32     INFO -  TEST-INFO took 4052ms```

Comment 1

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Please try to identify what change causes this issue.

Comment 2

[Intermittent Failures Robot]

18 failures in 4255 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 12
• mozilla-central: 6

Platform and build breakdown:

• android-em-7-0-x86_64: 13
  • debug: 13
• android-em-7-0-x86_64-qr: 5
  • debug: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1705181&startday=2021-04-12&endday=2021-04-18&tree=all

Comment 3

[Emily Toop (:fluffyemily)]

Removing priority so that we can retriage.

Comment 4

[Emily Toop (:fluffyemily)]

Agi, do you know who might have changed this code recently?

Comment 5

[Intermittent Failures Robot]

4 failures in 3224 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3
• mozilla-central: 1

Platform and build breakdown:

• android-em-7-0-x86_64: 3
  • debug: 3
• android-em-7-0-x86_64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1705181&startday=2021-04-19&endday=2021-04-25&tree=all

Comment 6

[Intermittent Failures Robot]

20 failures in 3706 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 8
• autoland: 12

Platform and build breakdown:

• android-em-7-0-x86_64: 10
  • debug: 10
• android-em-7-0-x86_64-qr: 10
  • debug: 10

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1705181&startday=2021-04-26&endday=2021-05-02&tree=all

Comment 7

[Intermittent Failures Robot]

16 failures in 3279 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 15
• mozilla-central: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 6
  • debug: 6
• android-em-7-0-x86_64: 10
  • debug: 10

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

Comment 8

[[ex-Mozilla] Agi Sferro | :agi]

Bisected on autoland, looks like this was introduced by Bug 1704545: https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=junit&tochange=b29fdf0da851cfd9eb8cd1f08263c09c2c997d21&fromchange=b1d0eb2feeff0d58b924bacc858cedf417198289
mccr8, do you have any ideas?

Comment 9

[Andrew McCreight [:mccr8]]

Looking at a few logs, it looks like it is expecting a value of 500ms, but instead it is getting values that are slightly smaller, like 499.86, 499.93, and 499.98499999999996. So there may just be a very small regression.

I think my first patch should not change behavior, unless Android is triggering the remote-browser-shown observer notification in some way I don't see in SearchFox. The second patch renames some functions so it really shouldn't change the behavior.

The third patch changes some process deprioritization from happening when ipc:browser-destroyed fires (in BrowserHost::DestroyComplete()) to BrowserParent::Deactivated(). Maybe we're ending up doing some deprioritization where we didn't before and that causes something to take a tiny bit longer?

The easiest fix here looks like it would be to change the threshold from 500ms to 499.5ms, but I don't know how important the precise value here is.

Comment 10

[[ex-Mozilla] Agi Sferro | :agi]

Thanks Andrew! Looks like reducing the rAF rate required is enough, that value was already an approximation so that should be fine. https://treeherder.mozilla.org/jobs?repo=try&revision=dfdc2e6127cf656004406ccaf1fc6b384d00bc42

Comment 11

[[ex-Mozilla] Agi Sferro | :agi]

Attachment: Bug 1705181 - Adjust rAF rate for asyncScriptsSuspendedWhileInactive.

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/03368909cd5c
Adjust rAF rate for asyncScriptsSuspendedWhileInactive. r=owlish

Comment 13

[Dorel Luca [:dluca]]

https://hg.mozilla.org/mozilla-central/rev/03368909cd5c

Comment 14

[Intermittent Failures Robot]

13 failures in 3061 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 10
• mozilla-central: 2
• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64: 9
  • debug: 9
• android-em-7-0-x86_64-qr: 4
  • debug: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1705181&startday=2021-05-17&endday=2021-05-23&tree=all

Comment 15

[[ex-Mozilla] Agi Sferro | :agi]

6c6f5da9-bf33-4082-a19d-7d99e8083d97 Mass rename intermittents due to Bug 1723034.