517804 - Try to avoid reflows and new invalidations during painting

Status: RESOLVED FIXED

(Core :: Web Painting, defect)

Description

[Markus Stange [:mstange]]

Attachment: v1

When we dispatch an NS_PAINT event during drawRect:, the view manager flushes pending reflows and invalidations before painting. Doing this during drawRect: has several drawbacks:
 - Changing view geometry during painting is not supported by Cocoa. We
   shouldn't do it.
 - Sometimes we can even re-enter drawing: For example if you change the width
   attribute of a <popup>, the resulting reflow will change the width of the
   popup's NSWindow, which will cause a synchronous repaint. Doing this inside
   drawRect: causes bugs like bug 517801.
 - Invalidations during drawRect won't get coalesced with the invalidations that
   caused the current repaint, which results in double painting in some cases,
   for example in bug 453541.

Mac OS 10.5 gives us a much better places for the flush: [NSView viewWillDraw].
We should use it.

Comment 1

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Comment on attachment 401762 [details] [diff] [review]
v1

You don't need the changes to content/events/src, right?

Otherwise looks good.

Comment 2

[Markus Stange [:mstange]]

Attachment: v2

Comment 3

[Josh Aas]

Comment on attachment 401774 [details] [diff] [review]
v2

We still need to support 10.4 on trunk even though we have that turned off, it looks to me like this just won't do anything on 10.4. So long as this is true, r+.

Comment 4

[Markus Stange [:mstange]]

Right, this has no effect on 10.4.

Comment 5

[Markus Stange [:mstange]]

http://hg.mozilla.org/mozilla-central/rev/7799cfb99362

Comment 6

[Boris Zbarsky [:bzbarsky]]

> For example if you change the width attribute of a <popup>, the resulting
> reflow will change the width of the popup's NSWindow, which will cause a
> synchronous repaint.

"synchronous" like "right in the middle of the reflow"?  That's not good at all.  Is there a bug on this?

Comment 7

[Johnathan Nightingale [:johnath]]

This looks like it has caused some pretty impressive wins on Leopard.

15% on Ts:

http://graphs.mozilla.org/graph.html#tests=[{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%2263%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%2264%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%2265%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%2266%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22168%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22169%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22170%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22171%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22172%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22173%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22174%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22175%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22176%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22177%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22178%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22179%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22180%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22181%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22182%22}]&sel=1253432340,1253605140

and 5% on Txul:

http://graphs.mozilla.org/graph.html#tests=[{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%2263%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%2264%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%2265%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%2266%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22168%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22169%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22170%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22171%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22172%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22173%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22174%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22175%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22176%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22177%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22178%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22179%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22180%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22181%22},{%22test%22:%2217%22,%22branch%22:%221%22,%22machine%22:%22182%22}]

Comment 8

[Boris Zbarsky [:bzbarsky]]

And a 53% Ts shutdown regression, no?

Comment 9

[Boris Zbarsky [:bzbarsky]]

Which makes me wonder whether it's just a matter of changing timing so that work that used to count as part of Ts started counting as part of Tshutdown (and similarly for the Txul, except we don't time window-closing time).

Comment 10

[Markus Stange [:mstange]]

