Open Bug 947688 Opened 11 years ago Updated 2 years ago

test_bug450930.xhtml has "Wrong event count" failures caused by the fade-away OSX scrollbars

Categories

(Core :: Layout, defect, P4)

Product:
Core
Component:
Layout
Platform:
x86_64
macOS
Type:
defect

Tracking

()

People

(Reporter: philor, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: platform-parity, Whiteboard: [test disabled in bug 934301])

Attachments

(1 file)

disable fade-away scrollbars for this test
3.20 KB, patch
Details | Diff | Splinter Review 
When run on the 10.9 slave, test_bug450930.xhtml consistently is unhappy about event counts:

https://tbpl.mozilla.org/php/getParsedLog.php?id=31634476&tree=Cedar
Rev5 MacOSX Mavericks 10.9 cedar opt test mochitest-4 on 2013-12-07 16:37:29 PST for push de1a3b3fbf4e
slave: t-mavericks-r5-001

16:42:33     INFO -  20060 INFO TEST-START | /tests/layout/base/tests/test_bug450930.xhtml
16:42:34     INFO -  20061 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | trigger test1 paint
16:42:34     INFO -  20062 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Left edges out (8,8)
16:42:34     INFO -  20063 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Right edges out (408,408)
16:42:34     INFO -  20064 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Top edges out (27,27)
16:42:34     INFO -  20065 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Bottom edges out (227,228)
16:42:34     INFO -  20066 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | trigger test1 paint
16:42:34     INFO -  20067 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Left edges out (8,8)
16:42:34     INFO -  20068 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Right edges out (408,408)
16:42:34     INFO -  20069 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Top edges out (27,27)
16:42:34     INFO -  20070 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Bottom edges out (227,228)
16:42:34     INFO -  20071 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | trigger test1 paint
16:42:34     INFO -  20072 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Left edges out (8,8)
16:42:34     INFO -  20073 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Right edges out (408,408)
16:42:34     INFO -  20074 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Top edges out (27,27)
16:42:34     INFO -  20075 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Bottom edges out (227,228)
16:42:34     INFO -  20076 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | trigger test1 paint
16:42:34     INFO -  20077 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Left edges out (8,8)
16:42:34     INFO -  20078 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Right edges out (408,410)
16:42:34     INFO -  20079 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Top edges out (27,27)
16:42:34     INFO -  20080 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Bottom edges out (227,639)
16:42:34     INFO -  20081 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Found exact rect
16:42:34     INFO -  Incoming rect: (8,227.1999969482422,412,431.20001220703125)
16:42:34     INFO -  List rect 0: (393,229,410,237) FOUND
16:42:34     INFO -  Incoming rect: (8,227.1999969482422,412,431.20001220703125)
16:42:34     INFO -  List rect 0: (393,229,410,429) FOUND
16:42:34     INFO -  Incoming rect: (8,227.1999969482422,412,431.20001220703125)
16:42:34     INFO -  List rect 0: (393,229,410,429) FOUND
16:42:34     INFO -  Incoming rect: (8,227.1999969482422,412,431.20001220703125)
16:42:34     INFO -  List rect 0: (393,229,410,429) FOUND
16:42:34     INFO -  Incoming rect: (8,227.1999969482422,412,431.20001220703125)
16:42:34     INFO -  List rect 0: (393,229,410,429) FOUND
16:42:34     INFO -  Incoming rect: (8,227.1999969482422,412,431.20001220703125)
16:42:34     INFO -  List rect 0: (393,229,410,429) FOUND
16:42:34     INFO -  Incoming rect: (8,227.1999969482422,412,431.20001220703125)
16:42:34     INFO -  List rect 0: (393,229,410,429) FOUND
16:42:34     INFO -  20082 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/base/tests/test_bug450930.xhtml | Wrong event count (iframe) - got 7, expected 1
16:42:34     INFO -  20083 INFO TEST-PASS | /tests/layout/base/tests/test_bug450930.xhtml | Didn't get subdoc invalidation while we were privileged (iframe)
16:42:34     INFO -  Incoming rect: (8,436.79998779296875,418,646.7999877929688)
16:42:34     INFO -  List rect 0: (393,229,410,429)
16:42:34     INFO -  List rect 1: (8,437,412,641) FOUND
16:42:34     INFO -  Incoming rect: (8,436.79998779296875,418,646.7999877929688)
16:42:34     INFO -  List rect 0: (393,229,410,429)
16:42:34     INFO -  List rect 1: (393,439,410,639) FOUND
16:42:34     INFO -  Incoming rect: (8,436.79998779296875,418,646.7999877929688)
16:42:34     INFO -  List rect 0: (393,229,410,429)
16:42:34     INFO -  List rect 1: (393,439,410,639) FOUND
16:42:34     INFO -  Incoming rect: (8,436.79998779296875,418,646.7999877929688)
16:42:34     INFO -  List rect 0: (393,229,410,429)
16:42:34     INFO -  List rect 1: (393,439,410,639) FOUND
16:42:34     INFO -  Incoming rect: (8,436.79998779296875,418,646.7999877929688)
16:42:34     INFO -  List rect 0: (393,229,410,429)
16:42:34     INFO -  List rect 1: (8,437,412,641) FOUND
16:42:34     INFO -  20084 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/base/tests/test_bug450930.xhtml | Wrong event count (iframe2) - got 5, expected 1
Hmm, we get 7 MozAfterPaint callbacks in the 100ms it takes before we remove the
event listener in check().
http://mxr.mozilla.org/mozilla-central/source/layout/base/tests/bug450930.xhtml#144
Where do these paints come from? the fade-away scrollbar? (but why only on 10.9?)
16:42:33     INFO -  20056 INFO TEST-INFO | MEMORY STAT vsize after test: 4362104832
16:42:33     INFO -  20057 INFO TEST-INFO | MEMORY STAT residentFast after test: 416403456
16:42:33     INFO -  20058 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 96353440
... test_bug450930.xhtml runs, see comment 0
16:42:34     INFO -  20086 INFO TEST-INFO | MEMORY STAT vsize after test: 4394536960
16:42:34     INFO -  20087 INFO TEST-INFO | MEMORY STAT residentFast after test: 436129792
16:42:34     INFO -  20088 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 116118640

