Bug 191806 – Web Content process main thread blocked beneath ImageDecoderAVFObjC::readSamples for many seconds on imgur.com

• Component: Media
• Status: RESOLVED FIXED

Often when flipping through posts on imgur.com, the Web Content process’s main thread gets blocked for seconds beneath ImageDecoderAVFObjC::readSamples. Here’s an example (showing the trailing 3.12s of a longer hang):

  Thread 0x42edc8           DispatchQueue <multiple>  1000 samples (1-1000)     priority 0-46 (base 46)   cpu time 3.194s (12.5G cycles, 10.0G instructions, 1.25c/i)
  999  start + 1 (libdyld.dylib + 4117) [0x7fff6cbb6015]
    999  WebKit::XPCServiceMain(int, char const**) + 490 (WebKit + 1459226) [0x110dd341a]
      999  xpc_main + 433 (libxpc.dylib + 63946) [0x7fff6cf0f9ca]
        999  _xpc_objc_main + 580 (libxpc.dylib + 68983) [0x7fff6cf10d77]
          999  NSApplicationMain + 804 (AppKit + 23154) [0x7fff421e2a72]
            999  -[NSApplication run] + 764 (AppKit + 223365) [0x7fff42213885]
              999  -[NSApplication(NSEvent) _nextEventMatchingEventMask:untilDate:inMode:dequeue:] + 3044 (AppKit + 8224308) [0x7fff429b4e34]
                999  _DPSNextEvent + 2085 (AppKit + 268915) [0x7fff4221ea73]
                  999  _BlockUntilNextEventMatchingListInModeWithFilter + 64 (HIToolbox + 194692) [0x7fff43f6e884]
                    997  ReceiveNextEventCommon + 613 (HIToolbox + 195334) [0x7fff43f6eb06]
                      997  RunCurrentEventLoopInMode + 286 (HIToolbox + 195990) [0x7fff43f6ed96]
                        936  CFRunLoopRunSpecific + 483 (CoreFoundation + 544819) [0x7fff44c84033]
                          412  __CFRunLoopRun + 1293 (CoreFoundation + 546765) [0x7fff44c847cd]
                            412  __CFRunLoopDoSources0 + 208 (CoreFoundation + 549712) [0x7fff44c85350]
                              412  __CFRunLoopDoSource0 + 108 (CoreFoundation + 1430284) [0x7fff44d5c30c]
                                412  __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 17 (CoreFoundation + 669937) [0x7fff44ca28f1]
                                  312  __NSThreadPerformPerform + 334 (Foundation + 426165) [0x7fff46dc90b5]
                                    312  WTF::dispatchFunctionsFromMainThread() + 176 (JavaScriptCore + 271520) [0x1117524a0]
                                      312  WebCore::ImageDecoderAVFObjC::readSamples() + 224 (WebCore + 2388736) [0x780247300]
                                        312  -[AVAssetReaderTrackOutput copyNextSampleBuffer] + 68 (AVFoundation + 647318) [0x7fff40e75096]
                                          312  -[AVAssetReaderOutput copyNextSampleBuffer] + 151 (AVFoundation + 102837) [0x7fff40df01b5]
                                            312  ??? (MediaToolbox + 1877100) [0x7fff48f2b46c]
                                              312  FigSemaphoreWaitRelative + 149 (CoreMedia + 15095) [0x7fff45c35af7]
                                                312  WaitOnCondition + 11 (CoreMedia + 15418) [0x7fff45c35c3a]
                                                  312  __psynch_cvwait + 10 (libsystem_kernel.dylib + 117270) [0x7fff6cd06a16]
                                                   *312  psynch_cvcontinue + 0 (pthread + 38948) [0xffffff7f80f0d824]

This is with the latest Safari Technology Preview on macOS High Sierra.

[Radar WebKit Bug Importer]

<rdar://problem/46151477>

[Jer Noble]

Created attachment 356298 [details]
Patch

[EWS Watchlist]

Comment on attachment 356298 [details]
Patch

