Closed Bug 932418 Opened 6 years ago Closed 6 years ago

setting a cookie string creates and throws away prompter


(Core :: DOM: Core & HTML, defect, P3)




blocking-b2g koi+
Tracking Status
firefox26 --- wontfix
firefox27 --- wontfix
firefox28 --- fixed
b2g18 28+ ---
b2g-v1.2 --- fixed


(Reporter: jrburke, Assigned: bkelly)



(Keywords: perf, Whiteboard: [c=handeye p=4 s= u=1.2])


(1 file, 4 obsolete files)

:mchang recently did a perf capture and noted a good chunk of time sent in htmlCacheSave (see the Gecko (EMail:2224) graph):

Diving in, the big hit seems to be related to:

BrowserElementPromptFactory.prototype.getPrompt() @ BrowserElementPromptService.jsm:485

Which I believe is related to the errors generated because of bug 902121.

Possible fixes:

1) Fix bug 902121. As it has been reported in other bugs (normally as a misleading cause), it seems generally a good idea to fix it for cases where it should not be generated, like for app:// URLs, as that may help other apps too.

2) Use localStorage for the email cookie use. localStorage use was forbidden in 1.1 and below, but there have been perf improvements in it that may make it feasible now to use in 1.2. I will do a test branch to try it out.
Whiteboard: [c= p=4 s= u=]
I created a branch that uses localStorage instead of cookies:

and created a zip for this branch here:

You could use the app manager to install that zip on the phone if using a B2G nightly build from this week. This would allow running the old and new app side by side. Steps to do this are here:

I used the "plog" logging call defined in html_cache_restore.js to log completion times using  performance.timing offsets. Averaged over 8 runs:

For the cookie case:

innerHTML of cookie data finished (relative to start of page): 240ms
Delta from starting save of cookie data to finish: 297ms

For localStorage:

innerHTML of localStorage data finished (relative to start of page): 285ms
Delta from starting save of localStorage data to finish: 1.3ms

So, localStorage takes about 45ms longer on startup to get to the innerHTML finish, but is super fast on saves. The issue found in this bug is related to the save portion, and the 297ms completion time for the cookie case highlights this.

So while I would prefer to just use localStorage, it takes a bit longer to use on app startup. I expect if the errors generated by bug 902121 were fixed, the cookie save number should go drastically down from the 285ms number.

So asking for :mchang and the perf team for help in either pushing to get a fix in for bug 902121 as that should fix the observed issue. Or if for some reason that is not an option and this issue must be fixed, getting the appropriate clearances for the use of localStorage for this case. 

It may be worth :mchang doing another perf run with the above zip too, to see if there are secondary effects, and if the save case is indeed better, and the perf issue initially observed goes away.
Flags: needinfo?(mchang)
Providing a profile with the email-localstorage. Thanks for the zip file, makes it a lot easier:

Looks like the cacheDom method went from 1250ms -> 100ms overall according to the new profile. Great job! One interesting thing about this patch is that we reflow a lot more.
Flags: needinfo?(mchang)
Talking more in IRC, since this is technically a regression in perf from 1.1, and the regression we believe is caused by the cookie error logging based on :mchang's first perf capture, we will ask for bug 902121 to be a koi+ bug, and depending on that outcome, will affect what we do for this ticket. Ideally the logging issue in 902121 is fixed and will address this issue, so placing a dependency on it.
Depends on: 902121
On further discussion in IRC, koi+ is only for "major perf" issues, and since this has not shown up on partner radar, bug 902121 has existed for a while without other complaints, and 1.3 is already in dev, will push it to 1.3 with :mchang tracking it already in the perf backlog for 1.3.
Assignee: nobody → mchang
Whiteboard: [c= p=4 s= u=] → [c=handeye p=4 s= u=]
Target Milestone: --- → 1.2 C6(Dec6)
Tagging this bug to put it in the productivity backlog
Target Milestone: 1.2 C6(Dec6) → ---
Priority: -- → P3
Blocks: 942242
No longer blocks: 936535
I applied my fix in bug 902121 which avoids the cookie related exception.  Unfortunately it looks like htmlCacheSave() still takes 350+ ms to run which introduces noticeable jank:

It looks to me like most of it is just the pain of passing giant cookie strings to the parent process to be stored synchronously.

(Also note significant sync reflows in MessageCardList._requestSnippets and MessageCardList.onMessage.)

I'm going to rename this bug to reflect the user visible symptom.  I'm also dropping the dep on bug 902121 since it seems the exception is unrelated.
Assignee: mchang → bkelly
No longer depends on: 902121
Summary: [Email] cookie exceptions may be affecting FPS → [Email] htmlCacheSave is slow
In the profile you provide in the big html cache saving thing, IPDL:PCookieService::RecvSetCookieString only is present on the stack for 13 ticks; I see 6 peaks, likely due to us splitting the HTML over multiple cookies.  In between them it mainly seems to be epoll_wait.

It looks like there is still a lot of time spent in the prompting logic or time spent seeing if we need to prompt.  Things are a little confused because the backtraces aren't perfect and there seems to be two major sub-trees related to the actual cookie setting because of those random "Unknown".

