1356605 - SessionCookies.jsm's initialization takes a long time on the ui thread

Status: RESOLVED FIXED

(Firefox :: Session Restore, enhancement, P1)

Description

[Florian Quèze [:florian]]

See this profile on a slow netbook where initializing SessionCookies._ensureInitialized takes 400ms during startup: https://perfht.ml/2pBfuf4

Bug 1353586 is also relevant here, as we shouldn't be attempting to save the current session before startup is fully finished.

Comment 1

[Will Wang [:WillWang]]

Hi :flo, thanks for your report and profile!

It would be great to improve the performance of session restore on slow devices,
I'm seeking rooms for improving the startup procedure without trading the reliability.

Could you please feedback following questions if possible?
1. Can this be easily reproduced/profiled on a mainstream device (which is not that slow)? (We might not see a duration like 400ms, but a relatively long time should be observed)
2. How many tabs do you have during profiling?

Thanks!

Comment 2

[Florian Quèze [:florian]]

(In reply to Will Wang [:WillWang] from comment #1)

> Could you please feedback following questions if possible?
> 1. Can this be easily reproduced/profiled on a mainstream device (which is
> not that slow)? (We might not see a duration like 400ms, but a relatively
> long time should be observed)

I don't have access to a 'mainstream device' yet. When looking at other performance measurements, I observed that the netbook used for the profile I shared here was about 25 times slower than my current very powerful latest generation macbook.

So that's a yes, I think it can be reproduced on any devices.

> 2. How many tabs do you have during profiling?

Probably one, maybe two.

Note that the time spent here is completely unrelated to how many tabs there are, it depends only on how many cookies are saved in the user's profile. So this bug will never be reproduced on a fresh profile.

The code synchronously iterates over all cookies at http://searchfox.org/mozilla-central/rev/7aa21f3b531ddee90a353215bd86e97d6974e25b/browser/components/sessionstore/SessionCookies.jsm#175

Comment 3

[Will Wang [:WillWang]]

Thanks for your feedback, Florian!

Besides postponing the session saving, to tackle this issue I also have several proposals (some of which might be suboptimal for now):

1. 1st proposal: I found that during the first time of collecting session cookie after each Firefox startup:
    1. An iterator for *ALL* cookies is returned from underlying cookie service [1]
    2. then, *EACH* of cookies is iterated for checking whether it's a session cookie or not
    3. finally, *ONLY* session cookies are used (collected).
    The problem here is, the proportion of session cookie is quite low; Taking my daily profile for example: only 5/3060 are session cookies. This might be an exciting chance to improve, which means most of the time we spent in _reloadCookies() (393ms) could be avoided.

2. 2nd proposal: break down the while loop inside the function _reloadCookies() into smaller functions, and also pull out the iterator-getting action[1] as a stand-alone function, to avoid jank the UI thread too long.

3. 3rd proposal: My understanding of our restore-collect algorithm for the session cookie is, during startup, Firefox restores session cookies by fetching them from session restore _file_ and add them to the cookie _service_, then soon afterwards, the session saving procedure fetches them from cookie _service_ and add them to an internal cookie _store_. It seems that there are some actions can be reduced (while still keeping the data consistent).

4. Minor improvement: reduce the redundant QueryInterface calling [2]

For the postponing the session saving after fully restored, this is a reasonable way, and we also have to carefully ensure that there is no data needed to be collected during restoring or queue the new incoming data in some way. Same here, we need to keep the data consistent. Besides, the postponed session saving still might jank the UI thread at an inconvenient time, like bug 1353586 did.

If I understand correctly, I think we could adopt one of above proposals to tackle this bug, then adopt more once needed.
And I consider that the 1st proposal could be our first step for now.

FYR, this bug might be (very slightly) eased in some scenario if bug 530594 is resolved.


[1]
http://searchfox.org/mozilla-central/rev/baf47b352e873d4516d7656186d6d7c7447d3873/browser/components/sessionstore/SessionCookies.jsm#175

[2]
http://searchfox.org/mozilla-central/rev/068e6f292503df13515a52321fc3844e237bf6a9/browser/components/sessionstore/SessionCookies.jsm#121,133,147,159

Comment 4

[Florian Quèze [:florian]]

Lots of good ideas here :). It seems implementing either your first or third proposal will fix the bug. And your second proposal is a good way to avoid the jank if we can't reduce the CPU time further; we should keep it for if the problem still exists after implementing one of the other 2 proposals.

Comment 5

[Will Wang [:WillWang]]

