Bug 227366 – REGRESSION: http/tests/preload/onload_event.html is a flaky timeout on Big Sur wk1 Release

• Status: RESOLVED
• Resolution: FIXED
• Component: Page Loading

http/tests/preload/onload_event.html (layout-tests)

Flaky time out failure 

History: https://results.webkit.org/?suite=layout-tests&test=http%2Ftests%2Fpreload%2Fonload_event.html

[Radar WebKit Bug Importer]

<rdar://problem/79733280>

I was able to reproduce this timeout using command:run-webkit-tests http/tests/preload/onload_event.html --iterations 500 -f --force -1

[Alexey Proskuryakov]

This test is usually very fast, so timing out means that it fails.

This started 2020-06-03. It seems important to find out when this started.

I was able to reproduce the issues with the earliest revision and it seems like the issue has been happening since the test began running on Big Sur

Created attachment 432294 [details]
Expectations

[Alexey Proskuryakov]

What were your steps to reproduce? This looks like a regression the bots.

[Ryan Haddad]

(In reply to Alexey Proskuryakov from comment #6)
> What were your steps to reproduce? This looks like a regression the bots.
The steps are in https://bugs.webkit.org/show_bug.cgi?id=227366#c2, but it would be good to know what "the earliest revision" tested was.

[Truitt Savell]

(In reply to Alexey Proskuryakov from comment #6)
> What were your steps to reproduce? This looks like a regression the bots.

Ayumi was able to reproduce this with command:
run-webkit-tests http/tests/preload/onload_event.html --iterations 500 -f --force -1

I confirmed this repro case on my system as well. 

I just ran this test on an old spade (278188) and was unable to reproduce it there. So I think we will be able to bisect to find where this regressed.

[EWS]

Committed r279300 (239176@main): <https://commits.webkit.org/239176@main>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 432294 [details].

[Alexey Proskuryakov]

Created attachment 432313 [details]
sample

[Alexey Proskuryakov]

Not sure if it's truly a regression. Did we happen to update the bots on 2020-06-03?

Samples captured by bots happen to show what happens (and I reproduced the same locally). DumpRenderTree permanently freezes in AVFoundation!

    +                     989 WebCore::ThreadTimers::sharedTimerFiredInternal()  (in WebCore) + 198  [0x11337c4a6]  ThreadTimers.cpp:127
    +                       989 WebCore::PageGroup::captionPreferencesChanged()  (in WebCore) + 248  [0x1132d2d88]  PageGroup.cpp:108
    +                         989 WebCore::Page::captionPreferencesChanged()  (in WebCore) + 53  [0x1132c46d5]  Page.cpp:2807
    +                           989 WebCore::Page::forEachDocument(WTF::Function<void (WebCore::Document&)> const&) const  (in WebCore) + 334  [0x1132bb5be]  Page.cpp:3334
    +                             989 WebCore::Document::captionPreferencesChanged()  (in WebCore) + 52  [0x112c9f134]  Document.cpp:5706
    +                               989 WTF::WeakHashSet<WebCore::HTMLMediaElement, WTF::EmptyCounter>::forEach(WTF::Function<void (WebCore::HTMLMediaElement&)> const&)  (in WebCore) + 352  [0x112c8d7f0]  WeakHashSet.h:148
    +                                 989 WebCore::HTMLMediaElement::captionPreferencesChanged()  (in WebCore) + 66  [0x112ee6a82]  HTMLMediaElement.cpp:6550
    +                                   989 WebCore::MediaPlayerPrivateAVFoundationObjC::tracksChanged()  (in WebCore) + 728  [0x111d3d3b8]  MediaPlayerPrivateAVFoundationObjC.mm:2057
    +                                     989 -[AVAsset tracksWithMediaCharacteristics:]  (in AVFCore) + 54  [0x7fff316eba1b]
    +                                       989 -[AVAssetTrackEnumerator initWithAsset:mediaCharacteristics:]  (in AVFCore) + 30  [0x7fff316f24f7]
    +                                         989 -[AVAssetTrackEnumerator initWithAsset:]  (in AVFCore) + 82  [0x7fff316b8fb3]
    +                                           989 -[AVURLAsset tracks]  (in AVFCore) + 136  [0x7fff316b898c]
    +                                             989 _dispatch_lane_barrier_sync_invoke_and_complete  (in libdispatch.dylib) + 60  [0x7fff203925ce]
    +                                               989 _dispatch_client_callout  (in libdispatch.dylib) + 8  [0x7fff20385806]
    +                                                 989 __20-[AVURLAsset tracks]_block_invoke  (in AVFCore) + 72  [0x7fff316f151b]
    +                                                   989 -[AVAsset _tracksWithClass:]  (in AVFCore) + 129  [0x7fff316eb8cd]
    +                                                     989 -[AVFigAssetInspector trackCount]  (in AVFCore) + 32  [0x7fff31772de4]
    +                                                       989 -[AVFigObjectInspector _nonNilArrayForProperty:]  (in AVFCore) + 17  [0x7fff317bed76]
    +                                                         989 -[AVFigObjectInspector _tollFreeBridgedObjectForProperty:]  (in AVFCore) + 17  [0x7fff317bed38]
    +                                                           989 -[AVFigAssetInspector _valueAsCFTypeForProperty:]  (in AVFCore) + 101  [0x7fff31772acf]
    +                                                             989 ???  (in MediaToolbox)  load address 0x7fff2c0d3000 + 0x4e1bbd  [0x7fff2c5b4bbd]
    +                                                               989 _dispatch_group_wait_slow  (in libdispatch.dylib) + 49  [0x7fff2038626b]
    +                                                                 989 _dlock_wait  (in libdispatch.dylib) + 44  [0x7fff20385fd7]
    +                                                                   989 __ulock_wait  (in libsystem_kernel.dylib) + 10  [0x7fff204fb9ee]


And that in turn is caused by a freeze between WebCoreResourceHandleAsOperationQueueDelegate and CFNetwork.

[Ryan Haddad]

This may line up with when we updated the Big Sur bots to macOS 11.4

[Jer Noble]

Classic AVFoundation deadlock:

- MainThread is querying for state on AVAssetTrack
- URLAssetWorkQueue.I thread is requesting more data from WebCore to fulfill query
- WebCore dispatches to MainThread to do networking

The real fix is to move either all of networking to a dedicated runloop/thread/queue, or to move all of AVFoundation access to a dedicated runloop/thread/queue.

[Jer Noble]

Short term, we should query assetStatus() before iterating over an asset's tracks.

[Jer Noble]

Created attachment 435025 [details]
Patch

[EWS]

Committed r280766 (240351@main): <https://commits.webkit.org/240351@main>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 435025 [details].