Attachment 356298 [details] did not pass mac-ews (mac):
Output: https://webkit-queues.webkit.org/results/10227482

New failing tests:
http/tests/images/mp4-partial-load.html

[EWS Watchlist]

Created attachment 356302 [details]
Archive of layout-test-results from ews101 for mac-sierra

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews101  Port: mac-sierra  Platform: Mac OS X 10.12.6

[EWS Watchlist]

Comment on attachment 356298 [details]
Patch

Attachment 356298 [details] did not pass mac-debug-ews (mac):
Output: https://webkit-queues.webkit.org/results/10227651

New failing tests:
http/tests/images/mp4-partial-load.html

[EWS Watchlist]

Created attachment 356303 [details]
Archive of layout-test-results from ews114 for mac-sierra

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews114  Port: mac-sierra  Platform: Mac OS X 10.12.6

[EWS Watchlist]

Comment on attachment 356298 [details]
Patch

Attachment 356298 [details] did not pass win-ews (win):
Output: https://webkit-queues.webkit.org/results/10228829

New failing tests:
http/tests/images/mp4-partial-load.html

[EWS Watchlist]

Created attachment 356306 [details]
Archive of layout-test-results from ews202 for win-future

The attached test failures were seen while running run-webkit-tests on the win-ews.
Bot: ews202  Port: win-future  Platform: CYGWIN_NT-6.1-2.10.0-0.325-5-3-x86_64-64bit

[Jer Noble]

Created attachment 356309 [details]
Patch

[Jer Noble]

Created attachment 356311 [details]
Patch

[EWS Watchlist]

Comment on attachment 356311 [details]
Patch

Attachment 356311 [details] did not pass win-ews (win):
Output: https://webkit-queues.webkit.org/results/10231607

New failing tests:
http/tests/images/mp4-partial-load.html

[EWS Watchlist]

Created attachment 356317 [details]
Archive of layout-test-results from ews200 for win-future

The attached test failures were seen while running run-webkit-tests on the win-ews.
Bot: ews200  Port: win-future  Platform: CYGWIN_NT-6.1-2.9.0-0.318-5-3-x86_64-64bit

[Jer Noble]

Created attachment 356407 [details]
Patch

[EWS Watchlist]

Comment on attachment 356407 [details]
Patch

Attachment 356407 [details] did not pass mac-ews (mac):
Output: https://webkit-queues.webkit.org/results/10253910

New failing tests:
http/tests/images/mp4-partial-load.html

[EWS Watchlist]

Created attachment 356424 [details]
Archive of layout-test-results from ews101 for mac-sierra

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews101  Port: mac-sierra  Platform: Mac OS X 10.12.6

[EWS Watchlist]

Comment on attachment 356407 [details]
Patch

Attachment 356407 [details] did not pass win-ews (win):
Output: https://webkit-queues.webkit.org/results/10254742

New failing tests:
http/tests/images/mp4-partial-load.html

[EWS Watchlist]

Created attachment 356432 [details]
Archive of layout-test-results from ews204 for win-future

The attached test failures were seen while running run-webkit-tests on the win-ews.
Bot: ews204  Port: win-future  Platform: CYGWIN_NT-6.1-2.10.0-0.325-5-3-x86_64-64bit

[EWS Watchlist]

Comment on attachment 356407 [details]
Patch

Attachment 356407 [details] did not pass mac-debug-ews (mac):
Output: https://webkit-queues.webkit.org/results/10254159

New failing tests:
http/tests/images/mp4-partial-load.html

[EWS Watchlist]

Created attachment 356433 [details]
Archive of layout-test-results from ews117 for mac-sierra

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews117  Port: mac-sierra  Platform: Mac OS X 10.12.6

[Dean Jackson]

Comment on attachment 356407 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=356407&action=review

