1720485 - Intermittent layout/base/tests/test_after_paint_pref.html | got MozAfterPaint when we should not have

Status: RESOLVED FIXED

(Core :: Layout, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=345190321&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/SAnzxqamQEOnw5fP9M7JjQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/SAnzxqamQEOnw5fP9M7JjQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1

---

[task 2021-07-14T12:06:11.189Z] 12:06:11     INFO - TEST-START | layout/base/tests/test_after_paint_pref.html
[task 2021-07-14T12:06:11.424Z] 12:06:11     INFO - TEST-INFO | started process screentopng
[task 2021-07-14T12:06:11.586Z] 12:06:11     INFO - TEST-INFO | screentopng: exit 0
[task 2021-07-14T12:06:11.587Z] 12:06:11     INFO - Buffered messages logged at 12:06:11
[task 2021-07-14T12:06:11.588Z] 12:06:11     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | A valid string reason is expected 
[task 2021-07-14T12:06:11.588Z] 12:06:11     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | Reason cannot be empty 
[task 2021-07-14T12:06:11.589Z] 12:06:11     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | pref defaults to true in mochitest harness 
[task 2021-07-14T12:06:11.590Z] 12:06:11     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | loaded 
[task 2021-07-14T12:06:11.590Z] 12:06:11     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | step1 reached: boundingClientRect=(top=0,left=0,width=0,height=undefined) 
[task 2021-07-14T12:06:11.591Z] 12:06:11     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | step2 reached: boundingClientRect=(top=0,left=0,width=0,height=undefined) 
[task 2021-07-14T12:06:11.592Z] 12:06:11     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | got MozAfterPaint (timeout for next step is 900ms) 
[task 2021-07-14T12:06:11.592Z] 12:06:11     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | step3 reached 
[task 2021-07-14T12:06:11.593Z] 12:06:11     INFO - TEST-FAIL | layout/base/tests/test_after_paint_pref.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2021-07-14T12:06:11.594Z] 12:06:11     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | failstep reached: boundingClientRect=(top=0,left=0,width=0,height=undefined) 
[task 2021-07-14T12:06:11.594Z] 12:06:11     INFO - Buffered messages finished
[task 2021-07-14T12:06:11.594Z] 12:06:11     INFO - TEST-UNEXPECTED-FAIL | layout/base/tests/test_after_paint_pref.html | got MozAfterPaint when we should not have 
[task 2021-07-14T12:06:11.594Z] 12:06:11     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-07-14T12:06:11.594Z] 12:06:11     INFO -     failstep@layout/base/tests/test_after_paint_pref.html:101:5
[task 2021-07-14T12:06:12.319Z] 12:06:12     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | step4 reached 
[task 2021-07-14T12:06:12.346Z] 12:06:12     INFO - GECKO(6140) | MEMORY STAT | vsize 2494MB | residentFast 116MB | heapAllocated 7MB
[task 2021-07-14T12:06:12.372Z] 12:06:12     INFO - TEST-OK | layout/base/tests/test_after_paint_pref.html | took 1182ms

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 6

Platform and build breakdown:

• linux1804-64-qr: 1
  • opt: 1
• linux1804-64: 1
  • opt: 1
• android-em-7-0-x86_64: 4
  • debug-isolated-process: 1
  • opt: 2
  • debug: 1

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

Comment 2

[Sandor Molnar[:smolnar]]

This started to fail on Tier 2 jobs

Comment 3

[Sandor Molnar[:smolnar]]

Started to fail on Tier 1 jobs

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1718755

Comment 5

[Intermittent Failures Robot]

27 failures in 2940 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

This is the #49 most frequent failure this week.

Repository breakdown:

• autoland: 20
• mozilla-central: 7

Platform and build breakdown:

• android-em-7-0-x86_64: 2
  • opt: 1
  • debug-isolated-process: 1
• linux1804-64-shippable-qr: 6
  • opt: 6
• android-em-7-0-x86_64-qr: 8
  • debug: 8
• linux1804-64-shippable: 1
  • opt: 1
• linux1804-64-qr: 5
  • opt: 4
  • debug: 1
