890305 - nsThreadPool (+ streamCopier) may introduce long hangs and CPU load

Status: NEW

(Core :: XPCOM, defect)

Description

[Honza Bambas (:mayhemer)]

During work on the new cache we were using (for some time - as a workaround) thread pool for async copy of output stream pipe.  We allowed some 25 active and idle threads.  Writing it self (to files) were happening on background, but despite that main thread and actually whole system was catastrophically suffering from usage of stream copier and the pool - there where huge main thread janks and enormous CPU load.

Example callstack I've caught on a slowed virtual machine and also on my natively slow mac (CPU load went to 120% on that machine :)):

>	nss3.dll!PR_Lock(PRLock * lock)  Line 202	C
 	nss3.dll!PR_EnterMonitor(PRMonitor * mon)  Line 67 + 0x6 bytes	C
 	xul.dll!nsThreadPool::PutEvent(nsIRunnable * event)  Line 76	C++
 	xul.dll!nsThreadPool::Dispatch(nsIRunnable * event, unsigned int flags)  Line 240	C++
 	xul.dll!nsStreamTransportService::Dispatch(nsIRunnable * task, unsigned int flags)  Line 467	C++
 	xul.dll!nsAStreamCopier::PostContinuationEvent_Locked()  Line 435	C++
 	xul.dll!nsAStreamCopier::PostContinuationEvent()  Line 425 + 0x7 bytes	C++
 	xul.dll!nsAStreamCopier::Start(nsIInputStream * source, nsIOutputStream * sink, nsIEventTarget * target, void (void *, tag_nsresult)* callback, void * closure, unsigned int chunksize, bool closeSource, bool closeSink, void (void *, unsigned int)* progressCallback)  Line 254 + 0x7 bytes	C++
 	xul.dll!NS_AsyncCopy(nsIInputStream * source, nsIOutputStream * sink, nsIEventTarget * target, nsAsyncCopyMode mode, unsigned int chunkSize, void (void *, tag_nsresult)* callback, void * closure, bool closeSource, bool closeSink, nsISupports * * aCopierCtx, void (void *, unsigned int)* progressCallback)  Line 586	C++
 	xul.dll!mozilla::net::CacheEntry::OpenOutputStreamInternal(__int64 offset, nsIOutputStream * * _retval)  Line 919	C++
 	xul.dll!mozilla::net::CacheEntry::OpenOutputStream(__int64 offset, nsIOutputStream * * _retval)  Line 840	C++
 	xul.dll!mozilla::net::CacheEntry::Handle::OpenOutputStream(__int64 offset, nsIOutputStream * * _retval)  Line 129 + 0x19 bytes	C++
 	xul.dll!mozilla::net::nsHttpChannel::InstallCacheListener(__int64 offset)  Line 3661 + 0x1b bytes	C++
 	xul.dll!mozilla::net::nsHttpChannel::ContinueProcessNormal(tag_nsresult rv)  Line 1367	C++
 	xul.dll!mozilla::net::nsHttpChannel::ProcessNormal()  Line 1297	C++
 	xul.dll!mozilla::net::nsHttpChannel::ProcessResponse()  Line 1208	C++
 	xul.dll!mozilla::net::nsHttpChannel::OnStartRequest(nsIRequest * request, nsISupports * ctxt)  Line 4697 + 0xb bytes	C++
 	xul.dll!nsInputStreamPump::OnStateStart()  Line 422	C++
 	xul.dll!nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream * stream)  Line 383	C++
 	xul.dll!nsOutputStreamReadyEvent::Run()  Line 83	C++ 


The hang was really long, pool thread was in the lock on almost all other threads.


What I want to suggest here is we should check what all code is using thread pool heavily and try to reduce the usage or fix the thread pool code to be jank free.  One consumer I know of is image decoding that I've already caught ones (now fixed) on causing janks.

Comment 1

[(no longer active)]

I also use a thread pool in the implementation of AudioContext.decodeAudioData <http://mxr.mozilla.org/mozilla-central/source/content/media/webaudio/MediaBufferDecoder.cpp#745>

Comment 2

[Benjamin Smedberg]

I don't understand this bug yet. The thread pool lock should have very small critical sections, and certainly not be holding the lock over any kind of I/O or long-running task. When you say "thread pool was in the lock on almost all other threads" we need the details about those threads, since it sounds like the lock is being held incorrectly.

Comment 3

[Wayne Mery (:wsmwk)]

Still valid?

Comment 4

[Honza Bambas (:mayhemer)]

No idea, and I also don't know if this could be accidentally fixed.  OTOH, I also don't know about happening this in the wild.

It would be great to try to construct the same code as I originally reported this for and actually analyze the problem.  But it would be quite complicated and doesn't have a high priority.