Closed Bug 972243 Opened 6 years ago Closed 6 years ago

time for nsISessionStore.getBrowserState() doubled between 27 and 30

Categories

(Firefox :: Session Restore, defect)

28 Branch
defect
Not set

Tracking

()

VERIFIED FIXED
Firefox 30
Tracking Status
firefox27 --- unaffected
firefox28 + verified
firefox29 + verified
firefox30 + verified
b2g-v1.3 --- fixed

People

(Reporter: tnikkel, Assigned: ttaubert)

References

Details

Attachments

(4 files, 3 obsolete files)

Attached file ss.js.bz2
Using the attached sessionstore.js (it contains only google search results in many tabs) file in an otherwise fresh profile I used the about:sessionstore addon to look at the time it reports for nsISessionStore.getBrowserState(). In Firefox 27 the time never exceeds 300ms. In latest nightly (30) the time is never below 700ms. It seems like this regression is in beta (28) as well.
This probably is a dupe of bug 912717. We should confirm whether all/most of the time is spent collecting cookies/host data.
Depends on: 912717
Whiteboard: [triage]
Blocks: 912717
No longer depends on: 912717
Bug 912717 was new between 27 and 30?
It probably wasn't. Tim, what makes you think that this is bug 912717?

tn, could you check with a recent Nightly the Telemetry histograms for FX_SESSION_RESTORE_COLLECT_*?
Flags: needinfo?(ttaubert)
Flags: needinfo?(tnikkel)
Attached file sessionstorestats.txt
I can't use nightly on my main profile due to this bug, but I copied my sessionstore.js into a fresh profile, got it to do several session store updates, and then copied all the session store stuff from about:telemetry. Let me know if you need anything else.
Flags: needinfo?(tnikkel)
Thanks for the data.