So this test alone added 32MB to vsize.  And 4.4GB ... really?  *shrug*
Something's sure weird with scrollbars on 10.9 (or, on the single 10.9 test slave anyway) - a good share of the 51 reftest failures seem to be scrollbar-related, the mochitest-chrome failures are scrollbar-related, the mochitest-5 failures might be. What I don't know is what and why, or who will know how to tell.
Steven, do you have 10.9 and some time to investigate this?
Flags: needinfo?(smichaud)
This looks like a *lot* of work ... at least to figure everything out from scratch.  But let me see, Mats, if I can find a quick answer to your question from comment #1 -- Where do the MozAfterPaint callbacks come from?

And yes, I do have 10.9, but only a couple of days before I go on vacation.
Flags: needinfo?(smichaud)
In case it helps, I did look into how these events are fired, and it starts
at nsPresContext::NotifyInvalidation which calls EnsureEventualDidPaintEvent
which starts a timer (to coalesce notifications for performance I presume),
the timeout then posts a script runner in NotifyDidPaintForSubtree which
eventually calls FireDOMPaintEvent which is where the actual DOM event
is dispatched, afaict.  I guess the NotifyInvalidation calls are the
root of the problem...

Now that I look at the test again, I wonder if the order of lines 151/152
is wrong.  If layout isn't fully flushed, then line 152 could cause
a lot of painting by itself... but it seems we're only interested
in the one paint for the background-toggling that flash() does.
I'm not sure why line 152 is even there in the first place --
triggerPaint() inside runTest1() doesn't have that.  Perhaps
it should be the first line of runNext() instead, so that we flush
layout between each test, and then wait for isMozAfterPaintPending
to become false before starting the test.
I figured the best place to start is to run this test locally.  Then I discovered it's actually been disabled (at bug 934301).  So to get it to run at all you have to edit layout/base/tests/mochitest.ini and rebuild.

I built m-c and ran the test locally on OS X 10.7.5 and 10.9.1 (in different partitions on the same machine -- a Retina MacBook Pro).  I ran it by itself and together with all the other tests in layout/base/tests/.  I got "wrong event count" errors every time I ran it (except one of the times I ran it by itself on OS X 10.9.1) -- 4 or 5 instead of the expected 1 on both OSes.

