Open Bug 886080 Opened 8 years ago Updated 5 years ago

Intermittent dynamic-feImage-01.svg | assertion count 1 is more than expected 0 assertions from ASSERTION: Double UnblockOnload!?: 'mCurrentRequestFlags & REQUEST_BLOCKS_ONLOAD'


(Core :: ImageLib, defect, P3)





(Reporter: philor, Unassigned)



(Keywords: assertion, intermittent-failure, Whiteboard: [leave open])


(1 file)
Ubuntu VM 12.04 mozilla-inbound debug test reftest on 2013-06-22 15:09:11 PDT for push 1ea803d6be37
slave: tst-linux32-ec2-071

16:31:10     INFO -  ###!!! ASSERTION: Double UnblockOnload!?: 'mCurrentRequestFlags & REQUEST_BLOCKS_ONLOAD', file ../../../../content/base/src/nsImageLoadingContent.cpp, line 641
16:31:10     INFO -  nsImageLoadingContent::UnblockOnload(imgIRequest*) [content/base/src/nsImageLoadingContent.cpp:640]
16:31:10     INFO -  imgRequestProxy::UnblockOnload() [image/src/imgRequestProxy.cpp:873]
16:31:10     INFO -  imgStatusTracker::SyncNotifyDifference(imgStatusTracker::StatusDiff) [image/src/imgStatusTracker.cpp:591]
16:31:10     INFO -  mozilla::image::RasterImage::FinishedSomeDecoding(mozilla::image::RasterImage::eShutdownIntent, mozilla::image::RasterImage::DecodeRequest*) [image/src/RasterImage.cpp:3102]
16:31:10     INFO -  mozilla::image::RasterImage::RequestDecodeCore(mozilla::image::RasterImage::RequestDecodeType) [image/src/RasterImage.cpp:2393]
16:31:10     INFO -  mozilla::image::RasterImage::StartDecoding() [image/src/RasterImage.cpp:2323]
16:31:10     INFO -  mozilla::dom::SVGFEImageElement::Notify(imgIRequest*, int, nsIntRect const*) [content/svg/content/src/SVGFEImageElement.cpp:299]
16:31:10     INFO -  imgRequestProxy::OnStartContainer() [image/src/imgRequestProxy.cpp:714]
16:31:10     INFO -  imgStatusTracker::SyncNotifyState(nsTObserverArray<imgRequestProxy*>&, bool, unsigned int, nsIntRect&, bool) [image/src/imgStatusTracker.cpp:486]
16:31:10     INFO -  imgStatusTracker::SyncNotify(imgRequestProxy*) [obj-firefox/dist/include/nsTObserverArray.h:356]
16:31:10     INFO -  imgRequestNotifyRunnable::Run() [image/src/imgStatusTracker.cpp:366]
16:31:10     INFO -  nsThread::ProcessNextEvent(bool, bool*) [xpcom/threads/nsThread.cpp:626]
16:31:10     INFO -  NS_ProcessNextEvent(nsIThread*, bool) [obj-firefox/xpcom/build/nsThreadUtils.cpp:238]
16:31:10     INFO -  mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:83]
16:31:10     INFO -  MessageLoop::RunInternal() [ipc/chromium/src/base/]
16:31:10     INFO -  MessageLoop::Run() [ipc/chromium/src/base/]
16:31:10     INFO -  nsBaseAppShell::Run() [widget/xpwidgets/nsBaseAppShell.cpp:165]
16:31:10     INFO -  nsAppStartup::Run() [toolkit/components/startup/nsAppStartup.cpp:270]
16:31:10     INFO -  XREMain::XRE_mainRun() [toolkit/xre/nsAppRunner.cpp:3857]
16:31:10     INFO -  XREMain::XRE_main(int, char**, nsXREAppData const*) [toolkit/xre/nsAppRunner.cpp:3924]
16:31:10     INFO -  XRE_main [toolkit/xre/nsAppRunner.cpp:4127]
16:31:10     INFO -  do_main [browser/app/nsBrowserApp.cpp:272]
16:31:10     INFO -  main [browser/app/nsBrowserApp.cpp:634]
16:31:10     INFO -  REFTEST TEST-PASS | file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/svg/dynamic-feImage-01.svg | image comparison (==)
16:31:10     INFO -  REFTEST INFO | Loading a blank page
16:31:10     INFO -  ++DOMWINDOW == 72 (0xbd5aaa8) [serial = 22356] [outer = 0xa229868]
16:31:10     INFO -  REFTEST TEST-UNEXPECTED-FAIL | file:///builds/slave/test/build/tests/reftest/tests/layout/reftests/svg/dynamic-feImage-01.svg | assertion count 1 is more than expected 0 assertions
Any ideas what might be going on here, jwatt?
Flags: needinfo?(jwatt)
I'm going to look at this.
Assignee: nobody → khuey
I caught this in the record and replay machine.  I'm on PTO the rest of this week so I may not investigate it immediately.
Alright I understand the problem.  Now to figure out what the fix is.
Flags: needinfo?(jwatt)
(In reply to Kyle Huey [:khuey] ( from comment #47)
> I caught this in the record and replay machine.  I'm on PTO the rest of this
> week so I may not investigate it immediately.

Ah great - thank you :-)
Attached patch PatchSplinter Review
This is a bandaid more than anything else, but I think it's what we want for now.  It effectively reverts part of Bug 792199.
Attachment #773934 - Flags: review?(joe)
Comment on attachment 773934 [details] [diff] [review]

Review of attachment 773934 [details] [diff] [review]:

This, as is, is totally safe, but I can't comment on the SVG code's requirements.
Attachment #773934 - Flags: review?(joe) → review+
Comment on attachment 773934 [details] [diff] [review]

Unfortunately it's not 100% non-notifying:

  return RequestDecodeCore(SYNCHRONOUS_NOTIFY);

I think we're going to create a third entry point, something that calls RequestDecodeCore(ASYNCHRONOUS), perhaps called AsyncRequestDecode or some such.
Attachment #773934 - Flags: review+ → review-
I don't have time to work on anything more complicated :-/
Assignee: khuey → nobody
Component: SVG → ImageLib
Kyle, could you post what you found (ie the relevant stack it sounds like) so someone else can pick this up?
Flags: needinfo?(khuey)
(In reply to Joe Drew (:JOEDREW! \o/) from comment #83)
> This, as is, is totally safe, but I can't comment on the SVG code's
> requirements.

It looks fine to me.
(In reply to Timothy Nikkel (:tn) from comment #89)
> Kyle, could you post what you found (ie the relevant stack it sounds like)
> so someone else can pick this up?

The problem is that we are dispatching notifications, the observer calls back into imagelib and does something that causes us to try to dispatch more notifications, and we end up dispatching them out of order.  The actual stack is:

 	xul.dll!NS_DebugBreak(unsigned int aSeverity=1, const char * aStr=0x684e4b3c, const char * aExpr=0x684e4df4, const char * aFile=0x684e4db0, int aLine=641)  Line 293	C++
 	xul.dll!nsImageLoadingContent::UnblockOnload(imgIRequest * aRequest=0x0ae3df00)  Line 641 + 0x26 bytes	C++
 	xul.dll!imgRequestProxy::UnblockOnload()  Line 875	C++
 	xul.dll!imgStatusTracker::SendUnblockOnload(imgRequestProxy * aProxy=0x0ae3df00)  Line 1030	C++
 	xul.dll!imgStatusTracker::SyncNotifyDifference(imgStatusTracker::StatusDiff diff={...})  Line 593	C++
 	xul.dll!mozilla::image::RasterImage::FinishedSomeDecoding(mozilla::image::RasterImage::eShutdownIntent aIntent=eShutdownIntent_Done, mozilla::image::RasterImage::DecodeRequest * aRequest=0x00000000)  Line 3104	C++
 	xul.dll!mozilla::image::RasterImage::RequestDecodeCore(mozilla::image::RasterImage::RequestDecodeType aDecodeType=SYNCHRONOUS_NOTIFY)  Line 2393 + 0xc bytes	C++
 	xul.dll!mozilla::image::RasterImage::StartDecoding()  Line 2324	C++
>	xul.dll!mozilla::dom::SVGFEImageElement::Notify(imgIRequest * aRequest=0x0ae3df00, int aType=1, const nsIntRect * aData=0x00000000)  Line 300	C++
 	xul.dll!imgRequestProxy::OnStartContainer()  Line 714	C++
 	xul.dll!imgStatusTracker::SyncNotifyState(nsTObserverArray<imgRequestProxy *> & proxies={...}, bool hasImage=true, unsigned int state=119, nsIntRect & dirtyRect={...}, bool hadLastPart=true)  Line 486 + 0x53 bytes	C++
 	xul.dll!imgStatusTracker::SyncNotify(imgRequestProxy * proxy=0x0ae3df00)  Line 628 + 0x40 bytes	C++
 	xul.dll!imgRequestNotifyRunnable::Run()  Line 369	C++
 	xul.dll!nsThread::ProcessNextEvent(bool mayWait=false, bool * result=0x0036f37f)  Line 626 + 0x19 bytes	C++
Flags: needinfo?(khuey)
Kyle and I also talked about this, and it's not clear whether this patch will fix the problem. It might make it less frequent, so I gave him verbal-r+ to land the patch as-is, leaving this bug open to collect failures that will definitely still occur (and find out how frequently they occur), but absent us doing one of:

1) Adding AsyncRequestDecode, which does absolutely no notification, and is used from places that do not want reentrant notifications, or
2) Changing imagelib to never do reentrant notification, which is absolutely possible, but when I tried it broke things

we can't fix this bug absolutely.

Only 2) will fix this *class* of bug, but it's got a lot of knock-on effects that someone will need to deal with.
Attachment #773934 - Flags: review- → review+
Whiteboard: [leave open]
Marked random-if on Linux for too many intermittent failures:
Whiteboard: [leave open] → [marked random-if on Linux][leave open]