919836 - Firefox hangs while opening very long page from bugzilla.mozilla.org

Status: RESOLVED FIXED

(Core :: General, defect)

Description

[Guilherme Lima]

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:27.0) Gecko/20100101 Firefox/27.0 (Beta/Release)
Build ID: 20130923030204

Steps to reproduce:

Open https://bugzilla.mozilla.org/show_bug.cgi?id=705294 (example of very long page)


Actual results:

Firefox hangs while loading the page. For me, on about:telemetry it shows under Browser Hangs (clicking on 'Fetch function names for hang stacks')

Hang Report #1 (17 seconds)
nsPrincipal::QueryInterface(nsID const &,void * *) (in xul.pdb)
XPCConvert::NativeData2JS(JS::Value *,void const *,nsXPTType const &,nsID const *,tag_nsresult *) (in xul.pdb)
nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS *,unsigned short,XPTMethodDescriptor const *,nsXPTCMiniVariant *) (in xul.pdb)
nsXPCWrappedJS::CallMethod(unsigned short,XPTMethodDescriptor const *,nsXPTCMiniVariant *) (in xul.pdb)
PrepareAndDispatch (in xul.pdb)
SharedStub (in xul.pdb)
nsContentPolicy::CheckPolicy(tag_nsresult ( nsIContentPolicy::*)(unsigned int,nsIURI *,nsIURI *,nsISupports *,nsACString_internal const &,nsISupports *,nsIPrincipal *,short *),unsigned int,nsIURI *,nsIURI *,nsISupports *,nsACString_internal const &,nsISupports *,nsIPrincipal *,short *) (in xul.pdb)
nsContentPolicy::ShouldLoad(unsigned int,nsIURI *,nsIURI *,nsISupports *,nsACString_internal const &,nsISupports *,nsIPrincipal *,short *) (in xul.pdb)
NS_CheckContentLoadPolicy(unsigned int,nsIURI *,nsIPrincipal *,nsISupports *,nsACString_internal const &,nsISupports *,short *,nsIContentPolicy *,nsIScriptSecurityManager *) (in xul.pdb)
nsContentUtils::CanLoadImage(nsIURI *,nsISupports *,nsIDocument *,nsIPrincipal *,short *) (in xul.pdb)
nsImageLoadingContent::LoadImage(nsIURI *,bool,bool,nsIDocument *,unsigned int) (in xul.pdb)
nsImageLoadingContent::LoadImage(nsAString_internal const &,bool,bool) (in xul.pdb)
mozilla::dom::HTMLImageElement::MaybeLoadImage() (in xul.pdb)
nsRunnableMethodImpl<void ( nsWyciwygChannel::*)(void),void,1>::Run() (in xul.pdb)
nsContentUtils::RemoveScriptBlocker() (in xul.pdb)
nsHTMLDocument::EndUpdate(unsigned int) (in xul.pdb)
mozAutoDocUpdate::~mozAutoDocUpdate() (in xul.pdb)
mozilla::dom::ElementBinding::set_innerHTML (in xul.pdb)
mozilla::dom::ElementBinding::genericSetter (in xul.pdb)
js::jit::DoCallNativeSetter (in mozjs.pdb)
-0x1
-0x1
-0x1
EnterBaseline (in mozjs.pdb)
js::jit::EnterBaselineAtBranch(JSContext *,js::StackFrame *,unsigned char *) (in mozjs.pdb)
Interpret (in mozjs.pdb)
js::RunScript(JSContext *,js::RunState &) (in mozjs.pdb)
js::ExecuteKernel(JSContext *,JS::Handle<JSScript *>,JSObject &,JS::Value const &,js::ExecuteType,js::AbstractFramePtr,JS::Value *) (in mozjs.pdb)
js::Execute(JSContext *,JS::Handle<JSScript *>,JSObject &,JS::Value *) (in mozjs.pdb)
JS::Evaluate(JSContext *,JS::Handle<JSObject *>,JS::CompileOptions,wchar_t const *,unsigned int,JS::Value *) (in mozjs.pdb)
nsJSUtils::EvaluateString(JSContext *,nsAString_internal const &,JS::Handle<JSObject *>,JS::CompileOptions &,nsJSUtils::EvaluateOptions &,JS::Value *,void * *) (in xul.pdb)
nsJSContext::EvaluateString(nsAString_internal const &,JS::Handle<JSObject *>,JS::CompileOptions &,bool,JS::Value *,void * *) (in xul.pdb)
nsScriptLoader::EvaluateScript(nsScriptLoadRequest *,nsString const &,void * *) (in xul.pdb)
nsScriptLoader::ProcessRequest(nsScriptLoadRequest *,void * *) (in xul.pdb)
nsScriptLoader::ProcessScriptElement(nsIScriptElement *) (in xul.pdb)
nsScriptElement::MaybeProcessScript() (in xul.pdb)
nsHtml5TreeOpExecutor::RunScript(nsIContent *) (in xul.pdb)
nsHtml5TreeOpExecutor::RunFlushLoop() (in xul.pdb)
nsHtml5ExecutorReflusher::Run() (in xul.pdb)
nsThread::ProcessNextEvent(bool,bool *) (in xul.pdb)
NS_ProcessNextEvent(nsIThread *,bool) (in xul.pdb)
mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate *) (in xul.pdb)
MessageLoop::RunHandler() (in xul.pdb)
MessageLoop::Run() (in xul.pdb)
nsBaseAppShell::Run() (in xul.pdb)
nsAppShell::Run() (in xul.pdb)
nsAppStartup::Run() (in xul.pdb)
XREMain::XRE_mainRun() (in xul.pdb)
XREMain::XRE_main(int,char * * const,nsXREAppData const *) (in xul.pdb)
XRE_main (in xul.pdb)
do_main (in firefox.pdb)
NS_internal_main(int,char * *) (in firefox.pdb)
wmain (in firefox.pdb)
__tmainCRTStartup (in firefox.pdb)
0x1336a (in wkernel32.pdb)
0x39f72 (in wntdll.pdb)
0x39f45 (in wntdll.pdb)


