1184763 - tp5 with e10s enabled spends time in 'imgRequestProxy::StartDecoding()'

Status: RESOLVED FIXED

(Core :: Graphics: ImageLib, defect)

Description

[Benoit Girard (:BenWa)]

The next issue that stands out from the tp5 regressions when you enabled e10s (bug 1174776) is that we're now spending time in 'imgRequestProxy::StartDecoding()' where we don't really spend any time during non-e10s tp5.

Let's find out why that is.

Comment 1

[Benoit Girard (:BenWa)]

Here are the profiles again. You should add 'StartDecoding' in the filter box (on the left hand side) and see that it only really shows up under e10s:

Non e10s:
http://people.mozilla.org/~bgirard/cleopatra/?zippedProfile=http://mozilla-releng-blobs.s3.amazonaws.com/blobs/Try-Non-PGO/sha512/3f1cf539d64869a3159e7cb1934e3b47112b5cfea8cdb5b8a2208f2d44c46ec326601ef87c617547dccd865533b2bc9497031b8bf7a91e797c3d2ce43036430f&pathInZip=profile_tp5o/youtube.com/cycle_0.sps

e10s with bug 1184277 fixed:
http://people.mozilla.org/~bgirard/cleopatra/?zippedProfile=http://mozilla-releng-blobs.s3.amazonaws.com/blobs/Try/sha512/668bbef25bc4815042eb84b15d3850eda7a6db200988b8243e528ac81374f9c8984a7c6e8e6de33051c9edc8cee96095c9f416d13266a2dce2213c752eade5c2&pathInZip=profile_tp5o/youtube.com/cycle_0.sps

Comment 2

[Benoit Girard (:BenWa)]

I'll start looking.

In the mean time :seth does anything off the top of your head explain this? Why would none e10s tp5 not hit 'StartDecoding'?

Comment 3

[Timothy Nikkel (:tnikkel)]

The e10s profile looks like it's calling StartDecoding from nsImageLoadingContent::OnLoadComplete.

The things in there that might be different on e10s are:
shell->IsVisible()
shell->IsPaintingSuppressed()
shell->AssumeAllImagesVisible()

Comment 4

[Benoit Girard (:BenWa)]

Looks like nsImageLoadingContent::OnLoadComplete fires in both places but only e10s is hitting 'nsImageLoadingContent::Notify(imgIRequest*, int, mozilla::gfx::IntRectTyped<mozilla::gfx::UnknownUnits> const*)'.

Comment 5

[Timothy Nikkel (:tnikkel)]

I think nsImageLoadingContent::Notify is the only caller of nsImageLoadingContent::OnLoadComplete, so probably just an artifact of the profile.

Comment 6

[Benoit Girard (:BenWa)]

Well both profiles seem to spend time under imgRequestProxy::RemoveFromLoadGroup(bool). So it looks like a bit of time under 'nsImageLoadingContent::OnLoadComplete' is normal before e10s.

Comment 7

[Benoit Girard (:BenWa)]

I confirmed that the Optimize behavior is the same on mac with and without e10s.

There's just something that's causing the XCB calls to take longer under e10s. It's likely that's we're hitting some kind of contention with the windowing server like we've on other platforms.

It would be good to explain where this new contention is coming from. This problem is likely Linux specific.

Comment 8

[Benoit Girard (:BenWa)]

Let's have a look at what happens with XRender disabled:

before e10s:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=86ccfb7dc7af

after e10s + cc fixes:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=0723b0255ea4

Comment 9

[Benoit Girard (:BenWa)]

Yea, this problem goes away with XRender disabed (but we're still left with a regression).

Comment 10

[Benoit Girard (:BenWa)]

without e10s without xrender:
http://people.mozilla.org/~bgirard/cleopatra/?zippedProfile=http://mozilla-releng-blobs.s3.amazonaws.com/blobs/Try/sha512/bad6e3b82e4a6b0ddad59ea3f3fe132e5943d9c0e9f827739dd3e7b9441a38ab63233abf0a2e1eae79f97d98904d62d58621260d4883fb2599fb0394167707b4&pathInZip=profile_tp5o/youtube.com/cycle_0.sps

with e10s without xrender:
http://people.mozilla.org/~bgirard/cleopatra/?zippedProfile=http://mozilla-releng-blobs.s3.amazonaws.com/blobs/Try/sha512/65ec93ac6fca8f50cd96d3893aa0e405d1893c5a75794244ce197b78618b74534d5dc40eea39a9cb65c42d9d082b34a155eec7a5bf0863ca268708d3960f8e6c&pathInZip=profile_tp5o/youtube.com/cycle_0.sps

Comment 11

[Benoit Girard (:BenWa)]

More (all of the \o/!) try pushes to understand the issue better:

without e10s with xrender without throbber:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=8e23115d4ab0

without e10s without xrender without throbber:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=a1e65c16ef11

with e10s without xrender without throbber:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=87dedb31301c

with e10s with xrender without throbber:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=25378a68a246

Comment 12

[Benoit Girard (:BenWa)]

I'm not sure that's there anything we really want to do here. We're just hitting contention and it's not likely to be cause by the Optimize call itself but by us requesting X to do more work elsewhere leading to this added contention.

Comment 13

[Mike Conley (:mconley) (:⚙️)]

We noticed that the imagelib cache is busted with e10s (bug 1217571). I'm not 100% familiar with our image decoding infrastructure, but it sounds like fixing the cache might result in us decoding less.

So let's fix the imagelib cache thing and see if this goes away.

Comment 14

[George Wright (:gw280) (needinfo me!)]

The imagelib cache bug is now fixed in Nightly. Probably worth reprofiling at this point.

Comment 15

[Brad Lassey [:blassey] (use needinfo?)]

fixed by fixing the image cache