> Source/WebCore/PAL/pal/cf/CoreMediaSoftLink.h:262
> +SOFT_LINK_FUNCTION_FOR_HEADER(PAL, CoreMedia, CMBlockBufferCreateWithMemoryBlock, OSStatus, (CFAllocatorRef structureAllocator, void* memoryBlock, size_t blockLength, CFAllocatorRef blockAllocator, const CMBlockBufferCustomBlockSource* customBlockSource, size_t offsetToData, size_t dataLength, CMBlockBufferFlags flags, CMBlockBufferRef* blockBufferOut), (structureAllocator, memoryBlock, blockLength, blockAllocator, customBlockSource, offsetToData, dataLength, flags, blockBufferOut))
> +#define CMBlockBufferCreateWithMemoryBlock softLink_CoreMedia_CMBlockBufferCreateWithMemoryBlock

Can we remove the things that you replaced from this file? e.g. allocAVAssetReaderTrackOutputInstance?

[Jer Noble]

Created attachment 358285 [details]
Patch for landing

[Alexey Proskuryakov]

Comment on attachment 358285 [details]
Patch for landing

View in context: https://bugs.webkit.org/attachment.cgi?id=358285&action=review

> Source/WebCore/rendering/RenderImage.cpp:264
> +    WTFLogAlways("RenderImage::imageChanged");

These are not in ChangeLog. Are these changes for landing?

[Jer Noble]

