I was looking at shark profiles of the testcase in bug 424715, and saw that we're spending the vast majority of our time in painting. Not only that, but we're entering painting via three different codepaths: sometimes from native cocoa event processing, sometimes from cocoa event processing triggered by appshell when it waits for events(?). Its not clear to me whether we end up processing the same paint event multiple times; joelr volunteered to look into that. Profile of us on this testcase: http://web.mit.edu/bzbarsky/www/profiles/bug424715/suspected-paint-profile.mshark Profile of a webkit nightly on the same testcase: http://web.mit.edu/bzbarsky/www/profiles/bug424715/raytracer-webkit.mshark We take 2x as long as the webkit nightly. One interesting thing is that if I change the testcase to NOT set innerHTML with the time after processing each line our time drops by a factor of 4. I suspect we're being bitten by simplifying a region to include lots of the previous raytracer pixels there. I'll double-check that, but wanted to check the paint entrypoint thing as well.

Markus might be able to look into the event loop thing as well.

I'm not ready to claim anything conclusive but WebKit uses CGContextFillRect whereas we use CGContextFillPath. I have a hunch that the former is much faster.

I don't see WebKit filling paths at all, e.g. WebKit: 1) WebCore::RenderBox::paintFillLayer() -> CGContextFillRect 0.0% 42.6% WebCore WebCore::RenderBox::paintFillLayer(WebCore::RenderObject::PaintInfo const&, WebCore::Color const&, WebCore::FillLayer const*, int, int, int, int, WebCore::CompositeOperator) 1.0% 42.4% WebCore WebCore::RenderBoxModelObject::paintFillLayerExtended(WebCore::RenderObject::PaintInfo const&, WebCore::Color const&, WebCore::FillLayer const*, int, int, int, int, WebCore::InlineFlowBox*, WebCore::CompositeOperator) 0.3% 40.1% WebCore WebCore::GraphicsContext::fillRect(WebCore::FloatRect const&, WebCore::Color const&) 0.2% 27.9% CoreGraphics CGContextFillRect Firefox: 1) nsCSSRendering::PaintBackground() results in a CGContextFillPath 0.0% 16.5% XUL nsCSSRendering::PaintBackground(nsPresContext*, nsIRenderingContext&, nsIFrame*, nsRect const&, nsRect const&, unsigned int, nsRect*) 0.6% 16.0% XUL nsCSSRendering::PaintBackgroundWithSC(nsPresContext*, nsIRenderingContext&, nsIFrame*, nsRect const&, nsRect const&, nsStyleBackground const&, nsStyleBorder const&, unsigned int, nsRect*) 0.0% 12.6% XUL _moz_cairo_fill_preserve 0.1% 12.6% XUL _cairo_gstate_fill 0.0% 12.4% XUL _cairo_surface_fill 0.1% 12.1% XUL _cairo_quartz_surface_fill 0.0% 5.8% CoreGraphics CGContextFillPath 2) PaintBackgroundLayer seems to trigger a path fill as well. 0.0% 0.0% XUL PaintBackgroundLayer(nsPresContext*, nsIRenderingContext&, nsIFrame*, unsigned int, nsRect const&, nsRect const&, nsRect const&, nsStyleBackground const&, nsStyleBackground::Layer const&) 0.0% 0.0% XUL _cairo_path_fixed_fini 0.0% 0.0% XUL gfxContext::Rectangle(gfxRect const&, int) 0.0% 0.0% XUL gfxContext::NewPath() 0.0% 0.0% XUL gfxContext::Fill()

That sounds like a cairo-quartz issue that should be filed separately from this bug. This bug really is about whether we're painting the same area 2 or more times when we should only do it once.

