Bug 191806 - Web Content process main thread blocked beneath ImageDecoderAVFObjC::readSamples for many seconds on imgur.com
Summary: Web Content process main thread blocked beneath ImageDecoderAVFObjC::readSamp...
Status: RESOLVED FIXED
Alias: None
Product: WebKit
Classification: Unclassified
Component: Media (show other bugs)
Version: Safari Technology Preview
Hardware: Unspecified Unspecified
: P2 Normal
Assignee: Jer Noble
URL:
Keywords: InRadar
Depends on:
Blocks:
 
Reported: 2018-11-17 09:24 PST by mitz
Modified: 2019-01-07 13:54 PST (History)
13 users (show)

See Also:


Attachments
Patch (32.70 KB, patch)
2018-12-01 00:07 PST, Jer Noble
no flags Details | Formatted Diff | Diff
Archive of layout-test-results from ews101 for mac-sierra (2.56 MB, application/zip)
2018-12-01 01:13 PST, EWS Watchlist
no flags Details
Archive of layout-test-results from ews114 for mac-sierra (2.01 MB, application/zip)
2018-12-01 02:02 PST, EWS Watchlist
no flags Details
Archive of layout-test-results from ews202 for win-future (12.86 MB, application/zip)
2018-12-01 04:53 PST, EWS Watchlist
no flags Details
Patch (33.86 KB, patch)
2018-12-01 09:29 PST, Jer Noble
no flags Details | Formatted Diff | Diff
Patch (33.86 KB, patch)
2018-12-01 09:49 PST, Jer Noble
no flags Details | Formatted Diff | Diff
Archive of layout-test-results from ews200 for win-future (12.83 MB, application/zip)
2018-12-01 11:22 PST, EWS Watchlist
no flags Details
Patch (33.88 KB, patch)
2018-12-03 14:45 PST, Jer Noble
dino: review+
ews-watchlist: commit-queue-
Details | Formatted Diff | Diff
Archive of layout-test-results from ews101 for mac-sierra (2.53 MB, application/zip)
2018-12-03 15:38 PST, EWS Watchlist
no flags Details
Archive of layout-test-results from ews204 for win-future (12.80 MB, application/zip)
2018-12-03 16:30 PST, EWS Watchlist
no flags Details
Archive of layout-test-results from ews117 for mac-sierra (2.13 MB, application/zip)
2018-12-03 16:30 PST, EWS Watchlist
no flags Details
Patch for landing (38.68 KB, patch)
2019-01-03 16:04 PST, Jer Noble
no flags Details | Formatted Diff | Diff
Archive of layout-test-results from ews203 for win-future (12.91 MB, application/zip)
2019-01-03 18:17 PST, EWS Watchlist
no flags Details
Patch for landing (34.09 KB, patch)
2019-01-04 10:34 PST, Jer Noble
no flags Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description mitz 2018-11-17 09:24:15 PST
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.
Comment 1 Radar WebKit Bug Importer 2018-11-17 12:14:03 PST
<rdar://problem/46151477>
Comment 2 Jer Noble 2018-12-01 00:07:25 PST
Created attachment 356298 [details]
Patch
Comment 3 EWS Watchlist 2018-12-01 01:13:31 PST Comment hidden (obsolete)
Comment 4 EWS Watchlist 2018-12-01 01:13:34 PST Comment hidden (obsolete)
Comment 5 EWS Watchlist 2018-12-01 02:02:53 PST Comment hidden (obsolete)
Comment 6 EWS Watchlist 2018-12-01 02:02:55 PST Comment hidden (obsolete)
Comment 7 EWS Watchlist 2018-12-01 04:53:42 PST Comment hidden (obsolete)
Comment 8 EWS Watchlist 2018-12-01 04:53:54 PST Comment hidden (obsolete)
Comment 9 Jer Noble 2018-12-01 09:29:21 PST
Created attachment 356309 [details]
Patch
Comment 10 Jer Noble 2018-12-01 09:49:51 PST
Created attachment 356311 [details]
Patch
Comment 11 EWS Watchlist 2018-12-01 11:22:25 PST Comment hidden (obsolete)
Comment 12 EWS Watchlist 2018-12-01 11:22:37 PST Comment hidden (obsolete)
Comment 13 Jer Noble 2018-12-03 14:45:14 PST
Created attachment 356407 [details]
Patch
Comment 14 EWS Watchlist 2018-12-03 15:38:02 PST
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
Comment 15 EWS Watchlist 2018-12-03 15:38:04 PST
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
Comment 16 EWS Watchlist 2018-12-03 16:29:55 PST
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
Comment 17 EWS Watchlist 2018-12-03 16:30:07 PST
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
Comment 18 EWS Watchlist 2018-12-03 16:30:31 PST
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
Comment 19 EWS Watchlist 2018-12-03 16:30:33 PST
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
Comment 20 Dean Jackson 2018-12-04 09:57:16 PST
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?
Comment 21 Jer Noble 2019-01-03 16:04:51 PST
Created attachment 358285 [details]
Patch for landing
Comment 22 Alexey Proskuryakov 2019-01-03 16:22:44 PST
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?
Comment 23 Jer Noble 2019-01-03 16:29:33 PST
(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.
Comment 24 EWS Watchlist 2019-01-03 18:17:00 PST
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
Comment 25 EWS Watchlist 2019-01-03 18:17:12 PST
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
Comment 26 Jer Noble 2019-01-04 10:34:21 PST
Created attachment 358332 [details]
Patch for landing
Comment 27 WebKit Commit Bot 2019-01-04 13:32:57 PST
Comment on attachment 358332 [details]
Patch for landing

Clearing flags on attachment: 358332

Committed r239636: <https://trac.webkit.org/changeset/239636>
Comment 28 WebKit Commit Bot 2019-01-04 13:32:59 PST
All reviewed patches have been landed.  Closing bug.
Comment 29 Zan Dobersek 2019-01-06 23:45:17 PST
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.
Comment 30 Said Abou-Hallawa 2019-01-07 09:45:43 PST
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?
Comment 31 Jer Noble 2019-01-07 13:54:05 PST
(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!