Bug 42772

Summary: WebTiming does not take page cache into account
Product: WebKit Reporter: Simon Fraser (smfr) <simon.fraser>
Component: WebKit Misc.Assignee: Mihai Parparita <mihaip>
Status: RESOLVED FIXED    
Severity: Normal CC: abarth, dbates, eric, mihaip, tonyg, webkit.review.bot
Priority: P2    
Version: 528+ (Nightly build)   
Hardware: Mac   
OS: OS X 10.5   
Bug Depends on: 42775    
Bug Blocks: 30685, 42434, 42435    
Attachments:
Description Flags
testcast
none
Patch
none
Patch none

Description Simon Fraser (smfr) 2010-07-21 12:11:51 PDT
After running run-webkit-tests and getting a Safari browser showing a page with test results, with some failures, if I click on a test result diff, and then click Back, I get:

ASSERTION FAILED: !timing->unloadEventEnd
(/Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:456 void WebCore::FrameLoader::stopLoading(WebCore::UnloadEventPolicy, WebCore::DatabasePolicy))

Stack is:

#0  0x00000001035d210e in WebCore::FrameLoader::stopLoading (this=0x11c816050, unloadEventPolicy=WebCore::UnloadEventPolicyUnloadAndPageHide, databasePolicy=WebCore::DatabasePolicyStop) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:456
#1  0x00000001035d24a6 in WebCore::FrameLoader::closeURL (this=0x11c816050) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:527
#2  0x00000001035d3d9d in WebCore::FrameLoader::transitionToCommitted (this=0x11c816050, cachedPage=@0x7fff5fbfd9d0) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:1983
#3  0x00000001035d4605 in WebCore::FrameLoader::commitProvisionalLoad (this=0x11c816050) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:1907
#4  0x00000001035d4b48 in WebCore::FrameLoader::loadProvisionalItemFromCachedPage (this=0x11c816050) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:3150
#5  0x00000001035d4edc in WebCore::FrameLoader::continueLoadAfterNavigationPolicy (this=0x11c816050, formState=@0x7fff5fbfdca0, shouldContinue=true) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:3023
#6  0x00000001035d4f9e in WebCore::FrameLoader::callContinueLoadAfterNavigationPolicy (argument=0x11c816050, request=@0x11c8d9220, formState=@0x7fff5fbfddf0, shouldContinue=true) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:2929
#7  0x0000000103b05921 in WebCore::PolicyChecker::checkNavigationPolicy (this=0x11c816060, request=@0x11c8d9220, loader=0x11c8d8e00, formState=@0x7fff5fbfdee0, function=0x1035d4f5a <WebCore::FrameLoader::callContinueLoadAfterNavigationPolicy(void*, WebCore::ResourceRequest const&, WTF::PassRefPtr<WebCore::FormState>, bool)>, argument=0x11c816050) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/PolicyChecker.cpp:68
#8  0x00000001035d53b6 in WebCore::FrameLoader::loadWithDocumentLoader (this=0x11c816050, loader=0x11c8d8e00, type=WebCore::FrameLoadTypeBack, prpFormState=@0x7fff5fbfe210) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:1542
#9  0x00000001035d6251 in WebCore::FrameLoader::navigateToDifferentDocument (this=0x11c816050, item=0x11ff4c7f0, loadType=WebCore::FrameLoadTypeBack) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:3208
#10 0x00000001035d6874 in WebCore::FrameLoader::loadItem (this=0x11c816050, item=0x11ff4c7f0, loadType=WebCore::FrameLoadTypeBack) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/FrameLoader.cpp:3311
#11 0x000000010364d8b8 in WebCore::HistoryController::recursiveGoToItem (this=0x11c8161c8, item=0x11ff4c7f0, fromItem=0x124922b30, type=WebCore::FrameLoadTypeBack) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/HistoryController.cpp:580
#12 0x000000010364da10 in WebCore::HistoryController::goToItem (this=0x11c8161c8, targetItem=0x11ff4c7f0, type=WebCore::FrameLoadTypeBack) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/loader/HistoryController.cpp:224
#13 0x0000000103ade01e in WebCore::Page::goToItem (this=0x11add3530, item=0x11ff4c7f0, type=WebCore::FrameLoadTypeBack) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/page/Page.cpp:332
#14 0x0000000103ade1e5 in WebCore::Page::goBack (this=0x11add3530) at /Volumes/InternalData/Development/webkit/OpenSource/WebCore/page/Page.cpp:261
#
Comment 1 Simon Fraser (smfr) 2010-07-21 12:14:21 PDT
This prevents me from browser layout test results with a debug  build.
Comment 2 Adam Barth 2010-07-21 12:28:35 PDT
Yeah, this bug is super annoying to me too.  Tonyg, are you looking at it?
Comment 3 Tony Gentilcore 2010-07-21 12:33:34 PDT
(In reply to comment #2)
> Yeah, this bug is super annoying to me too.  Tonyg, are you looking at it?

Yes, I'll be landing a patch to temporarily comment out the ASSERT momentarily.
Comment 4 Tony Gentilcore 2010-07-21 12:42:02 PDT
I've disabled the ASSERT for now. The consequence of that ASSERT being reached is that the unloadEventEnd exposed to Web Timing is incorrect.

I'm leaving this open to track the actual fix.
Comment 5 Mihai Parparita 2010-08-04 21:33:13 PDT
Created attachment 63543 [details]
testcast
Comment 6 Mihai Parparita 2010-08-04 21:38:25 PDT
I've attached a reduced test case. For triggering the assert when going page 1-> page 2 -> back the requirements are for page 1 to not have an unload handler but for page 2 to have one. This makes page 1 end up in the page cache, while page 2 doesn't.

Tony, do you mind if I work on fixing this? It seems like another good (i.e. simple) initial patch for me.
Comment 7 Tony Gentilcore 2010-08-04 22:33:58 PDT
(In reply to comment #6)
> I've attached a reduced test case. For triggering the assert when going page 1-> page 2 -> back the requirements are for page 1 to not have an unload handler but for page 2 to have one. This makes page 1 end up in the page cache, while page 2 doesn't.
> 
> Tony, do you mind if I work on fixing this? It seems like another good (i.e. simple) initial patch for me.

By all means. Nice reduction :-)
Comment 8 Mihai Parparita 2010-08-06 16:08:11 PDT
After looking at this a bit more, it looks like the WebTiming code in general doesn't take the page cache into account at all. When we're restoring a page from the page cache, we bypass the normal loading flow (e.g. navigationStart is called in continueLoadAfterWillSubmitForm, but we exit before that in continueLoadAfterNavigationPolicy, and instead call loadProvisionalItemFromCachedPage). 

The fix might be as simple as resetting the timing data in loadProvisionalItemFromCachedPage (so that times recorded for the previous time the page was displayed aren't used) and also recording navigationStart there.
Comment 9 Mihai Parparita 2010-08-06 16:46:17 PDT
Created attachment 63783 [details]
Patch
Comment 10 Mihai Parparita 2010-08-06 16:47:57 PDT
Adam, can you review this (since you helped Tony and I understand what's going on in the first place)?
Comment 11 Mihai Parparita 2010-08-06 17:17:36 PDT
Created attachment 63786 [details]
Patch
Comment 12 Adam Barth 2010-08-06 18:00:49 PDT
Comment on attachment 63786 [details]
Patch

Looks great!  Thanks.
Comment 13 Eric Seidel (no email) 2010-08-07 23:19:57 PDT
Comment on attachment 63786 [details]
Patch

Clearing flags on attachment: 63786

Committed r64939: <http://trac.webkit.org/changeset/64939>
Comment 14 Eric Seidel (no email) 2010-08-07 23:20:03 PDT
All reviewed patches have been landed.  Closing bug.
Comment 15 WebKit Review Bot 2010-08-07 23:55:29 PDT
http://trac.webkit.org/changeset/64939 might have broken GTK Linux 64-bit Debug
Comment 16 Mihai Parparita 2010-08-08 09:36:40 PDT
This is the diff from the GTK builder of onunload-back-to-page-cache.html

-main frame "navigated" - has 1 onunload handler(s)
+main frame - has 1 onunload handler(s)

Seems like the GTK DRT doesn't report frame names quite the same way as the other DRTs. I'll modify the test to clear the frame name before exiting and file a bug about the GTK DRT (if there isn't one already).
Comment 17 Adam Barth 2010-08-08 10:03:00 PDT
> Seems like the GTK DRT doesn't report frame names quite the same way as the other DRTs. I'll modify the test to clear the frame name before exiting and file a bug about the GTK DRT (if there isn't one already).

Thanks.  The other option is to make the Gtk DRT report frame names correctly.
Comment 18 Mihai Parparita 2010-08-08 10:28:05 PDT
(In reply to comment #17)
> > Seems like the GTK DRT doesn't report frame names quite the same way as the other DRTs. I'll modify the test to clear the frame name before exiting and file a bug about the GTK DRT (if there isn't one already).
> 
> Thanks.  The other option is to make the Gtk DRT report frame names correctly.

I filed bug 43690 about fixing the GTK DRT, but since I don't have a Linux build environment (yet), modifying the test seems like reasonable workaround for now (bug 43692 has that).