Fair enough. I filed the same comments in [https://bugzilla.mozilla.org/show_bug.cgi?id=424715 Bug 424715].

You should really put them into a new mac-gfx-specific bug.

(In reply to comment #0) > Not only that, but we're entering painting via three different codepaths: Three? > sometimes from native cocoa event processing, sometimes from cocoa event > processing triggered by appshell when it waits for events(?). Yes, nsAppShell::OnProcessNextEvent starts a nested event loop, so there are two functions that call [NSApplication nextEventMatchingMask:...]: [NSApplication run] and nsAppShell::ProcessNextNativeEvent. I think Steven Michaud knows why we need a nested event loop in OnProcessNextEvent. > Its not clear to me whether we end up processing the same paint event > multiple times; Even if we did, Cocoa would only ask us to repaint the dirty region once. Dirty regions aren't stored in paint events, they're stored on the NSView and get cleared after each drawRect call. I'll add some printfs and see whether that's really true, but I think it's unlikely that we're painting twice.

Note that we do the re-entrant event processing for all kinds of events, not only paint events. So if there was a problem with double processing events we'd probably have noticed by now.

> Three? Yes, there are two different callstacks to entering it via the appshell. See the shark files... If we're not double-processing paints, that's good (and this bug should be marked invalid). ;)

Native events (Cocoa events) can be processed from nsAppShell::Run() and from nsAppShell::ProcessNextNativeEvent(). Calls to nsAppShell::ProcessNextNativeEvent() (from various places in nsBaseAppShell::OnProcessNextEvent()) are needed to prevent native event starvation while processing Gecko events. But there's only a single "stream" of native events (from the window server). So processing them in multiple "locations" won't (in itself) cause these events to handled more than once.

The specific issues that concerned me were: 1) Under nsAppShell::OnProcessNextEvent we seem to be doing significant drawing on two different NSViews. Why? See the 60% branch of the profile, which breaks up into 38% and 22%. Are we sure we're not painting the same area twice there (via those different NSViews)? 2) The painting under a function that looked like it was just trying to get but not dequeue the next event matching a mask was weird to me, but if you say this is correct (and that it dequeues events as needed), then fine.

> 2) The painting under a function that looked like it was just trying to get > but not dequeue the next event matching a mask was weird to me, If this is actually happening, it's wrong. Where, exactly, is the evidence for this?

Hmm. Maybe this was the call that does say to dequeue the event. I'm looking at this callstack (reading from the top down): nsAppShell::ProcessNextNativeEvent -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] _DPSNextEvent BlockUntilNextEventMatchingListInMode ReceiveNextEventCommon RunCurrentEventLoopInMode CFRunLoopRunInMode CFRunLoopRunSpecific __CFRunLoopDoObservers _handleWindowNeedsDisplay -[NSWindow displayIfNeeded] Is that an expected callstack?

