824658 - Long-lived loop decoding a PNG

Status: RESOLVED FIXED

(Core :: Graphics: ImageLib, defect)

Description

[Justin Lebar (not reading bugmail)]

We've seen this before, and I remember that it took us months to figure out what was going on.  Unfortunately I just saw it again.  :(

This loop was not infinite; it went away after a while.

I guess I'll try to catch it in gdb.

http://people.mozilla.com/~bgirard/cleopatra/#report=7ee7f6a5f43900029ad8624ab13f66b723ff66a3

Comment 1

[Justin Lebar (not reading bugmail)]

This seems to be happening quite often.  The jank is awful.

http://people.mozilla.com/~bgirard/cleopatra/#

Comment 2

[Justin Lebar (not reading bugmail)]

This bug also prevents Firefox from cleanly shutting down.  So a user will have to kill it using the task manager before starting Firefox up again.

Comment 3

[Justin Lebar (not reading bugmail)]

> http://people.mozilla.com/~bgirard/cleopatra/#

erm, sorry, I guess that's not a profile.  :)  Anyway, it looked just like the one in comment 0.

Comment 4

[Justin Lebar (not reading bugmail)]

I caught this in GDB and, before it segfaulted Firefox, I observed that we appeared to be discarding the image that we'd then re-decode.  We were discarding from the discard manager, which indicates that the image we were drawing was not locked.

Comment 5

[Justin Lebar (not reading bugmail)]

I've verified that some images are ::Drawn while discardable.  I suspect such images may be the problem here.

