1010119 - [APZC] Sometimes the content is not painted correctly

Status: RESOLVED FIXED

(Core :: Panning and Zooming, defect)

Description

[Julien Wajsberg [:julienw]]

Attachment: apzc-issue.txt

This happens sometimes when I enter a thread in the SMS app. I get the header, the composer (the part with the input to enter the message), the send button, but not the thread content. I also have the scrollbar. Too bad I didn't take a screenshot, sorry :(

When I have this situation, when I get back to the thread list and open the same thread, I have the exact same issue. But as soon as I scroll the container the issue is gone and then I can't reproduce it by opening the thread again.

The paint is done a soon as I scroll the container.

I attached a APZC log I got using attachment 8402141 [details] [diff] [review] (that I rebased to central). This is the log from opening the thread again as explained above, not a log from when the issue appeared in the first place, so maybe it won't be useful enough.

I use a gecko from central from yesterday.

I also had report of paintings not working correctly in v1.4, but the issue looked different. Don't know if this is the same root cause.

Kats, I hope this makes sense.

Comment 1

[Kartikaya Gupta (email:[e-mail])]

(In reply to Julien Wajsberg [:julienw] from comment #0)
> I attached a APZC log I got using attachment 8402141 [details] [diff] [review]
> [review] (that I rebased to central). This is the log from opening the
> thread again as explained above, not a log from when the issue appeared in
> the first place, so maybe it won't be useful enough.

Just to clarify - the log covers opening the thread for the second time (so the issue is visible), and then scrolling to fix the issue? I just want to be clear on exactly what's in the log, because it covers a 30-second time period and I want to make sure I look at the right bits.

Comment 2

[Kartikaya Gupta (email:[e-mail])]

And yes, the displayport there looks wrong on one of the layers, it has a giant y-value and is sized to 0x0, so that would probably explain why you're not seeing anything. From the log it's not clear how it gets into that state, because it happens before the log starts (and anyway just APZC logging might not be sufficient to track that down). Really need reliable STR for this.

Julien, before you ran into this issue, were you on any screen with a really really long scrollable area? Like 135000 pixels tall? If so that might explain why the displayport y-value is so big, and it might be related.

Comment 3

[Julien Wajsberg [:julienw]]

(In reply to Kartikaya Gupta (email:[e-mail]) from comment #1)
> (In reply to Julien Wajsberg [:julienw] from comment #0)
> > I attached a APZC log I got using attachment 8402141 [details] [diff] [review]
> > [review] (that I rebased to central). This is the log from opening the
> > thread again as explained above, not a log from when the issue appeared in
> > the first place, so maybe it won't be useful enough.
> 
> Just to clarify - the log covers opening the thread for the second time (so
> the issue is visible), and then scrolling to fix the issue? I just want to
> be clear on exactly what's in the log, because it covers a 30-second time
> period and I want to make sure I look at the right bits.

Nope, it does not contains the scrolling part.

To be clear: I had the bug, ran adb logcat, tried again, stopped adb logcat, scrolled, and then thought "I should have taken a screenshot".

I think that the end of the log is just me leaving the phone without touching it at all.

(In reply to Kartikaya Gupta (email:[e-mail]) from comment #2)
> And yes, the displayport there looks wrong on one of the layers, it has a
> giant y-value and is sized to 0x0, so that would probably explain why you're
> not seeing anything. From the log it's not clear how it gets into that
> state, because it happens before the log starts (and anyway just APZC
> logging might not be sufficient to track that down). Really need reliable
> STR for this.

I have another log for you :)

> 
> Julien, before you ran into this issue, were you on any screen with a really
> really long scrollable area? Like 135000 pixels tall? If so that might
> explain why the displayport y-value is so big, and it might be related.

It could definitely be.
Basically, it involved moving in the SMS app between quite big threads and the thread list quite quickly, so maybe different things happen in the same time.

Comment 4

[Julien Wajsberg [:julienw]]

Attachment: another apzc.log

Here is another log, happened with this STR:

* opened a quite big thread
* scrolled it up quite quickly (when we do this, we toggle existing DOM elements from display:none to display:block, so that what's above is then displayed. The goal is to avoid reflowing all messages because the user likely wants to see the last page only).
* at one point, toggling existing DOM to display:block just made everything disappear, but it worked once or twice before, in the same scrolling movement.

This is when it happened for the first time, so you might have the reason in this log. Then I have the same behavior: when I go back to the thread list and open the thread again, I have the issue asap (no log for this this time). And when I scroll, it's then displayed.

Comment 5

[Julien Wajsberg [:julienw]]

Attachment: 2014-05-14-17-03-30.png

Screenshot for the second log

Comment 6

[Julien Wajsberg [:julienw]]

It seems I can quite reliably make it happen when I scroll while the reflow (triggered by the DOM change) is happening.

If you want to try on a device, you can try to flash a heavy or x-heavy workload:

  APP=sms make reference-workload-heavy

or

  APP=sms make reference-workload-x-heavy

The x-heavy workload is maybe too heavy for a buri.

Comment 7

[Julien Wajsberg [:julienw]]

I see this on v1.4 (Peak) too, but not on v1.3 (Inari).
One (possibly wrong) thought is that your patch from bug 987771 fixed this as well?

Comment 8

[Kartikaya Gupta (email:[e-mail])]

Ok, I went through the log and think I understand what's going on. The relevant lines in the log are listed and explained below, but I believe this is a regression from bug 978248.

05-14 16:58:51.921   135   337 I Gecko   : APZC: 0x45481800 got a NotifyLayersUpdated with aIsFirstPaint=0 layersId=36: i=(2 16) cb=(0 50 320 366) rcs=(320.000 456.000) dp=(0.000 -48.000 320.000 1024.000) dpm=(0.000 0.000 0.000 0.000) um=0 v=(0.000 50.000 320.000 366.000) s=(0.000 48.000) sr=(0.000 0.000 320.000 3099.300) z(ld=1.000 r=1.000 cr=1.000 z=1.000 ts=1.000) u=(0 0)
05-14 16:58:51.951   135   135 I Gecko   : APZC: Calculated displayport as (0.000000 0.000000 320.000000 988.199951) from velocity (0.000000 0.000000) paint time 38.788334 metrics: i=(2 16) cb=(0 50 320 366) rcs=(320.000 456.000) dp=(0.000 0.000 0.000 0.000) dpm=(25.010 0.000 432.490 0.000) um=1 v=(0.000 50.000 320.000 366.000) s=(0.000 0.000) sr=(0.000 0.000 320.000 3099.300) z(ld=1.000 r=1.000 cr=1.000 z=1.000 ts=1.000) u=(1 1065)
05-14 16:58:51.951   135   135 I Gecko   : APZC: 0x45481800 requesting content repaint: i=(2 16) cb=(0 50 320 366) rcs=(320.000 456.000) dp=(0.000 0.000 0.000 0.000) dpm=(0.000 0.000 622.200 0.000) um=1 v=(0.000 50.000 320.000 366.000) s=(0.000 0.000) sr=(0.000 0.000 320.000 3099.300) z(ld=1.000 r=1.000 cr=1.000 z=1.000 ts=1.000) u=(1 1065)

The above happens as the user is scrolling upwards, reaching the top of the scrollable content. We see an NLU come in with scroll offset (0, 48) - this is the result of the previous paint request from this APZC. In the third line above we see the APZC send a new paint request at the new scroll offset of (0,0) with margins that seem perfectly fine.

In the meantime, something in the front-end or layout or who knows where, changes the scroll offset to (0, 3216), putting it back at the bottom of the scrollable rect. We see the APZC get an NLU call which reflects this:

05-14 16:58:52.251   135   337 I Gecko   : APZC: 0x45481800 got a NotifyLayersUpdated with aIsFirstPaint=0 layersId=36: i=(2 16) cb=(0 50 320 366) rcs=(320.000 456.000) dp=(0.000 -144.000 320.000 1024.000) dpm=(0.000 0.000 0.000 0.000) um=0 v=(0.000 50.000 320.000 366.000) s=(0.000 3216.000) sr=(0.000 0.000 320.000 6290.300) z(ld=1.000 r=1.000 cr=1.000 z=1.000 ts=1.000) u=(1 1214)

Note the u=(1 1214) above which indicates that the update-scroll-offset flag is set on the metrics. Note also that the displayport here seems relatively sane; it starts 144px above the scroll position and is 1024px tall so it includes the visible area. After this point, we don't see any more paint requests go out from the APZC, because the last margins that the APZC sent are assumed to still be ok. Immediately after this, we see:

05-14 16:58:52.341   135   337 I Gecko   : APZC: 0x45481800 got a NotifyLayersUpdated with aIsFirstPaint=0 layersId=36: i=(2 16) cb=(0 50 320 366) rcs=(320.000 456.000) dp=(0.000 -3216.000 320.000 768.000) dpm=(0.000 0.000 0.000 0.000) um=0 v=(0.000 50.000 320.000 366.000) s=(0.000 3216.000) sr=(0.000 0.000 320.000 6290.300) z(ld=1.000 r=1.000 cr=1.000 z=1.000 ts=1.000) u=(0 0)

Here the scroll position is still at the bottom of the scrollable, but the displayport is all the way at the top. What happened? Looking at the code, I believe that the NLU with update-scroll-offset cross inflight with the last paint request that was sent, such that when the paint request was processed in APZCCallbackHelper, it had the wrong scroll generation. The call at [1] would set scrollUpdated=false and return the "actualScrollOffset" of (0, 3216). The scroll offset in the metrics would be (0, 0). As a result, the call at [2] would translate the margins up by 3216px, putting it where we see it come out in the last NLU call I showed above.

[1] http://mxr.mozilla.org/mozilla-central/source/gfx/layers/apz/util/APZCCallbackHelper.cpp?rev=1170c75f8a87#271
[2] http://mxr.mozilla.org/mozilla-central/source/gfx/layers/apz/util/APZCCallbackHelper.cpp?rev=1170c75f8a87#278

Comment 9

[Botond Ballo [:botond]]

MaybeAlignAndClampDisplayPort does two different things: 
  1) shift the displayport by the difference between the requested and actual scroll postitions
  2) align the displayport to tile boundaries and clamp it to the scrollable rect

Bug 978248 made MaybeAlignAndClampDisplayPort happen even when scrollUpdated = false, to make sure that (2) happens even on first paint.

This regression seems to be caused by (1) happening when scrollUpdated = false.

==> Perhaps we should split (1) and (2) into different functions, and only do (2) when scrollUpdated = false.

Comment 10

[Kartikaya Gupta (email:[e-mail])]

Attachment: Patch

Julien, can you try reproducing the problem with this patch applied? I believe this should fix it.

It's basically a backout of the regressing bug. I don't believe that patch is needed any more. According to bug 978248 comment 0 the code was needed because the initial displayport set by TabChild was not getting tile-aligned. But since then, bug 957668 has landed and been uplifted to aurora, and this changes TabChild to set the displayport as a margin value. The margin value is tile-aligned inside layout when the displayport is calculated for use, so the alignment patch should no longer be needed.

Comment 11

[Julien Wajsberg [:julienw]]

Comment on attachment 8422690 [details] [diff] [review]
Patch

Tried to do my STR again and I couldn't trigger the issue.

Thanks !!

Comment 12

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 8422690 [details] [diff] [review]
Patch

Review of attachment 8422690 [details] [diff] [review]:
-----------------------------------------------------------------

Awesome, thanks!

Comment 13

[Kartikaya Gupta (email:[e-mail])]

Attachment: Patch for 1.4

Comment 15

[Kartikaya Gupta (email:[e-mail])]

Requesting carry-over of 1.4+ from bug 1009162 which was duped to this.

Comment 16

[Julien Wajsberg [:julienw]]

Bug 1009162 makes me confident that other similar bugs I saw in the SMS app will be resolved too ! \o/

Comment 17

[Kartikaya Gupta (email:[e-mail])]

The patch in attachment 8422690 [details] [diff] [review] has a slight error: it doesn't remove the old call to MaybeAlign in UpdateRootFrame. The 1.4 version of the patch does that correctly. I discovered that while rebasing and I'll fix it on landing.

Comment 18

[Kartikaya Gupta (email:[e-mail])]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2928c68c0d8d

Comment 19

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/2928c68c0d8d

Comment 20

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/e31691ad752c

Comment 21

[Paladin]

Attachment: Verify_video.3gp

We can't reproduce this issue on latest Flame 2.0
Reproducing rate: 0/10
See Attachment:Verify_video.3gp
STR: 1. Open Message.
     2. Open a thread.
     3. Get back to the thread list.
     4. Tap the same thread.
    ** The content can be displayed normally.

Device Info:
Build ID               20150205000205
Gaia Revision          2989f2b2bd12fcc0e9c017d2db766e76a55873b8
Gaia Date              2015-01-22 21:13:40
Gecko Revision         https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/69057b33ef5b
Gecko Version          32.0
Device Name            flame
Firmware(Release)      4.4.2
Firmware(Incremental)  eng.cltbld.20150205.034605
Firmware Date          Thu Feb  5 03:46:16 EST 2015
Bootloader             L1TC000118D0