• android-em-7-0-x86_64-lite: 1
  • debug: 1
• android-em-7-0-x86_64-lite-qr: 4
  • debug: 4

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

Comment 6

[Natalia Csoregi [:nataliaCs]]

Update:

There have been 40 failures within the last 7 days:

• 11 failures on android-em-7-0-x86_64-lite-qr opt/debug
• 12 failures on Android 7.0 x86-64 WebRender opt/debug
• 1 failure Android 7.0 x86-64 Shippable WebRender opt
• 1 failure on Linux 18.04 x64 asan opt
• 9 failures on Linux 18.04 x64 WebRender opt/debug
• 6 failures on Linux 18.04 x64 WebRender Shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=347027749&repo=autoland&lineNumber=6807

[task 2021-08-01T06:23:44.581Z] 06:23:44     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | failstep reached: boundingClientRect=(top=0,left=0,width=0,height=undefined) 
[task 2021-08-01T06:23:44.581Z] 06:23:44     INFO - Buffered messages finished
[task 2021-08-01T06:23:44.581Z] 06:23:44     INFO - TEST-UNEXPECTED-FAIL | layout/base/tests/test_after_paint_pref.html | got MozAfterPaint when we should not have 
[task 2021-08-01T06:23:44.581Z] 06:23:44     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-08-01T06:23:44.581Z] 06:23:44     INFO -     failstep@layout/base/tests/test_after_paint_pref.html:101:5
[task 2021-08-01T06:23:45.201Z] 06:23:45     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | step4 reached 

Daniel, could you help us assign this to someone?
Thank you.

Comment 7

[Intermittent Failures Robot]

42 failures in 3131 pushes (0.013 failures/push) were associated with this bug in the last 7 days.

This is the #29 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 32
• mozilla-central: 9
• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 12
  • debug: 10
  • opt: 2
• linux1804-64-qr: 8
  • opt: 5
  • debug: 3
• android-em-7-0-x86_64-qr: 12
  • debug: 11
  • opt: 1
• linux1804-64-shippable-qr: 7
  • opt: 7
• linux1804-64: 1
  • opt: 1
• linux1804-64-asan: 1
  • opt: 1
• android-em-7-0-x86_64-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1720485&startday=2021-07-26&endday=2021-08-01&tree=all

Comment 8

[Iulian Moraru]

Update:
There have been 50 failures within the last 7 days:
• 20 failures on android-em-7-0-x86_64-lite-qr debug
• 2 failures on android-em-7-0-x86_64-lite-qr opt
• 7 failures on Android 7.0 x86-64 WebRender debug
• 7 failures on Linux 18.04 x64 WebRender asan opt
• 1 failures on Linux 18.04 x64 CCov WebRender opt
• 5 failures on Linux 18.04 x64 WebRender opt
• 3 failures on Linux 18.04 x64 WebRender debug
• 4 failures on Linux 18.04 x64 WebRender Shippable opt
• 1 failures on linux1804-64-tsan-qr opt
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=347774783&repo=mozilla-central&lineNumber=8080