If so, my plan is to notice when an image is Drawn while discardable and discard it less aggressively.  (In particular, drawn-while-discardable images won't be subject to our hard cap on decoded image memory.)

But I need to test for a bit.

Comment 6

[Justin Lebar (not reading bugmail)]

This is bad, right?

> #0  mozilla::image::RasterImage::RequestDecodeCore (this=0x12c667b80, aDecodeType=<value temporarily unavailable, due to optimizations>) at ../../../../image/src/RasterImage.cpp:2784
> #1  0x0000000101362a45 in mozilla::image::RasterImage::GetImgFrame (this=0x12c667b80, framenum=0) at ../../../../image/src/RasterImage.cpp:817
> #2  0x0000000101363f17 in mozilla::image::RasterImage::SetFrameAsNonPremult (this=0x18, aFrameNum=1, aIsNonPremult=false) at ../../../../image/src/RasterImage.cpp:1567
> #3  0x000000010135ff90 in mozilla::image::Decoder::PostDecodeDone (this=0x10b2a6870) at ../../../../image/src/Decoder.cpp:282
> #4  0x000000010259a96b in MOZ_PNG_push_have_end [inlined] () at /Users/jlebar/code/moz/ff-inbound/src/media/libpng/pngpread.c:1453
> #5  0x000000010259a96b in MOZ_PNG_push_read_chunk (png_ptr=0x10fe9d800, info_ptr=0x127119a80) at ../../../../media/libpng/pngpread.c:2784
> #6  0x000000010259a52b in MOZ_PNG_proc_some_data [inlined] () at /Users/jlebar/code/moz/ff-inbound/src/media/libpng/pngpread.c:121
> #7  0x000000010259a52b in MOZ_PNG_process_data (png_ptr=0x10fe9d800, info_ptr=0x127119a80, buffer=<value temporarily unavailable, due to optimizations>, buffer_size=<value temporarily unavailable, due to optimizations>) at ../../../../media/libpng/pngpread.c:2784
> #8  0x000000010137f941 in mozilla::image::nsPNGDecoder::WriteInternal (this=<value temporarily unavailable, due to optimizations>, aBuffer=<value temporarily unavailable, due to optimizations>, aCount=<value temporarily unavailable, due to optimizations>) at ../../../../image/decoders/nsPNGDecoder.cpp:348
> #9  0x00000001013646e5 in mozilla::image::RasterImage::WriteToDecoder (this=0x12c667b80, aBuffer=0x12d647008 "?PNG\r\n\032\n", aCount=7867) at ../../../../image/src/RasterImage.cpp:2688
> #10 0x0000000101366aca in mozilla::image::RasterImage::DecodeWorker::DecodeSomeOfImage (this=<value temporarily unavailable, due to optimizations>, aImg=0x12c667b80, aDecodeType=mozilla::image::RasterImage::DecodeWorker::DECODE_TYPE_NORMAL) at ../../../../image/src/RasterImage.cpp:3200

Comment 7

[Justin Lebar (not reading bugmail)]

Yeah, and the image's lock count is 0, so as soon as it finishes decoding, we discard it.  Then the runnable comes 'round the mountain, and we're screwed.

Comment 8

[Justin Lebar (not reading bugmail)]

Here is my hypothesis as to how this is happening.

1. Image A's decode finishes.  Image A sets mDecoded = true.  Image A's lock
   count is 0, so it calls DiscardTracker::Reset.
   
2. DiscardTracker::Reset notices that we're low on memory and calls
   MaybeDiscardSoon, which enqueues a task to run DiscardTracker::DiscardNow.

3. From image B's Decoder::PostDecodeDone, we end up in RequestDecodeCore.
   This notices that mInDecoder and dispatches a new imgDecodeRequestor to the
   main thread.

4. Image B's decode finishes.  Its lock count is also 0.

5. DiscardTracker::DiscardNow runs.  This happens before image B's
   imgDecodeRequestor runs, because DiscardNow was enqueued after image A's
   decode.
   
   DiscardNow discards image B (and maybe also image A, but we don't care).

6. Image B's imgDecodeRequestor runs and decodes image B.

Comment 9

[Joe Drew (not getting mail)]

It really looks like we should modify SetFrameAsNonPremult (and similar) to call GetImgFrameNoDecode(), since they're called from within decoders. If we do we no longer call RequestDecode at all afaict.

Comment 10

[Justin Lebar (not reading bugmail)]

> It really looks like we should modify SetFrameAsNonPremult (and similar) to call GetImgFrameNoDecode(), since they're called from 
> within decoders.

I can do that.  But we've already had another bug just like this, so I also want to change the discard tracker so that it's more forgiving of this sort of thing.

Comment 11

[Justin Lebar (not reading bugmail)]

Heh, so: If you ever load a tab in the background, we'll decode images in that tab while they're unlocked.  And that's of course all you need to trigger this bug.

I'm becoming increasingly skeptical that this logic where we willingly keep only X kb of decoded image data can work properly.

If we're over the limit, should we even decode an unlocked image?  We're going to throw it away immediately...

Comment 12

[Justin Lebar (not reading bugmail)]

I'm probably seeing this problem when nobody else is because I've set image.mem.max_decoded_kb to 1024.  (I set this specifically to tickle bugs like this.)

But we set this value to 5mb on B2G, so it's not inconceivable that we'd hit this bug there.

Comment 13

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Attachment: Patch

Comment 14

[Justin Lebar (not reading bugmail)]

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

Whatchathink, joe?

khuey is also reworking the discard tracker to avoid this class of issue (per comment 10), but he says he's going to do this in a separate bug.

Comment 15

[Joe Drew (not getting mail)]

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

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

This looks lovely

Comment 16

[Justin Lebar (not reading bugmail)]

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

[Approval Request Comment]
Per comment 15, I'm afraid B2G is particularly susceptible to this bug.  It's hard to notice that it's occurring on the phone, except you'll run down your battery and the phone will be sluggish.

Imagelib changes are always scary, but I think we should take this.

No string changes, etc.

Comment 17

[Justin Lebar (not reading bugmail)]

> Per comment 15, I'm afraid B2G is particularly susceptible to this bug.

Sorry, comment 12.

Comment 18

[Justin Lebar (not reading bugmail)]

khuey is away, so I landed this with Joe's blessing so that we could get as much bake time on nightly as possible before porting to b2g.  Hope that's OK, Kyle!

https://hg.mozilla.org/integration/mozilla-inbound/rev/efc12cf7cf4a

(I realized that this may not have been pushed to try only after pushing this to inbound.  If it burns, let it be known that it's my fault, not khuey's.)

Comment 19

[Kyle Huey (Exited; not receiving bugmail, old account, do not use)]

Yep that's fine.  I was on a plane :-P

Comment 20

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/efc12cf7cf4a

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g18/rev/e85226806816

This be nominated for Aurora/Beta as well?

Comment 22

[Justin Lebar (not reading bugmail)]

(In reply to Ryan VanderMeulen from comment #21)
> https://hg.mozilla.org/releases/mozilla-b2g18/rev/e85226806816
> 
> This be nominated for Aurora/Beta as well?

0.5% of users (well, 0.5% of sessions) are hitting this bug.  I'm not sure if it's worth taking on Aurora and Beta.  Maybe Aurora, though.

http://goo.gl/tIBTX

Comment 23

[Justin Lebar (not reading bugmail)]

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

[Approval Request Comment]
* Bug caused by (feature/regressing bug #): Probably bug 732820.
* User impact if declined: 0.5% of users will experience high CPU usage and a janky browser for at least some minutes, possibly until they restart the browser.  This may also cause shutdown hangs.
* Testing completed (on m-c, etc.): On m-c.
* Risk to taking this patch (and alternatives if risky): I'd say moderate risk; imagelib changes often have regressions.  I'm not convinced this is worth taking on beta, but maybe it's worthwhile for Aurora.
String or UUID changes made by this patch: none

Comment 24

[Alex Keybl [:akeybl]]

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

Agreed on taking this on Aurora only given the risk profile. We're early enough in the Aurora cycle for this to get the necessary bake time for release.

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/0ef586dc6e57

Comment 26

[Justin Lebar (not reading bugmail)]

Oops, sorry guys.  I just pushed an empty cset for this to Aurora.

https://hg.mozilla.org/releases/mozilla-aurora/rev/6ee29f8c87d7

(It claims to have modified some files, but there's no diff in those files; this is a known bug in hg.)