So:
- cookies are bad with 322ms;
- COLLECT_SINGLE_WINDOW_DATA_MS, however, is much worse, with 894ms;
- SERIALIZE is quite bad, too, with 580ms;
Blocks: 930202
Flags: needinfo?(wmccloskey)
And for good measure here are the stats with latest nightly using my full profile, not just the sessionstore.js copied into a new profile.
(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo?") from comment #3)
> It probably wasn't. Tim, what makes you think that this is bug 912717?

Pure speculation. Looks like I was wrong, sorry.
Flags: needinfo?(ttaubert)
No longer blocks: 912717
I think this should be way faster.
Attachment #8382047 - Flags: review?(wmccloskey)
Timothy, can you give the attached patch a try, please?
Flags: needinfo?(tnikkel)
Bug 964293 was fortunately uplifted to Fx 28, so using Cu.cloneInto() would work.
That patch definitely improves the situation, but doesn't get us close to where we were before.

Current nightly: 2100ms
2013-11-04 nightly: 1800ms
2013-11-03 nightly: 900ms

my own opt mozilla-inbound build: 2300ms
my own opt mozilla-inbound build + this patch: 1400-1800ms

I'm testing using the about:sessionstore addon because it is convenient if that makes a difference.
Flags: needinfo?(tnikkel)
Thanks for testing, Timothy! I actually think that the problem we were trying to address with cloning the tab state here as described in bug 930202 comment #1 doesn't exist anymore, since we broadcast all data starting with Fx 29. We might have a different option for 29+.
Assignee: nobody → ttaubert
Status: NEW → ASSIGNED
Attachment #8382124 - Flags: review?(wmccloskey)
Timothy, what do collection times look like with both of the patches applied?
Flags: needinfo?(tnikkel)
Attachment #8382047 - Flags: review?(wmccloskey) → review+
Comment on attachment 8382124 [details] [diff] [review]
0002-Bug-972243-Remove-cloning-__SS_data-when-collecting-.patch

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

I'm a little more worried about this part. It seems like if someone calls duplicateTab during restoration, then they will directly update tabState.index. Then, later on, the same data could get used in (for example) onTabClose. Maybe we don't actually use the index field in these cases, but I don't like it when code is this hard to reason about.

What if, instead, we do a shallow clone of the data? We could just loop over the properties and copy them to a new object. I think that would answer all of my concerns, and it should be a lot faster than doing a structured clone.
(In reply to Bill McCloskey (:billm) from comment #18)
> I'm a little more worried about this part. It seems like if someone calls
> duplicateTab during restoration, then they will directly update
> tabState.index. Then, later on, the same data could get used in (for
> example) onTabClose. Maybe we don't actually use the index field in these
> cases, but I don't like it when code is this hard to reason about.

Yeah, I don't like all these shared caches everywhere in sessionstore.

> What if, instead, we do a shallow clone of the data? We could just loop over
> the properties and copy them to a new object. I think that would answer all
> of my concerns, and it should be a lot faster than doing a structured clone.

This patch does that.
Attachment #8382419 - Flags: review?(wmccloskey)
Timothy, could you check the new "0002" patch on top of "0001" as well, please?
Comment on attachment 8382419 [details] [diff] [review]
0002-Bug-972243-Create-a-shallow-copy-of-__SS_data-rather.patch

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

Thanks.

::: browser/components/sessionstore/src/Utils.jsm
@@ +43,5 @@
>             (prevChar == "." || prevChar == "/");
> +  },
> +
> +  shallowCopy: function (obj) {
> +    let retval =  {};

Looks like you have an extra space here.
Attachment #8382419 - Flags: review?(wmccloskey) → review+
Attachment #8382124 - Flags: review?(wmccloskey)
Flags: needinfo?(wmccloskey)
patch0001 + 0002-Bug-972243-Remove-cloning-__SS_data-when-collecting-.patch: oscillates between 900ms and 1300ms, with about two thirds being 900ms

patch0001 + 0002-Bug-972243-Create-a-shallow-copy-of-__SS_data-rather.patch: oscillates between 900ms and 1300ms, with about two thirds being 900ms
Flags: needinfo?(tnikkel)
Sounds like we're back on Fx 27 levels with those patches. Thanks for confirming!
Attachment #8382124 - Attachment is obsolete: true
Pretty close, except for the 1300ms ones that show up about one out of every three.
I folded the patches, they both are upliftable.

https://hg.mozilla.org/integration/fx-team/rev/f5b3819834fe
(In reply to Timothy Nikkel (:tn) from comment #24)
> Pretty close, except for the 1300ms ones that show up about one out of every
> three.

So that never happens on Fx 27?
Nope, never get one over 1000ms with my testcase on Firefox 27.
https://hg.mozilla.org/mozilla-central/rev/f5b3819834fe
Status: ASSIGNED → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 30
No longer blocks: fxdesktopbacklog
Whiteboard: [triage]
The patch that has been checked in.
Attachment #8382047 - Attachment is obsolete: true
Attachment #8382419 - Attachment is obsolete: true
Attachment #8383531 - Flags: review+
OS: Mac OS X → All
Hardware: x86 → All
Version: unspecified → 28 Branch
Comment on attachment 8383531 [details] [diff] [review]
Use Cu.cloneInto() and/or shallow copies to clone state objects

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 930202
User impact if declined: Frequent hangs for bigger sessions.
Testing completed (on m-c, etc.): On m-c.
Risk to taking this patch (and alternatives if risky): Low risk.
String or IDL/UUID changes made by this patch: None.
Attachment #8383531 - Flags: approval-mozilla-beta?
Attachment #8383531 - Flags: approval-mozilla-aurora?
Attachment #8383531 - Flags: approval-mozilla-beta?
Attachment #8383531 - Flags: approval-mozilla-beta+
Attachment #8383531 - Flags: approval-mozilla-aurora?
Attachment #8383531 - Flags: approval-mozilla-aurora+
Thanks for catching this one, Timothy.
Well, I didn't have much choice, it was making my main profile basically unusable. :) Thanks for fixing it!
(In reply to Timothy Nikkel (:tn) from comment #34)
> Well, I didn't have much choice, it was making my main profile basically
> unusable. :) Thanks for fixing it!

Timothy, can you confirm this is performant for you now with Firefox 28, 29, and 30?
(In reply to Anthony Hughes, QA Mentor (:ashughes) from comment #35)
> (In reply to Timothy Nikkel (:tn) from comment #34)
> > Well, I didn't have much choice, it was making my main profile basically
> > unusable. :) Thanks for fixing it!
> 
> Timothy, can you confirm this is performant for you now with Firefox 28, 29,
> and 30?

Sorry, forgot to needinfo you.
Flags: needinfo?(tnikkel)
Sure, I can confirm (and I've already checked on nightly), but it would be good to get at least one other person to verify this besides me. The STR are pretty easy and they are in comment 0.
(In reply to Timothy Nikkel (:tn) from comment #37)
> it would be good to get at least one other person to verify this besides me. 

Will do.
Flags: needinfo?(tnikkel)
Keywords: verifyme
I tested on Firefox 28 beta 1 and got 1051ms value for 'nsISessionStore.getBrowserState()'
Using latest versions of Firefox:
 - Ubuntu 12.04 32bit: 
latest Nightly: 485ms, 475ms, 473ms, 479ms, 487ms
latest Aurora: 456ms, 470ms, 482ms, 468ms, 472ms
Firefox 28 Beta 8: 461ms, 488ms, 494ms, 479ms, 487ms

- Mac OS X 10.9.1:
latest Nightly: 588ms, 592ms, 537ms, 540ms, 531ms
latest Aurora: 495ms, 536ms, 548ms, 501ms, 536ms
Firefox 28 Beta 8: 511ms, 721ms, 516ms, 498ms, 507ms

- Windows 7 64bit
latest Nightly: 519ms, 452ms, 450ms, 503ms, 451ms
latest Aurora: 510ms, 474ms, 473ms, 471ms, 504ms
Firefox 28 Beta 8: 475ms, 495ms, 510ms, 500ms, 546ms

The Timings for Firefox 27 RC are the same as I get on Firefox 28 beta 8, latest Nightly and latest Aurora. Calling this verified fixed based on my testing.
You need to log in before you can comment on or make changes to this bug.