Bug 73688 - REGRESSION (r91738): didFinishLoad is called before custom fonts have finished loading
Summary: REGRESSION (r91738): didFinishLoad is called before custom fonts have finishe...
Alias: None
Product: WebKit
Classification: Unclassified
Component: CSS (show other bugs)
Version: 528+ (Nightly build)
Hardware: Unspecified Unspecified
: P1 Normal
Assignee: mitz
Keywords: InRadar, Regression
Depends on:
Reported: 2011-12-02 13:32 PST by mitz
Modified: 2012-02-01 12:50 PST (History)
5 users (show)

See Also:

Ensure that font loads that are waiting to begin prevent didFinishLoad from being called (24.72 KB, patch)
2011-12-02 13:56 PST, mitz
darin: review+
Details | Formatted Diff | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description mitz 2011-12-02 13:32:21 PST
After <http://trac.webkit.org/r91738>, when loading a document which uses custom fonts, WebKit often makes the didFinishLoad callback before the custom fonts have finished loading. Prior to that change, any font needed to render the document would have finished loading by the time didFinishLoad was called. Patch forthcoming.
Comment 1 mitz 2011-12-02 13:32:52 PST
Comment 2 mitz 2011-12-02 13:56:49 PST
Created attachment 117684 [details]
Ensure that font loads that are waiting to begin prevent didFinishLoad from being called
Comment 3 Darin Adler 2011-12-02 14:18:14 PST
Comment on attachment 117684 [details]
Ensure that font loads that are waiting to begin prevent didFinishLoad from being called

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