[task 2021-08-08T09:53:00.940Z] 09:53:00     INFO - TEST-START | layout/base/tests/test_after_paint_pref.html
[task 2021-08-08T09:53:02.453Z] 09:53:02     INFO - TEST-INFO | started process screentopng
[task 2021-08-08T09:53:02.697Z] 09:53:02     INFO - TEST-INFO | screentopng: exit 0
[task 2021-08-08T09:53:02.699Z] 09:53:02     INFO - Buffered messages logged at 09:53:02
[task 2021-08-08T09:53:02.700Z] 09:53:02     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | A valid string reason is expected 
[task 2021-08-08T09:53:02.700Z] 09:53:02     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | Reason cannot be empty 
[task 2021-08-08T09:53:02.700Z] 09:53:02     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | pref defaults to true in mochitest harness 
[task 2021-08-08T09:53:02.700Z] 09:53:02     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | loaded 
[task 2021-08-08T09:53:02.701Z] 09:53:02     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | step1 reached: boundingClientRect=(top=0,left=0,width=0,height=undefined) 
[task 2021-08-08T09:53:02.702Z] 09:53:02     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | step2 reached: boundingClientRect=(top=0,left=0,width=0,height=undefined) 
[task 2021-08-08T09:53:02.703Z] 09:53:02     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | got MozAfterPaint (timeout for next step is 900ms) 
[task 2021-08-08T09:53:02.705Z] 09:53:02     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | step3 reached 
[task 2021-08-08T09:53:02.705Z] 09:53:02     INFO - TEST-FAIL | layout/base/tests/test_after_paint_pref.html | The author of the test has indicated that flaky timeouts are expected.  Reason: untriaged 
[task 2021-08-08T09:53:02.706Z] 09:53:02     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | failstep reached: boundingClientRect=(top=0,left=0,width=0,height=undefined) 
[task 2021-08-08T09:53:02.708Z] 09:53:02     INFO - Buffered messages finished
[task 2021-08-08T09:53:02.708Z] 09:53:02     INFO - TEST-UNEXPECTED-FAIL | layout/base/tests/test_after_paint_pref.html | got MozAfterPaint when we should not have 
[task 2021-08-08T09:53:02.708Z] 09:53:02     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-08-08T09:53:02.708Z] 09:53:02     INFO -     failstep@layout/base/tests/test_after_paint_pref.html:101:5
[task 2021-08-08T09:53:03.328Z] 09:53:03     INFO - TEST-PASS | layout/base/tests/test_after_paint_pref.html | step4 reached 
[task 2021-08-08T09:53:03.369Z] 09:53:03     INFO - GECKO(8079) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2021-08-08T09:53:03.371Z] 09:53:03     INFO - GECKO(8079) | MEMORY STAT heapAllocated not supported in this build configuration.
[task 2021-08-08T09:53:03.372Z] 09:53:03     INFO - GECKO(8079) | MEMORY STAT | vsize 20974416MB | residentFast 364MB
[task 2021-08-08T09:53:03.424Z] 09:53:03     INFO - TEST-OK | layout/base/tests/test_after_paint_pref.html | took 2484ms
[task 2021-08-08T09:53:03.562Z] 09:53:03     INFO - TEST-START | layout/base/tests/test_border_radius_hit_testing.html

Comment 9

[Daniel Holbert [:dholbert]]

