1034309 - Extremely slow image load - MessagePumpForNonMainThreads may delay events for minutes

Status: RESOLVED WORKSFORME

(Core :: IPC, defect)

Description

[Honza Bambas (:mayhemer)]

Attachment: mozilla-img-thread.zip

m-c@caefe18d7ffe + few local changes (unrelated), opt build, win7.

Loading a page with 5 images each having ~5 MB (jpgs).  Loading from the HTTP cache (content valid).


Problem: the 5 images load all extremely slowly.


Reason is that the MessagePumpForNonMainThreads from some reason doesn't process events immediately when they are dispatched to the target thread (here the ImageDecoder), in this case data-availability event from Cache I/O thread to ImageDecoder threads.

In the log search for "NotifyChunkListenerEvent::NotifyChunkListenerEvent" that is dispatched from IO thread to the Image thread.  "NotifyChunkListenerEvent::Run" then is logged when the even is actually run.

(Checked this is NOT an HTTP cache bug)


Filtered log snippet (68ed4a0, 195eaf20) of "timestamp,threadnames,cache2:5,nsThread:5" :

2014-07-03 21:14:59.992000 UTC - [Cache2 I/O] 5196[911360]: CacheFile::NotifyChunkListener() [this=195fc540, listener=13ba6f68, target=68ed4a0, rv=0x00000000, idx=10, chunk=a35c740]
2014-07-03 21:14:59.992000 UTC - [Cache2 I/O] 5196[911360]: NotifyChunkListenerEvent::NotifyChunkListenerEvent() [this=195eaf20]
2014-07-03 21:14:59.992000 UTC - [Cache2 I/O] 5196[911360]: THRD(68ed4a0) Dispatch [195eaf20 0]

delay of more then 1 minute...

2014-07-03 21:16:02.485000 UTC - [ImageDecoder #7] 4304[72af0c0]: THRD(68ed4a0) ProcessNextEvent [0 0]
2014-07-03 21:16:02.485000 UTC - [ImageDecoder #7] 4304[72af0c0]: THRD(68ed4a0) running [195eaf20]
2014-07-03 21:16:02.485000 UTC - [ImageDecoder #7] 4304[72af0c0]: NotifyChunkListenerEvent::Run() [this=195eaf20] 


The stack the event is run at is:

 	xul.dll!mozilla::net::NotifyChunkListenerEvent::Run() Line 91	C++
 	xul.dll!nsThread::ProcessNextEvent(false, 0x230ff75f) Line 768	C++
 	xul.dll!NS_ProcessNextEvent(0x018ed4a0, false) Line 284	C++
	xul.dll!mozilla::ipc::MessagePumpForNonMainThreads::Run(0x0a380140) Line 337	C++
 	xul.dll!MessageLoop::RunHandler() Line 223	C++
 	xul.dll!MessageLoop::Run() Line 197	C++
 	xul.dll!nsThread::ThreadFunc(0x068ed4a0) Line 357	C++
 	nss3.dll!_PR_NativeRunThread(0x0a37c3d0) Line 419	C
 	nss3.dll!pr_root(0x072af0c0) Line 90	C

Comment 1

[Honza Bambas (:mayhemer)]

I'll expose the test case on my web and link here.

Comment 2

[Honza Bambas (:mayhemer)]

Test case:
http://janbambas.cz/moz/bug1034309/

Make sure the images all go from cache (304 or even unvalidated cache load), load the page once and then F5 will do.

Comment 3

[Honza Bambas (:mayhemer)]

Any idea?

Comment 4

[Ben Turner (not reading bugmail, use the needinfo flag!)]

Nothing off the top of my head. We use this pump on all threads now so if there is a race it's somehow not a very common one or we would have seen this before now.

Comment 5

[Honza Bambas (:mayhemer)]

Looks I have to look at this...

Comment 6

[Ben Kelly [:bkelly, not reviewing]]

It seems likely this is due to this code:

    // This will either sleep or process an event.
    NS_ProcessNextEvent(mThread, true);

Here:

  http://dxr.mozilla.org/mozilla-central/source/ipc/glue/MessagePump.cpp#355

If the chromium message_loop gets a task posted from the IO thread while the worker thread is blocked in that NS_ProcessNextEvent(aMayWait=true), then the thread will not be woken up.

Comment 7

[Ben Kelly [:bkelly, not reviewing]]

Sorry, you can ignore comment 6.  The MessagePump::ScheduleWork() does a dispatch to the gecko thread which should wake up the NS_ProcessNextEvent().

Comment 8

[Honza Bambas (:mayhemer)]

Haven't seen this for a while.