Expected results:

I'm filing this bug just for the chance that someone investigates if there's something that can be made so Firefox loads the page faster.

Comment 1

[Boris Zbarsky [:bzbarsky]]

The comment 0 link is not a particularly long page... and it sure shouldn't be hanging in content policy checks for image loads. Is that the right link?  Do you have the "show images for comments" Bugzilla preference on?  Any addons that would do content-policy checks?

Comment 2

[Guilherme Lima]

Ah, yes. Sorry, so it's not a Firefox problem. I tested with all my addons on and set "Show gravatar images when viewing bugs" to off and the page loaded a lot faster (with a very short hang/not long enough to show up on about:telemetry).
Then I set it again to on, and disabled AdBlock Plus and NoScript (don't know which do what you said, but they're the only complex addons I have). And the page took the same amount of time to load as the other combination.

Comment 3

[Boris Zbarsky [:bzbarsky]]

Both adblock and noscript implement content policies.  So for each image, they were both running some code...

Comment 4

[Wladimir Palant]

I guess that the example link in comment0 is wrong - that isn't exactly a long page. I tried opening bug 627699 instead that has 274 comments right now. There is no visible hang for me with Adblock Plus 2.3.2.3717 development build and Firefox 27.0a1 trunk nightly (2013-09-19) on Linux. According to Diagnostics for Adblock Plus extension that page produced 342 content policy requests that took 0.224 seconds to process in Adblock Plus (XPCOM overhead not counted). While I'm currently working on improving the performance, this seems reasonable, nothing like the 17 seconds reported.

Comment 5

[Guilherme Lima]

Bug 627699 didn't hang for me. Testing bug 705294 again, I can confirm:
no addons - no hang on about:telemetry and no "Slow SQL Statement"
only adblock plus - 12s hang and 1 "Slow SQL Statement"
only noscript - 9s hang and 1 "Slow SQL Statement"
both - 14s hang and 4 "Slow SQL Statement"

This "Slow SQL Statement" only happen once, on the second time I'm loading the page.
The avg time is ~900ms and the statement is:
SELECT h.url, h.title, f.url, EXISTS(SELECT 1 FROM moz_bookmarks WHERE fk = h.id) AS bookmarked, ( SELECT title FROM moz_bookmarks WHERE fk = h.id AND title NOTNULL ORDER BY lastModified DESC LIMIT 1 ) AS btitle, ( SELECT GROUP_CONCAT(t.title, :private) FROM moz_bookmarks b JOIN moz_bookmarks t ON t.id = +b.parent AND t.parent = :parent WHERE b.fk = h.id ) AS tags, h.visit_count, h.typed, h.id, :query_type, t.open_count FROM moz_places h LEFT JOIN moz_favicons f ON f.id = h.favicon_id LEFT JOIN moz_openpages_temp t ON t.url = h.url WHERE h.frecency <> 0 AND AUTOCOMPLETE_MATCH(:searchString, h.url, IFNULL(btitle, h.title), tags, h.visit_count, h.typed, bookmarked, t.open_count, :matchBehavior, :searchBehavior) ORDER BY h.frecency DESC, h.id DESC LIMIT :maxResults