(In reply to Natalia Csoregi [:nataliaCs] from comment #6)

Daniel, could you help us assign this to someone?
Thank you.

Sorry for the delay. mattwoodrow, perhaps you could take a look here? Not sure who's the best person to ask about the MozAfterPaint event (and this test) these days, but you feel like a good candidate. :)

Some initial thoughts from skimming the test:

The test does have this suspicious snippet, which is just before the failure in step3:

  // When there was previously another page in our window, we seem to
  // get duplicate events, simultaneously, so we need to register our
  // next listener after a zero timeout.
  await SpecialPowers.pushPrefEnv({'set': [['dom.send_after_paint_to_content', false]]});
  await SpecialPowers.promiseTimeout(0);
  setTimeout(step3, 0, timeout);

https://searchfox.org/mozilla-central/rev/162a8620f126c27de70766808708696260f2256a/layout/base/tests/test_after_paint_pref.html#81

That timeout feels suspicious/hacky. I wonder if some recent architectural change "broke" this promiseTimeout(0) hackaround here (and so now we're getting a mozAfterPaint event that had been queued up from some previously-loaded test, of the sort referenced in the code comment). If the hackaround is indeed just broken/insufficient, maybe there's a better hackaround we could be doing, e.g. a double-rAF to allow any currently-pending paints to be flushed (and hence any pending MozAfterPaint calls to be flushed), or something...?

Alternately/also, maybe there's a race condition that causes the pref-tweak to not immediately take effect in the content process... (I don't have a good feel for whether await SpecialPowers.pushPrefEnv( is meant to be immediately observable in the content process after the promise has resolved. I would suspect it is, but I'm not sure.)

Comment 10

[Intermittent Failures Robot]

48 failures in 2829 pushes (0.017 failures/push) were associated with this bug in the last 7 days.

This is the #22 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• autoland: 40
• mozilla-central: 7
• try: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 7
  • opt: 7
• android-em-7-0-x86_64-lite-qr: 20
  • debug: 18
  • opt: 2
• android-em-7-0-x86_64-qr: 8
  • debug: 8
• linux1804-64-qr: 8
  • debug: 4
  • opt: 4
• linux1804-64-ccov-qr: 1
  • opt: 1
• linux1804-64-shippable-qr: 3
  • opt: 3
• linux1804-64-tsan-qr: 1
  • opt: 1

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

Comment 11

[Daniel Holbert [:dholbert]]

I managed to catch this in rr locally (by running the test repeatedly in chaos mode for ~20min, in a debug+O1-opt build). I've uploaded the recording to pernosco and I'll post the link when I've got it.

Comment 12

[Daniel Holbert [:dholbert]]

Pernosco link (focused on the first of two test-failures in the aforementioned repeated-chaos-mode testrun):
https://pernos.co/debug/Xobq0MrDYw0nGkOF5vX7Bg/index.html

Comment 13

[Daniel Holbert [:dholbert]]

I have a theory about what's going on, and I think my double-rAF suggestion from comment 9 will fix it.

Notes:

• This dom.send_after_paint_to_content pref is internally represented as a nsPresContext flag named mSendAfterPaintToContent
• We update that flag somewhat lazily, on the next refresh cycle tick.
• ...but before we can do that, we get composited, and that (rather than a refresh driver tick) is what prompts us to create a MozAfterPaint event.

So we end up dispatching MozAfterPaint barely after the pref was turned off, due to:

• the lazy refresh-driver-throttled way that we get the pref-change reflected into our nsPresContext
• ...combined with the fact that MozAfterPaint is depent on compositor timing (i.e. receiving IPC events), not refresh-driver timing.
• ...combined with the fact that we had some earlier painting to do, which is what prompts some earlier paint that ends up resulting in this unfortunately-timed composite operation.

I suspect a double-rAF will help here (in place of the promiseTimeout(0)) because I think it will actually make us wait on the compositor to flush all of its pending composites. At least, I'm pretty sure rAF is gated on the compositor.

ni=me to follow up on this...

Comment 14

[Daniel Holbert [:dholbert]]

Attachment: Bug 1720485: Adjust test_after_paint_pref.html to use a double-rAF instead of a timeout, to give its pref-adjustment a better chance to take effect. r?mattwoodrow

nsPresContext has a flag that caches the value of this pref, and the flag gets
updated in the next refresh driver tick after a pref-change occurs. Right now
we don't have a strong guarantee that the flag will have been updated by the
time the test assumes that it has, which is why we're seeing intermittent
failures.

This patch adjusts the test so that it waits for a double-rAF before proceeding
from its pref adjustment. I believe this is the recommended way of forcing &
waiting-out at least one refresh driver tick; and this should let the test
reliably assume the pref-adjustment has taken effect.

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/510d15e845ba
Adjust test_after_paint_pref.html to use a double-rAF instead of a timeout, to give its pref-adjustment a better chance to take effect. r=mattwoodrow

Comment 16

[Daniel Holbert [:dholbert]]

I'm fairly confident that the landed patch will fix this.

I ran the same process as in comment 11, with the patch that has now landed, and I was able to get through 9x the number of test iterations without any failures (at which point I stopped the trial).

In comment 11, I let the test run on repeat for about 20 minutes and got 2 test-failures. Now I've repeated that same process 9 times, with the patch, and I got zero test-failures.

For reference, the command I'm using is:

 MOZ_CHAOSMODE=1 ./mach mochitest --headless --setpref="fission.autostart=true" layout/base/tests/test_after_paint_pref.html --repeat 10000

Comment 17

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/510d15e845ba

Comment 18

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/7863f383b868

Comment 19

[Intermittent Failures Robot]

10 failures in 3025 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 7
• mozilla-central: 3

Platform and build breakdown:

• linux1804-64-qr: 3
  • debug: 1
  • opt: 2
• android-em-7-0-x86_64-qr: 4
  • debug: 4
• android-em-7-0-x86_64-lite-qr: 2
  • debug: 2
• linux1804-64-shippable-qr: 1
  • opt: 1

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