(In reply to Alexey Proskuryakov from comment #22)
> Comment on attachment 358285 [details]
> Patch for landing
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=358285&action=review
> 
> > Source/WebCore/rendering/RenderImage.cpp:264
> > +    WTFLogAlways("RenderImage::imageChanged");
> 
> These are not in ChangeLog. Are these changes for landing?

Whoops, no those were compile-time debugging statements. Will remove before landing.

[EWS Watchlist]

Comment on attachment 358285 [details]
Patch for landing

Attachment 358285 [details] did not pass win-ews (win):
Output: https://webkit-queues.webkit.org/results/10622181

New failing tests:
http/tests/images/mp4-partial-load.html

[EWS Watchlist]

Created attachment 358298 [details]
Archive of layout-test-results from ews203 for win-future

The attached test failures were seen while running run-webkit-tests on the win-ews.
Bot: ews203  Port: win-future  Platform: CYGWIN_NT-6.1-2.9.0-0.318-5-3-x86_64-64bit

[Jer Noble]

Created attachment 358332 [details]
Patch for landing

[WebKit Commit Bot]

Comment on attachment 358332 [details]
Patch for landing

Clearing flags on attachment: 358332

Committed r239636: <https://trac.webkit.org/changeset/239636>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Zan Dobersek]

Comment on attachment 358332 [details]
Patch for landing

View in context: https://bugs.webkit.org/attachment.cgi?id=358332&action=review

> Source/WebCore/platform/graphics/ImageSource.cpp:84
>      m_decoder = ImageDecoder::create(*data, mimeType(), m_alphaOption, m_gammaAndColorProfileOption);
> +    m_decoder->setEncodedDataStatusChangeCallback([weakThis = makeWeakPtr(this)] (auto status) {
> +        if (weakThis)
> +            weakThis->encodedDataStatusChanged(status);
> +    });
>      if (!isDecoderAvailable())
>          return false;

The isDecoderAvailable() check should be moved before the setEncodedDataStatusChangeCallback() call in case a null object is returned from ImageDecoder::create(). I think this is a possibility only when ScalableImageDecoder is used underneath. Bug #193187 has the patch.

[Said Abou-Hallawa]

Comment on attachment 358332 [details]
Patch for landing

View in context: https://bugs.webkit.org/attachment.cgi?id=358332&action=review

> Source/WebCore/platform/graphics/ImageSource.cpp:81
> +        if (weakThis)
> +            weakThis->encodedDataStatusChanged(status);

This relationship ImageDecoder -> ImageSource is weird and hidden. There is no other place in the code where an ImageDecoder has or needs access to the ImageSource. For all other decoders, the encoded data is managed by the ImageSource. Only the EncodedDataStatus has to be calculated by the ImageDecoder. But it is weird that ImageDecoderAVFObjC is managing the  encoded data, the decoded data and the EncodedDataStatus.

I would suggest one of these solutions: 

1. Create the superclass ImageSourceAVFObjC to handle the encoded data of the video image. In this case you would not need to make ImageDecoderAVFObjC owns a weak back pointer to ImageSource.

2. Make the back-pointer accessible from the ImageDecoder always and not only from this callback. And make ImageDecoder call the function in the ImageSource directly:
    ImageSource::ensureDecoderAvailable():
         m_decoder = ImageDecoder::create(this, *data, ...);
    ImageDecoderAVFObjC::readSamples():
        if (m_source)
            m_source ->encodedDataStatusChanged(encodedDataStatus());

I prefer the first solution more than the second.

> Source/WebCore/platform/graphics/ImageSource.cpp:172
> +    m_encodedDataStatus = status;
> +
> +    if (status >= EncodedDataStatus::SizeAvailable)
> +        growFrames();
> +
> +    if (m_image && m_image->imageObserver())
> +        m_image->imageObserver()->encodedDataStatusChanged(*m_image, status);

Part of this code is repeated in ImageSource::dataChanged(). Can we refactor the code such that one place in ImageSource rebuilds its internal structures when the encoded data changes?

[Jer Noble]

(In reply to Said Abou-Hallawa from comment #30)
> Comment on attachment 358332 [details]
> Patch for landing
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=358332&action=review
> 
> > Source/WebCore/platform/graphics/ImageSource.cpp:81
> > +        if (weakThis)
> > +            weakThis->encodedDataStatusChanged(status);
> 
> This relationship ImageDecoder -> ImageSource is weird and hidden. There is
> no other place in the code where an ImageDecoder has or needs access to the
> ImageSource. For all other decoders, the encoded data is managed by the
> ImageSource. Only the EncodedDataStatus has to be calculated by the
> ImageDecoder. But it is weird that ImageDecoderAVFObjC is managing the 
> encoded data, the decoded data and the EncodedDataStatus.

The weirdness is due to ImageSource assuming that the decoder can determine the encodedDataStatus synchronously after the data has been provided by the network. In the case of ImageDecoderAVFObjC, this is not possible.  Without some way of notifying upstream that decoding has progressed, clients of ImageDecoderAVFObjC will never realize image data is available.

> I would suggest one of these solutions: 
> 
> 1. Create the superclass ImageSourceAVFObjC to handle the encoded data of
> the video image. In this case you would not need to make ImageDecoderAVFObjC
> owns a weak back pointer to ImageSource.

I'm not sure why this would be a benefit. You'd still need a weak back pointer for the decoder to talk to the source, but now you've added another class just for that purpose.

The current implementation does not require ImageDecoder to know anything about the client whatsoever. This is a good thing, as it allows ImageDecoder to be re-used by objects other than ImageSource.

> 2. Make the back-pointer accessible from the ImageDecoder always and not
> only from this callback. And make ImageDecoder call the function in the
> ImageSource directly:
>     ImageSource::ensureDecoderAvailable():
>          m_decoder = ImageDecoder::create(this, *data, ...);
>     ImageDecoderAVFObjC::readSamples():
>         if (m_source)
>             m_source ->encodedDataStatusChanged(encodedDataStatus());
> 
> I prefer the first solution more than the second.

I don't prefer either of these.  A third option would be to move to a fully asynchronous model where setData() takes a Callback object when processing of the data completes, similar to how network processing works. Then this specific callback wouldn't be necessary, and it would allow experiments such as decoding asynchronously on background threads.

> > Source/WebCore/platform/graphics/ImageSource.cpp:172
> > +    m_encodedDataStatus = status;
> > +
> > +    if (status >= EncodedDataStatus::SizeAvailable)
> > +        growFrames();
> > +
> > +    if (m_image && m_image->imageObserver())
> > +        m_image->imageObserver()->encodedDataStatusChanged(*m_image, status);
> 
> Part of this code is repeated in ImageSource::dataChanged(). Can we refactor
> the code such that one place in ImageSource rebuilds its internal structures
> when the encoded data changes?

Sure can!