> -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] You need to be able to tell what 'dequeue' value was passed in. If 'true', then this stack is normal (though it's missing several levels between nsAppShell::ProcessNextEvent and the next line). If 'false' then we've got a problem -- though that's probably an Apple bug.

> (though it's missing several levels between nsAppShell::ProcessNextEvent and > the next line) Oops, I was reading the stack the wrong way. If the first call is the top one (nsAppShell::ProcessNextNativeEvent), and the second call ([NSApplication nextEventMatchingMask...]) was made from it, there (probably) aren't any missing levels. The rest of what I said still applies, though.

ProcessNextNativeEvent called nextEventMatchingMask. It may well have passed true for dequeue; this is a profile, not a debugger stack, so I don't have the arguments. If that behavior is expected in that situation, great! What about the two separate NSViews we're painting on?

> What about the two separate NSViews we're painting on? That'll take more time to figure out. We're almost certainly not painting them at *exactly* the same time -- as far as I know only one NSView can be focused for drawing at a time (the OS only calls lockFocus and drawRect on one NSView at a time). And I assume your profile shows calls over a span of time -- not those actually taking place simultaneously.

Yes, indeed.

Oh and in case you didn't know -- OS-triggered drawing takes place always and only in the [NSView drawRect:] method.

> See the 60% branch of the profile, which breaks up into 38% and 22%. Alright, I've got your firefox-bin Shark profile open ... but I can't find any of this.

You're looking at http://web.mit.edu/bzbarsky/www/profiles/bug424715/suspected-paint-profile.mshark yes? You need to drill down from the toplevel... What _are_ you seeing?

I think I've figured it out now -- I needed to chose the "Tree (Top-Down)" view (in the lower right), instead of the default "Heavy (Bottom-Up)" view. Now I see two entries for [ChildView drawRect:] -- one labeled 37.7% and called (indirectly) from [NSView _recursiveDisplayRectIfNeededIgnoringOpacity:...], the other labeled 22.1% and called (indirectly) from [NSView _recursiveDisplayAllDirtyWithLockFocus:...]. In the WebKit kit trace I see just one entry for WebKit's equivalent of [ChildView drawRect:] ([WebHTMLView drawRect:]), labeled 66.1% and called from [NSView _recursiveDisplayRectIfNeededIgnoringOpacity:...]. I'm almost certain the Firefox trace doesn't show paint events being "processed twice". It also doesn't appear that Firefox's calls to drawRect: take any more time (as a percentage) than WebKit's calls to drawRect:. I'm puzzled why Firefox has two paths to drawRect: ... but I don't see any convincing evidence that this is a bad thing.

> Now I see two entries for [ChildView drawRect:] Yes, those are the two I was talking about. > time (as a percentage) Webkit's baseline is 2x smaller; so we're taking similar time as a percentage (actually more; there's another paint entrypoint in our profile that's another 30% of total time; scroll down to the __CFRunLoopDoObservers call that comes directly from the toplevel CFRunLoopRunSpecific). > but I don't see any convincing evidence that this is a bad thing. Honestly, the point of this bug report wasn't to present convincing evidence of anything; I don't know this code well enough to do that. The point was to note something that looked odd and hopefully get someone qualified to do so (not me, so far) to investigate _whether_ there's a problem. That still needs to happen, unless we have convincing evidence there _isn't_ a problem (which could just be in the form of your knowledge of the code, of course; that's already eliminated a number of "this could be wrong" possibilities here).

Or put yet another way, I'm not saying "we can make painting faster in this case" ; I'm saying "painting is 90% of our total time in this case and we're 2x slower than webkit; can we do anything to make the painting faster other than making the paint operations themselves take less time?"

Note bug 516924. Once that lands, I'll reprofile here.

I just applied that locally and rechecked. The "[NSView _recursiveDisplayAllDirtyWithLockFocus:...]" codepath into painting went away completely with that patch (and the time dropped significantly). Markus, did we in fact end up painting twice due to the focus rect thing? If we were, we should mark this bug fixed once bug 516924 lands. If not, then invalid.

I still don't think your traces show double-painting, or that double-painting is in fact going on. (Markus's comments at bug 516924 show excess painting, but no increase in the number of times painting occurs.) In fact it's only in retrospect (thanks to Markus) that they show anything at all -- apparently redrawing the whole view is more likely to cause drawRect: to be called from [NSView _recursiveDisplayAllDirtyWithLockFocus:...]. But though your traces don't really show anything, your having opened this bug got Markus to do some debugging. And (thanks to his previous experience with using NSCells for drawing) he *was* able to find a drawing problem. So I think this bug is invalid. But if you hadn't opened it, Markus might not have discovered the problem (or at least not as soon as he did). Funny how these things sometimes work out :-)

Hey, I'm more interested in stuff getting fixed than in the status of particular bugs. Please resolve as desired. ;)

Doing the deed

(In reply to comment #26) > I just applied that locally and rechecked. The "[NSView > _recursiveDisplayAllDirtyWithLockFocus:...]" codepath into painting went away > completely with that patch Sounds like AllDirty means "all views with dirty focus rings". But I agree with Steven: there was only excess painting, no double-painting. One more piece of information: Painting the same regions into two different NSViews is prevented by a part in drawRect that subtracts the subview rects from the painting region. Since we don't have overlapping sibling views, this pretty much guarantees that we don't double-paint.

> Sounds like AllDirty means "all views with dirty focus rings". Actually I suspect AllDirty means all "dirty" NSViews (ones that have been at least partially invalidated, and therefore need updating). I'd guess [NSView _recursiveDisplayAllDirtyWithLockFocus:...] only calls drawRect: if an entire view is "dirty" (and needs to be completely repainted). Otherwise drawRect: gets called from [NSView _recursiveDisplayRectIfNeededIgnoringOpacity:...]. If you run any Cocoa app and break on these methods, you'll see that both get called a lot, and that DisplayAllDirty gets called from DisplayRectIfNeeded. Furthermore, maybe DisplayAllDirty just looks (recursively) for NSViews that need to be completely repainted, and leaves ones that only need partial repainting (or no repainting at all) to DispalyRectIfNeeded. Or maybe you're right, Markus. It's all a black box, so it's difficult to be really sure :-)