In the larger one, I still see a large number of ticks (76 out of 273 in the given time-span) in BrowserElemeentPromptFactory.prototype.getPrompt() @ BrowserElementPromptService.jsm.  Compare with ~55 ticks in mozilla::dom::HTMLDocumentBinding::set_cookie, and 31 of those ticks in IPDL::PCookieService::AsyncSendSetCookieString.  Some of the more unidentifiable frames seem like they could potentially be associated with chrome activities related to prompting, but it's hard to know for sure.

In the other fork with nsHTMLDocuument::SetCookie there's another 12 ticks that seem related to serialization, but 21 ticks involved with nsWindowWatcher::GetNewPrompter.

Is there an easy way to take the prompting stuff out of the equation and see how fast we go?
(In reply to Andrew Sutherland (:asuth) from comment #7)
> In the profile you provide in the big html cache saving thing,
> IPDL:PCookieService::RecvSetCookieString only is present on the stack for 13
> ticks; I see 6 peaks, likely due to us splitting the HTML over multiple
> cookies.  In between them it mainly seems to be epoll_wait.

Note: I was talking about the b2g parent process in this paragraph.
Hmm, it looks like nsHTMLDocument::SetCookie() always gets a prompter:

But we throw it away in the child process by ignoring the aPrompt argument to CookieServiceChild::SetCookieString():

Maybe we could have nsHTMLDocument::SetCookie() ask the cookie service if it needs a prompter or not.

Boris, what do you think?  (Or is there someone better to ask?)
Flags: needinfo?(bzbarsky)
I think we should just kill the prompt thing.  It's unused (and even documented as unused in the API).  A simple fix is to just pass null in nsHTMLDocument, but even better would be to change nsICookieService to not have the attractive nuisance.
Flags: needinfo?(bzbarsky)
Looking at <>, we can't really break that interface unfortunately.
Filed bug 943414 to address this in the cookie service code.
I hacked out the prompt code in hsHTMLDocument.cpp to see how it would effect the b2g email app.  With this change I can no longer catch htmlCacheSave() in a profile.  I took three profiles trying to get it.

Here is one of those profiles:

Adding in console.log instrumentation shows that htmlCacheSave() is typically only taking 20ms to 40ms with the prompt code removed.  This probably causes some very minor jank still, but its less important than the 150ms sync reflows that are occurring.
I wrote a separate bug to track the sync reflow issues.  See bug 943498.
Renaming this bug to reflect the underlying issue.
Component: Gaia::E-Mail → DOM: Core & HTML
Product: Firefox OS → Core
Summary: [Email] htmlCacheSave is slow → setting a cookie string creates and throws away prompter
Attached patch cookie-prompt.patch (obsolete) — Splinter Review
Candidate patch removing the code that creates the prompt since nsCookieService() ignores it.

Try build:
Attached patch cookie-prompt.patch (obsolete) — Splinter Review
Updated patch.  This only tweaked a comment, but here's a new try since the last one got mugged by the network outage yesterday:
Attachment #8338697 - Attachment is obsolete: true
Blocks: 943414
Attached patch cookie-prompt.patch (obsolete) — Splinter Review
One last update removing headers that are no longer needed.

The updated patch builds locally and previous try builds were green.  Going to go ahead and ask for review.
Attachment #8339264 - Attachment is obsolete: true
Attachment #8339340 - Flags: review?(bzbarsky)
Based on Ben Kelly's comments we can land this patch for koi?
blocking-b2g: --- → koi?
Comment on attachment 8339340 [details] [diff] [review]

I believe that nsPluginHost::GetPrompt is dead code after this patch.  Just go ahead and remove that as well?

r=me with that, and thank you!
Attachment #8339340 - Flags: review?(bzbarsky) → review+
Attached patch cookie-prompt.patch (obsolete) — Splinter Review
Update patch to remove nsPluginHost::GetPrompt().  Carry r+ forward.

Looks good locally, but here's another minimal try for sanity checking:

I'll checkin-needed this once its green.
Attachment #8339340 - Attachment is obsolete: true
Attachment #8341079 - Flags: review+
Here's one last version to update the commit message to include r=bz.
Attachment #8341079 - Attachment is obsolete: true
Attachment #8341081 - Flags: review+

Is the patch giving us a boost in perf numbers?

Downside of not taking it in 1.2?
Flags: needinfo?(bkelly)
(In reply to Preeti Raghunath(:Preeti) from comment #24)
> Is the patch giving us a boost in perf numbers?
> Downside of not taking it in 1.2?

The improvement is in email scroll performance.  Periodically email saves its state to a cookie.  Currently this takes almost half a second which causes scrolling to jank.  This patch allows the cookie operation to complete in about 1/10 the time and therefore helps improve email scrolling smoothness.

Note, there is still other work that needs to be done to further improve email scrolling in addition to this.  See bug 943498.
Flags: needinfo?(bkelly)
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla28
koi+ for email perf scrolling.
blocking-b2g: koi? → koi+
Whiteboard: [c=handeye p=4 s= u=] → [c=handeye p=4 s= u=1.2]
You need to log in before you can comment on or make changes to this bug.