Hi valentin, may I ask a question regarding my 1st proposal in comment 3?

We found that session restore spends a lot of time on iterating/checking _all_ coookies from cookie service, but actually we just need session cookies. Unfortunately, the whole iteration blocks the UI thread for almost 400ms in some scenarios.

AFAIK, currently there is no way for session restore to iterate only session cookies.
Therefore, what do you think that would it be possible to overload(add a parameter)the nsCookieService::GetEnumerator [1] to restrict the returned cookie list, or add another function in cookie service for session restore(and any possible consumer) to get session cookies only?

Thanks!


[1] http://searchfox.org/mozilla-central/rev/876c7dd30586f9c6f9c99ef7444f2d73c7acfe7c/netwerk/cookie/nsCookieService.cpp#2352

Comment 6

[Valentin Gosu [:valentin] (he/him)]

(In reply to Will Wang [:WillWang] from comment #5)
> Hi valentin, may I ask a question regarding my 1st proposal in comment 3?
> 
> We found that session restore spends a lot of time on iterating/checking
> _all_ coookies from cookie service, but actually we just need session
> cookies. Unfortunately, the whole iteration blocks the UI thread for almost
> 400ms in some scenarios.

Do you know if it's the call to Services.cookies.enumerator that takes a long time, or the actual iteration that is taking a long time?

Comment 7

[Florian Quèze [:florian]]

(In reply to Valentin Gosu [:valentin] from comment #6)
> (In reply to Will Wang [:WillWang] from comment #5)
> > Hi valentin, may I ask a question regarding my 1st proposal in comment 3?
> > 
> > We found that session restore spends a lot of time on iterating/checking
> > _all_ coookies from cookie service, but actually we just need session
> > cookies. Unfortunately, the whole iteration blocks the UI thread for almost
> > 400ms in some scenarios.
> 
> Do you know if it's the call to Services.cookies.enumerator that takes a
> long time, or the actual iteration that is taking a long time?

In the profile from comment 0, the nsCookieService::GetEnumerator(nsISimpleEnumerator**) takes 95ms: https://perf-html.io/public/ec14efa1e59fc517955a363fcdfd832a850d554b/calltree/?callTreeFilters=prefixjs-yw0zxqzxrzxszybzyczC1zC2zC3~prefixjs-zC3zC4~prefix-zC4zUhzFa&range=1.0447_1.6078&thread=0

And then iterating through it with the _addCookie method takes 185ms: https://perf-html.io/public/ec14efa1e59fc517955a363fcdfd832a850d554b/calltree/?callTreeFilters=prefix-01Qi2yw02zxq2zxr2zxs2zyb2zyc2zC12zC22zC32zC4zL6&range=1.0447_1.6078&thread=0

So the answer to your question is... both.

Comment 8

[Will Wang [:WillWang]]

Thanks for Florian's reply!
Here is my reply after stripping out same info in above comment:

Note, the profile in comment 0 shows that the direct cost(not including the condition checking of while loop, etc).

And I'm writing a WIP patch for your reference.

Comment 9

[Valentin Gosu [:valentin] (he/him)]

(In reply to Florian Quèze [:florian] [:flo] from comment #7)
> So the answer to your question is... both.

Thanks for the info. Amy is the de facto owner of the cookie code, but she's a bit busy right now, so I'll try to help out with this one.

(In reply to Will Wang [:WillWang] from comment #5)
> 
> AFAIK, currently there is no way for session restore to iterate only session
> cookies.
> [...] or add another function in cookie service for session
> restore(and any possible consumer) to get session cookies only?

I think the best solution would be to add a GetSessionEnumerator method, so we don't need to change the old callsites.
The slowness of the call may be due to the fact that we're doing IO (reading from the DB), but if we only return the session cookies it will definitely be an improvement.

Comment 10

[Will Wang [:WillWang]]

(In reply to Valentin Gosu [:valentin] from comment #9)
> I think the best solution would be to add a GetSessionEnumerator method, so
> we don't need to change the old callsites.
Thanks for your feedback, I will go this way! :)

> The slowness of the call may be due to the fact that we're doing IO (reading
> from the DB), but if we only return the session cookies it will definitely
> be an improvement.
If InitDBStates() is the one you are mentioning:
1. In the profile of this bug: 9ms (should not be the bottleneck)
2. In the profile of bug 1360202(comment 0): 90ms (main part in the function _reloadCookies)

Comment 11

[Will Wang [:WillWang]]

Attachment: necko.patch

Thanks for your suggestion, Valentin!

Here is a proof-of-concept WIP patch of necko part(no comment, no polish, ...etc), profiling shows that it can reduce the time of function _reloadCookies():

Before: 37 ms
After: 2 ms

(Profiling was run on my powerful MacBook, so the gap on a slow machine like netbook should be much *bigger* .)

If your feedback is positive, I'll do the following including more optimizations(both in front-end part and necko part).

Thanks! :)

Comment 12

[Valentin Gosu [:valentin] (he/him)]

Comment on attachment 8864499 [details] [diff] [review]
necko.patch

Review of attachment 8864499 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good. Thanks!

Comment 13

[Will Wang [:WillWang]]

Attachment: Bug 1356605 - part1: Add an enumerator for getting session cookies only.

Hi Valentin, could you please review this patch? Thanks!

Comment 14

[Will Wang [:WillWang]]

Attachment: Bug 1356605 - part2: Load session cookies only during initialization at startup.

Hi Mikedeboer, could you please review this patch?

This patch simply changes the iterator we use, which can significantly reduce the cookies we need to iterate/check during initialization at startup.

Thanks a lot!

Comment 15

[Will Wang [:WillWang]]

Attachment: Bug 1356605 - part2: Load session cookies only during initialization at startup.

Opps, the patch in above comment 14 was actually part1; Here is the part2 we need. Thanks!

Comment 16

[Mike de Boer [:mikedeboer]]

Comment on attachment 8866185 [details] [diff] [review]
Bug 1356605 - part2: Load session cookies only during initialization at startup.

Review of attachment 8866185 [details] [diff] [review]:
-----------------------------------------------------------------

Very nice work, Will! One general comment: please update the patch comment to reflect what the code in this patch really changes: use the new `sessionEnumerator` to iterate only the cookies we need.

Idea: you could add a new observer notification in nsICookieService, called 'session-cookie-changed', that only fires when a session cookie was added/ removed/ updated. This'll make sure that the observer is called way less often in SessionCookies.jsm. What do you think?

Comment 17

[Will Wang [:WillWang]]

(In reply to Mike de Boer [:mikedeboer] from comment #16)
> Very nice work, Will! One general comment: please update the patch comment
> to reflect what the code in this patch really changes: use the new
> `sessionEnumerator` to iterate only the cookies we need.
Got it, thanks for your review!


> Idea: you could add a new observer notification in nsICookieService, called
> 'session-cookie-changed', that only fires when a session cookie was added/
> removed/ updated. This'll make sure that the observer is called way less
> often in SessionCookies.jsm. What do you think?
It's a good idea, I also had the same thought during writing this patch,
and since then I was considering the overall performance about which one is more efficient:
(1) check ALL cookies within JS session restore
(2) check ALL cookies within C++ cookie service (still, need checking all cookies...)

Thanks for your remind, now it becomes more clear to me that (2) is a better choice since it can:
A. save amount of observer calling (most obvious win)
B. save amount of cookie access from JS to C++ (as a result of above A)
C. check cookie faster as its native language nature(Theoretically, if I understand correctly)

I also did a preliminary evaluation to have a glance at the activity of notification within cookie service,
then I observed that it acts pretty frequently. 

In sum, I think it's a great change to improve!

I'd like to file another follow-up bug(which is a bit different with this bug) and attach patch once I finish it(ongoing), is that ok? If so, I will push patches of this bug into try for further testing :)

Comment 18

[Mike de Boer [:mikedeboer]]

(In reply to Will Wang [:WillWang] from comment #17)
> Thanks for your remind, now it becomes more clear to me that (2) is a better
> choice since it can:
> A. save amount of observer calling (most obvious win)
> B. save amount of cookie access from JS to C++ (as a result of above A)
> C. check cookie faster as its native language nature(Theoretically, if I
> understand correctly)
> 
> I also did a preliminary evaluation to have a glance at the activity of
> notification within cookie service,
> then I observed that it acts pretty frequently. 
> 
> In sum, I think it's a great change to improve!
> 
> I'd like to file another follow-up bug(which is a bit different with this
> bug) and attach patch once I finish it(ongoing), is that ok? If so, I will
> push patches of this bug into try for further testing :)

Good idea - it's never a good a idea to pile work work on top of an existing bug - bugs are cheap!

Comment 19

[Will Wang [:WillWang]]

Follow-up bug filed as bug 1366213.

Comment 20

[Will Wang [:WillWang]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=e177ef708968

Comment 21

[Will Wang [:WillWang]]

Attachment: Bug 1356605 - part 1: Add an enumerator for getting session cookies only. r=valentin

Update patches with the revised commit message, which is the one sent to try in comment 20.

Comment 22

[Will Wang [:WillWang]]

Attachment: Bug 1356605 - Part 2: Use the new `sessionEnumerator` to iterate only the cookies we need. r=mikedeboer

Update patches with the revised commit message, which is the one sent to try in comment 20.

Comment 23

[Will Wang [:WillWang]]

Please help to push patches of comment 21 and comment 22, thanks!

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/96ac0b3d2b57
Part 1: Add an enumerator for getting session cookies only. r=valentin
https://hg.mozilla.org/integration/mozilla-inbound/rev/2a7293861315
Part 2: Use the new `sessionEnumerator` to iterate only the cookies we need. r=mikedeboer

Comment 25

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/96ac0b3d2b57
https://hg.mozilla.org/mozilla-central/rev/2a7293861315

Comment 26

[mirh]

Just for the records, I don't think bug 1358283 was very related to this, since there were no cookies at all involved. 
I mean, it was just a fresh session with a copy-pasted sessionstore.js

Comment 27

[Will Wang [:WillWang]]

Hi Florian,

Out of curiosity, would it be possible for you to use the latest nightly on the netbook(and Firefox profile) you mentioned in comment 0 to profile again?
It might show a typical example of startup improvement on a slow machine :)

Comment 28

[Florian Quèze [:florian]]

(In reply to Will Wang [:WillWang] from comment #27)

> Out of curiosity, would it be possible for you to use the latest nightly on
> the netbook(and Firefox profile) you mentioned in comment 0 to profile again?
> It might show a typical example of startup improvement on a slow machine :)

Here is a warm startup profile of the current nightly on the same slow netbook (hence giving a very detailed profile), where it takes 9.9s to reach first paint: https://perfht.ml/2rXVdp1

We don't reach the SessionCookies.jsm code at all in there. Maybe this has been delayed so that the SessionSaver code runs during an idle callback rather than during startup?

Comment 29

[Will Wang [:WillWang]]

(In reply to Florian Quèze [:florian] [:flo] from comment #28)
> Here is a warm startup profile of the current nightly on the same slow
> netbook (hence giving a very detailed profile), where it takes 9.9s to reach
> first paint: https://perfht.ml/2rXVdp1
Thanks for your help, Florian!
The slow netbook and the very detailed profile are valuable for our works :D


> We don't reach the SessionCookies.jsm code at all in there. Maybe this has
> been delayed so that the SessionSaver code runs during an idle callback
> rather than during startup?
I believe there is no any idle callback in session restore yet;

Two possible reasons for not reached are:
(1) Session restore is not enabled in about:preferences (should not be this, I saw some SR functions in profile)
(2) No any cookie operation is triggered yet: we can open some web page like cnn.com[1](or make it be restored from startup), then the operation should be reflected on the profile.

I believe you are busy with many works right now... would it be possible to profile again when you are available?
Many thanks!


[1]
We will see a notification:
"By continuing to browse our site you agree to our use of cookies, revised Privacy Policy and Terms of Service. More information about cookies"

Comment 30

[Florian Quèze [:florian]]

(In reply to Will Wang [:WillWang] from comment #29)

> (2) No any cookie operation is triggered yet: we can open some web page like
> cnn.com[1](or make it be restored from startup), then the operation should
> be reflected on the profile.

Ah, that's possible. I had about:blank set as the home page to avoid slowing down the already very slow startup.

Comment 31

[Will Wang [:WillWang]]

Hi Florian,

If possible, could you help to share the profile when you are profiling the slow netbook again?
Many thanks!

Comment 32

[Shian-Yow Wu [:swu]]

ni? Florian on comment 31. Thanks!

Comment 33

[Florian Quèze [:florian]]

(In reply to Will Wang [:WillWang] from comment #31)

> If possible, could you help to share the profile when you are profiling the
> slow netbook again?

This is a startup profile on the slow netbook, using the June 20 nightly:
https://perf-html.io/public/6801d5dff8f8e5e1505b145df68b2bf49ba191cb/calltree/?implementation=js&range=0.0000_42.2471&search=SessionCookies&thread=0

Comment 34

[Shian-Yow Wu [:swu]]

New result looks good, thank you Florian!

Comment 35

[Will Wang [:WillWang]]

Thank you Florian!

Now we know the time of getting all session cookies is reduced as: 397 ms -> 13 ms,
based on that I am considering the possibility of changing design of collecting session cookies. (ref bug 1366213 comment 8)

It's a valuable profile, thanks a lot!