> Source/WebCore/css/CSSFontSelector.cpp:583
> +    if (!m_fontsToBeginLoading.isEmpty()) {

Do we really need this optimization? It seems to me that the code inside this if would do nothing relatively quickly.

> Source/WebCore/css/CSSFontSelector.cpp:607
> +    // Increment the request count now, in order to prevent didFinishLoad from being dispatched
> +    // after this font has been requested but before it began loading. Balanced by
> +    // decrementRequestCount() in beginLoadTimerFired() and in clearDocument().
> +    m_document->cachedResourceLoader()->incrementRequestCount(font);

Another way to do this is to create a type that does the increment/decrement and holds a CachedResourceHandle<CachedFont> inside it, then use that type in the vector. A little more foolproof than having the explicit code in three places, but not sure it’s better. It would completely eliminate the loop in CSSFontSelector::clearDocument.
Comment 4 mitz 2011-12-02 14:50:50 PST
Fixed in <http://trac.webkit.org/r101858>.
Comment 5 Nikolas Zimmermann 2011-12-20 01:38:05 PST
Hm, I think this is causing regressions.
On a local SL build of ToT, svg/W3C-SVG-1.1-SE/coords-dom-03-f.svg occasionally hangs (among dozens of other tests using SVG Fonts). If you open this file in Safari, the activity button will never stop spinning, despite the fact that "Activities" shows that the SVG Font has been loaded successfully.

I have not yet built with this patch rolled out, but I suspect its causing these problems.
Comment 6 Nikolas Zimmermann 2011-12-20 01:41:41 PST
Note that this doesn't reproduce everytime in Safari as well. For me in about 30% of all loads of that page, it doesn't stop showing the spinning wheel in the tab bar/adress bar.
Comment 7 Nikolas Zimmermann 2011-12-20 02:56:33 PST
Some more traces:

I ran gdb DumpRenderTree LayoutTests/svg/W3C-SVG-1.1-SE/coords-dom-03-f.svg, and set a breakpoint on FrameLoader::checkCompleted(). Its called three times, each time returning false, as "m_frame->document()->cachedResourceLoader()->requestCount()" is > 0. (Here its 8).

This is the backtrace of the last, the third call to checkCompleted:

(gdb) bt
#0  WebCore::FrameLoader::checkCompleted (this=0x1088286d8) at /Users/nikolaszimmermann/Coding/WebKit/Source/WebCore/loader/FrameLoader.cpp:710
#1  0x000000010193e06b in WebCore::FrameLoader::loadDone (this=0x1088286d8) at /Users/nikolaszimmermann/Coding/WebKit/Source/WebCore/loader/FrameLoader.cpp:687
#2  0x0000000101492bea in WebCore::CachedResourceLoader::loadDone (this=0x107c82af0) at /Users/nikolaszimmermann/Coding/WebKit/Source/WebCore/loader/cache/CachedResourceLoader.cpp:658
#3  0x0000000102339fa1 in WebCore::SubresourceLoader::releaseResources (this=0x108891e00) at /Users/nikolaszimmermann/Coding/WebKit/Source/WebCore/loader/SubresourceLoader.cpp:302
#4  0x000000010225f231 in WebCore::ResourceLoader::didFinishLoading (this=0x108891e00, finishTime=0) at /Users/nikolaszimmermann/Coding/WebKit/Source/WebCore/loader/ResourceLoader.cpp:313
#5  0x000000010233a552 in WebCore::SubresourceLoader::didFinishLoading (this=0x108891e00, finishTime=0) at /Users/nikolaszimmermann/Coding/WebKit/Source/WebCore/loader/SubresourceLoader.cpp:261
#6  0x000000010225e612 in WebCore::ResourceLoader::didFinishLoading (this=0x108891e00, finishTime=0) at /Users/nikolaszimmermann/Coding/WebKit/Source/WebCore/loader/ResourceLoader.cpp:451
#7  0x00000001022593e6 in -[WebCoreResourceHandleAsDelegate connectionDidFinishLoading:] (self=0x107ca7e30, _cmd=0x7fff89a92d20, connection=0x107ca79b0) at /Users/nikolaszimmermann/Coding/WebKit/Source/WebCore/platform/network/mac/ResourceHandleMac.mm:886
#8  0x00007fff8364b86c in _NSURLConnectionDidFinishLoading ()
#9  0x00007fff86fa70ea in URLConnectionClient::_clientDidFinishLoading ()
#10 0x00007fff8700d22c in URLConnectionClient::ClientConnectionEventQueue::processAllEventsAndConsumePayload ()
#11 0x00007fff8700d498 in URLConnectionClient::ClientConnectionEventQueue::processAllEventsAndConsumePayload ()
#12 0x00007fff86f936d7 in URLConnectionClient::processEvents ()
#13 0x00007fff86f934b2 in MultiplexerSource::perform ()
#14 0x00007fff84b6227d in __CFRunLoopDoSources0 ()
#15 0x00007fff84b605c9 in __CFRunLoopRun ()
#16 0x00007fff84b5fd8f in CFRunLoopRunSpecific ()
#17 0x00007fff83605b74 in -[NSRunLoop(NSRunLoop) runMode:beforeDate:] ()
#18 0x0000000100013582 in runTest (testPathOrURL=@0x7fff5fbff6d0) at /Users/nikolaszimmermann/Coding/WebKit/Tools/DumpRenderTree/mac/DumpRenderTree.mm:1273
#19 0x0000000100013f2d in dumpRenderTree (argc=2, argv=0x7fff5fbff750) at /Users/nikolaszimmermann/Coding/WebKit/Tools/DumpRenderTree/mac/DumpRenderTree.mm:797
#20 0x00000001000140d0 in main (argc=2, argv=0x7fff5fbff750) at /Users/nikolaszimmermann/Coding/WebKit/Tools/DumpRenderTree/mac/DumpRenderTree.mm:834

Soon after this void CSSFontSelector::beginLoadTimerFired(Timer<WebCore::CSSFontSelector>*) gets called, which correctly decrements the request count from 8 to 0. (Side-note: It's a bit unfortunate that we call beginLoadIfNeeded eight times, where we just early exit the next 7 times after the first invocation, but that's not important for this bug).

After this point DRT just hangs, and no one ever calls FrameLoader::checkCompleted() again, which would now return true.

Does that ring a bell?
Comment 8 Yong Li 2012-02-01 12:50:31 PST
Is there a test case to reproduce the problem?