Comment 6

[Liz Henry (:lizzard) (relman/hg->git project)]

cc-ing glob since we added the gravatars recently to BMO.

Comment 7

[Wladimir Palant]

(In reply to Guilherme Lima from comment #5)
> Bug 627699 didn't hang for me. Testing bug 705294 again, I can confirm:
> no addons - no hang on about:telemetry and no "Slow SQL Statement"
> only adblock plus - 12s hang and 1 "Slow SQL Statement"

Ok, I can see the reason now - you have to be logged in and display history inline, only then does it hang. According to Diagnostics for Adblock Plus that's 28285 content policy calls which indeed took 12 seconds to process in Adblock Plus.

Comment 8

[Wladimir Palant]

Note that there are only 238 images on that page so the number of content policy requests (most of them for the gravatars) seems very excessive. Without having looked into the Bugzilla code I suspect that the gravatars are being added dynamically one by one, each new one invalidating the previous ones when added (.innerHTML += "..." or some equivalent). So the number of content policy requests is actually quadratic in the number of actual images displayed.

Comment 9

[Wladimir Palant]

Now that I've looked into the Bugzilla code (https://bugzilla.mozilla.org/extensions/InlineHistory/web/inline-history.js) my suspicion in comment 8 seems correct:

>          var itemHtml =  '<div class="ih_history_item ' + containerClass + '" '
>                          + 'id="h' + i + '">'
>                          + item[3]
>                          + '<div class="ih_history_change">' + item[2] + '</div>'
>                          + '</div>';
>
>          if (ih_activity_sort_order == 'oldest_to_newest') {
>            currentDiv.innerHTML = currentDiv.innerHTML + itemHtml;
>          } else {
>            currentDiv.innerHTML = itemHtml + currentDiv.innerHTML;
>          }

This is being done for each single history item and in case of bug 705294 currentDiv is always the same element (there is only one comment so all history items are being inserted into the same place). Each time an item is being added the HTML code for the entire block (including all the previously added items) has to be reparsed. The most trivial way to avoid this issue would be replacing the code above by one that doesn't touch already existing elements:

>          var item = document.createElement("div");
>          item.className = "ih_history_item " + containerClass;
>          item.id = "h' + i;
>          item.innerHTML = item[3] + '<div class="ih_history_change">' + item[2] + '</div>';
>
>          if (ih_activity_sort_order == 'oldest_to_newest') {
>            currentDiv.appendChild(item);
>          } else {
>            currentDiv.insertChild(item, currentDiv.firstChild);
>          }

Personally I would recommend avoiding innerHTML altogether but that would require a more significant refactoring of that code.

Comment 10

[:glob ✱]

(In reply to Wladimir Palant from comment #9)
> Now that I've looked into the Bugzilla code
> (https://bugzilla.mozilla.org/extensions/InlineHistory/web/inline-history.
> js) my suspicion in comment 8 seems correct:

thanks, this is very useful! filed as bug 920525.

however inline history *is not* responsible for adding the gravatar images, nor as the gravatar images added via innerHTML, so according to comment 2 that may not be the root cause of this issue.

Comment 11

[Wladimir Palant]

(In reply to Byron Jones ‹:glob› from comment #10)
> however inline history *is not* responsible for adding the gravatar images,

Probably not directly. However, item[3] in the code I quoted in comment 9 contains a <span class="bz_comment_user"> block among other things which *does* contain a gravatar image.

Comment 12

[:glob ✱]

bug 920525 has landed on production.

Comment 13

[Wladimir Palant]

Yes, only minimal delay when loading bug 705294 now.

Comment 14

[Loic]

Yes, I was able to reproduce the browser hang during loading bug 705294, now it's very smooth, even better than previously in safe mode.

Comment 15

[Guilherme Lima]

Awesome! I only have the option to set RESOLVED WORKSFORME, but FIXED is more correct, right?

Comment 16

[Giorgio Maone [:ma1]]

Since this has been deemed fixed on the content side, I'll just add for the records that the inferior overhead of NoScript's content policy calls is due to images being checked for anti-CSRF purposes only.