(In reply to comment #6)
> > For example if you change the width attribute of a <popup>, the resulting
> > reflow will change the width of the popup's NSWindow, which will cause a
> > synchronous repaint.
> 
> "synchronous" like "right in the middle of the reflow"?  That's not good at
> all.  Is there a bug on this?

Oh, looks like it doesn't happen during reflow after all. It happens during nsView::ResetWidgetBounds, which is apparently outside reflow. Stack trace is in bug 517801.

(In reply to comment #8)
> And a 53% Ts shutdown regression, no?

I'm investigating.

(In reply to comment #9)
> Which makes me wonder whether it's just a matter of changing timing so that
> work that used to count as part of Ts started counting as part of Tshutdown
> (and similarly for the Txul, except we don't time window-closing time).

This would really surprise me. The performance wins in this bug come from doing work *sooner* - work that we would have done anyway a moment later.

The only way I can explain the shutdown regression to me right now is that viewWillDraw can get called at times where no call to drawRect will follow - maybe because the window has already closed. But I need to look into this more.

Comment 11

[Markus Stange [:mstange]]

I haven't been able to reproduce the shutdown regression locally, but I started tryserver builds with some logging.

It's worth looking at the performance numbers in absolute terms:
The patch made startup 200ms faster and shutdown 80ms slower.

Comment 12

[Markus Stange [:mstange]]

Hmm, the full Talos logs apparently don't contain console output from Ts runs, so my debug printfs are useless. Unless somebody insists on it, I'll stop the investigation here and just point out the overall win.

Comment 13

[Boris Zbarsky [:bzbarsky]]

> Hmm, the full Talos logs apparently don't contain console output from Ts runs,

That's odd.  Alice, any idea what's up there?

> just point out the overall win.

We have a loss on one benchmark; a win on another.  If it has to be that way, so be it.  But we need to try to fix the loss, imo; we can't just randomly accept 50% losses on our perf benchmarks just because the patch speeds up _another_ of our perf benchmarks without trying to mitigate the fallout.

Probably need a separate bug on this....

Comment 14

[Johnathan Nightingale [:johnath]]

(In reply to comment #13)
> We have a loss on one benchmark; a win on another.  If it has to be that way,
> so be it.  But we need to try to fix the loss, imo; we can't just randomly
> accept 50% losses on our perf benchmarks just because the patch speeds up
> _another_ of our perf benchmarks without trying to mitigate the fallout.

I agree, my initial enthusiasm notwithstanding, we can make a Ts-for-Tshutdown trade IFF we understand the source of both and think that the win is important enough (and "real" enough - not just an artifact of the way we make our measurements) to outweigh the loss.

Right now, we have a patch with surprising performance results including a potentially serious regression on a benchmark that we know we have problems with. I don't think I'd vote separate bug here, I'd vote backout and reopen - that's how we deal with regressions that aren't understood and agreed-to.

Sorry Markus, not trying to make your life difficult - I've backed my own patches out for regressions that didn't make any sense, it sucks. But it's the only mechanism we have for preserving and improving our performance (and our measurements!)

Comment 15

[Shawn Wilsher :sdwilsh]

(In reply to comment #14)
> Right now, we have a patch with surprising performance results including a
> potentially serious regression on a benchmark that we know we have problems
> with. I don't think I'd vote separate bug here, I'd vote backout and reopen -
> that's how we deal with regressions that aren't understood and agreed-to.
I have to agree.  It sucks, but we need to understand the TShutdown regression before we can say we can live with it.

Comment 16

[Markus Stange [:mstange]]

I'm not sure we're on the same page here. The Ts test works like this:
 1. Timestamp A is recorded.
 2. The browser is launched.
 3. Timestamp B is recorded during the onload handler.
 4. The browser is quit.
 5. Timestamp C is recorded.

Now the values are computed as follows:
 ts = B - A,
 ts_shutdown = C - B

The patch in this bug caused ts to drop from 1600 to 1400ms, and ts_shutdown to
increase from 160 to 240ms.

So there are two things here:
 - I don't think a 80ms shutdown regression is potentially serious.
 - C - A has dropped by 120ms. This is the "overall win" that I mentioned.

You've convinced me to look into the shutdown regression again, but I wanted to
make sure that we're looking at the absolute numbers.

Comment 17

[alice nodelman [:alice] [:anode]]

In response to comment #13, talos records whatever the browser dumps to console and all of it is written to the log.  If there's nothing there it's because the browser had no messages.

Comment 18

[Markus Stange [:mstange]]

Oh, sorry. I'll look more closely this time.

Comment 19

[Shawn Wilsher :sdwilsh]

(In reply to comment #16)
>  - I don't think a 80ms shutdown regression is potentially serious.
80ms on a nice new profile.  We have lots of bugs about long shutdowns.  How does 80ms translate to them?

>  - C - A has dropped by 120ms. This is the "overall win" that I mentioned.
We've backed out lots of stuff before that was a win in one benchmark and a loss in another.  If we always take wins in various places, but all the losses in one place, that one place that took all the losses is going to suffer.  We have a policy of zero performance regressions (that we don't do a good job of enforcing) without explicit approval.  This needs to be backed out until the regression is understood.

Comment 20

[Markus Stange [:mstange]]

Backed out.

Comment 21

[Markus Stange [:mstange]]

I've found my debug printfs in the logs. It helps if you don't look for debug-only log messages... And I've started new builds with more helpful logging.

Comment 22

[Tom Dyas]

Small nit on the patch:  The NSView docs say that [super viewWillDraw] must be called by all overrides.  The patch doesn't do that.

http://developer.apple.com/mac/library/documentation/Cocoa/Reference/ApplicationKit/Classes/NSView_Class/Reference/NSView.html#//apple_ref/occ/instm/NSView/viewWillDraw

Comment 23

[Markus Stange [:mstange]]

Oh, thanks.

Comment 24

[Tom Dyas]

Only relevant if there are subviews probably.

Comment 25

[Markus Stange [:mstange]]

This is how the log looks between B and C without the fix:

NOISE: __startTimestamp1253669481626__endTimestamp
NOISE:  6 | (1024 x 746) (viewWillDraw)
NOISE:  7 | (1024 x 746) drawRect:
NOISE: (876, 731, 128, 12) (11, 66, 16, 15) (33, 66, 206, 15) (11, 64, 16, 2) 
NOISE: --flushing--
NOISE: painting box 11, 64, 993, 679
NOISE:  7 | (1024 x 746) (viewWillDraw)
NOISE:  8 | (1024 x 746) drawRect:
NOISE: (7, 731, 855, 15) (11, 66, 16, 15) (33, 66, 206, 15) (11, 64, 16, 2) (124, 0, 40, 39) 
NOISE: --flushing--
NOISE: painting box 7, 0, 855, 746
NOISE: __startSecondTimestamp1253669481781__endSecondTimestamp

1253669481781 - 1253669481626 = 155

And this is how it looks with the fix:

NOISE: __startTimestamp1253667428558__endTimestamp
NOISE:  4 | (1024 x 746) viewWillDraw
NOISE: --flushing--
NOISE:  6 | (1024 x 746) drawRect:
NOISE: (7, 731, 855, 15) (11, 66, 16, 15) (33, 66, 206, 15) (11, 64, 16, 2) (124, 0, 40, 39) 
NOISE: --flushing--
NOISE: painting box 7, 0, 855, 746
NOISE: __startSecondTimestamp1253667428803__endSecondTimestamp

1253667428803 - 1253667428558 = 245

--

Note that we're drawing less but taking longer.
The next thing I'll try is to add timestamps in more places.

Comment 26

[Markus Stange [:mstange]]

Result from the investigation in bug 519893: The ts_shutdown regression this patch caused is an artifact of unrealistic testing conditions. It only applies to machines without screens.

I'll reland this patch.

Comment 27

[Markus Stange [:mstange]]

Relanded:
http://hg.mozilla.org/mozilla-central/rev/3cdaf0a84414

Comment 28

[Markus Stange [:mstange]]

This blocks blocker bug 498340, so it should block, too.

Comment 29

[Dão Gottwald [:dao]]

http://hg.mozilla.org/releases/mozilla-1.9.2/rev/4d8660a55a7e

Comment 30

[Markus Stange [:mstange]]

(In reply to comment #22)
> Small nit on the patch:  The NSView docs say that [super viewWillDraw] must be
> called by all overrides.  The patch doesn't do that.

Sorry, I totally forgot about this when I relanded. I've filed bug 532878.

Comment 31

[Honza Bambas (:mayhemer)]

This bug has caused regression bug 537530 on 1.9.2.