So these errors have nothing to do with Mavericks.
Thanks Steven, that's good to know.  Unfortunately,  I can't reproduce it in a local m-c
debug build on a MBP2011 with OSX 10.7.5.  :-(
I ran it with --repeat=10 and it passed all the runs.  I also tried with always-on
scrollbars (System Prefs - Personal - General) with the same result.

Steven, can you reproduce it also with always-on scrollbars?
Did you use Opt or Debug builds?
Flags: needinfo?(smichaud)
I have a "Retina, Mid 2012" MacBook Pro, whose storage device is an SSD, whose access time is much faster than a conventional hard drive.  I'll bet that's what makes the difference (that it's the reason why I can reproduce this bug on OS X 10.7.5 but you can't).

I did a non-opt non-debug build, using the following .mozconfig file:

export CC="clang"
export CXX="clang++"
export CFLAGS="-g -gfull"
export CXXFLAGS="-g -gfull"
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/obj-firefox-64bit
mk_add_options MOZ_MAKE_FLAGS=-j4
mk_add_options AUTOCONF=autoconf213
ac_add_options --disable-optimize
ac_add_options --enable-tests
ac_add_options --enable-cpp-rtti
ac_add_options --enable-logrefcnt
ac_add_options --disable-strip
ac_add_options --disable-install-strip
ac_add_options --with-macos-sdk=/Developer/SDKs/MacOSX10.6.sdk
ac_add_options --enable-macos-target=10.6

I'll test with always-on scrollbars.  But like I said I suspect it's my SSD that makes the difference.
Flags: needinfo?(smichaud)
Phil, what can you tell us about the physical characteristics of the 10.9 slave on which you've seen these test failures?
Flags: needinfo?(philringnalda)
Oh, and I'll try changing the --disable-optimize in my mozconfig to --enable-optimize, to see if that makes a difference.
> I'll test with always-on scrollbars.

I don't get the "wrong event count" failure (or any others) testing (on OS X 10.7.5) with always-on scrollbars.  I ran the test several times by itself (one repeat only), and once together with all the other layout/base mochitests.
302 coop (comment 10).
Flags: needinfo?(philringnalda) → needinfo?(coop)
> I'll try changing the --disable-optimize in my mozconfig to --enable-optimize

Doing this made the "wrong event count" numbers go up, and happen in more than one iframe (usually "got 7, expected 1" in "iframe" and "got 5, expected 1" in "iframe2").

(In non-opt builds I usually just see "got 4, expected 1" for "iframe".)
(I have an SSD in mine too, fwiw.)

I recompiled with --disable-debug and --enable-optimize and now I can reproduce it as well!
And the problem goes away with always-on scrollbars, same as for you.

This is interesting; I suspect that the fade-away animation of the scrollbars
causes the invalidations that generates these extra events.  Hmm, this would
make any test using MozAfterPaint and have a scrollbar anywhere on the page
rather unreliable (on OSX at least; is Android/B2G affected too?).
> (I have an SSD in mine too, fwiw.)
> 
> I recompiled with --disable-debug and --enable-optimize

So my guess about the importance of the SSD is wrong.

Here's another:  I'll bet the debug spew you get with --enable-debug was slowing your system down enough to stop you seeing these errors.

Try again with --disable-debug and --disable-optimize.

I'm going to try logging calls (and hopefully also stack traces) to FireDOMPaintEvent() and the DelayedFireDOMPaintEvent constructor with an interpose library.  With luck that won't slow down my machine enough to stop seeing these errors.  (Though of course the stack traces will be more intelligible with --disable-optimize.)
This makes the test 100% reliable for me, does it fix it for you as well?

Unfortunately though, clearing the pref at the end has no effect
due to bug 932814 so the always-on scrollbar setting will remain
for the rest of the session.
A temporary fix would be to just wait 3 seconds before starting the test I guess. :-)
(I guess bug 932814 is specifically about "accessibility.tabfocus" and its corresponding
system pref setting, so I filed bug 952613 for "ui.useOverlayScrollbars".)
Comment on attachment 8350735 [details] [diff] [review]
disable fade-away scrollbars for this test

I'll try this in a bit (still working on my interpose library).

But I suspect it'd be better just to disable this test.  At some point we do want to be able to run automated tests with overlay scrollbars enabled.
> But I suspect it'd be better just to disable this test.

Until bug 952613 is fixed, that is.
(In reply to Steven Michaud from comment #21)
> > But I suspect it'd be better just to disable this test.
> 
> Until bug 952613 is fixed, that is.

I agree.  I would also really like to understand the failures in bug 934301
(which appears to be Linux/Windows only), it seems even weirder than this bug.
Depends on: 952613
Keywords: pp
Priority: -- → P4
Summary: test_bug450930.xhtml has "Wrong event count" failures on 10.9 → test_bug450930.xhtml has "Wrong event count" failures caused by the fade-away OSX scrollbars
Whiteboard: [test disabled in bug 934301]
(In reply to Steven Michaud from comment #16)
> Try again with --disable-debug and --disable-optimize.

Yep, I can reproduce it also with that, fwiw.
For what it's worth, I've established the following about the "excess" calls to nsPresContext::FireDOMPaintEvent() associated with this mochitest's nsHTMLDocument:

Each happens as the result of the creation of exactly one DelayedFireDOMPaintEvent (in nsPresContext::NotifyDidPaintForSubtree()).

Each DelayedFireDOMPaintEvent is created during a tick of the refresh timer belonging to the root nsPresContext.

I've also found that increasing the refresh timer frequency (by setting layout.frame_rate to 0) increases the "wrong event count".

I'll try to get back to this next year, and dig further.  But for now it looks like this kind of test failure isn't caused by any bug or design flaw in the overlay scrollbars -- it's by design that they cause updates to their window as they fade in and fade out.  So this kind of test will always need to turn off overlay scrollbars to work properly.
Thanks, I think it's pretty clear now that painting the fading scrollbars is the
root cause of these events so there's no need to dig further unless you want to.
We should just fix bug 952613 and use that pref here...
Flags: needinfo?(coop)
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: