1795312 - Firefox GUI lags for a few seconds serializing principals in session restore code

Status: RESOLVED FIXED

(Firefox :: Session Restore, defect)

Description

[Germano Massullo (Thetra)]

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:105.0) Gecko/20100101 Firefox/105.0

Steps to reproduce:

Firefox GUI sometimes lags for a few seconds. It happens on both webpages and Firefox GUI.
CPU Ryzen 5 3600, 128 GB RAM, Radeon RX480
Fedora 36 KDE, xorg session, Plasma 5.25.5, kernel 5.19.14-200.fc36.x86_64, videodriver amdgpu, Firefox 105.0.2

I attached the output file of https://profiler.firefox.com/
At the moment I don't have the opportunity to test a new Firefox profile

Comment 1

[Germano Massullo (Thetra)]

Attachment: Firefox_profile.tar.xz

Comment 2

[BugBot [:suhaib / :marco/ :calixte]]

The Bugbug bot thinks this bug should belong to the 'Core::Widget: Gtk' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.

Comment 3

[Germano Massullo (Thetra)]

If you are trying to import the file into profiler.firefox.com and you get an error, is because I had to break it into multiple lines to be able to inspect it and remove sensitive data.
To achieve that I had to use
sed 's/},/}\n/g' input.json > output.json
I filled https://bugzilla.mozilla.org/show_bug.cgi?id=1795303 to complain about Firefox creating such huge single line JSON file

Comment 4

[Germano Massullo (Thetra)]

I tried to create a new Firefox profile, but I was not able to reproduce the problem

Comment 5

[Germano Massullo (Thetra)]

I would like to debug this bug as soon as possible because I don't know how long I will be using the machine were the problem is reproducible

Comment 6

[Martin Stránský [:stransky] (ni? me)]

Can you try Wayland session and/or upstream binaries?
https://fedoraproject.org/wiki/How_to_debug_Firefox_problems#Testing_Mozilla_binaries
May be as well caused by Fedora packages.
Thanks.

Comment 7

[Germano Massullo (Thetra)]

Also upstream binary causes the same problem.

Comment 8

[Emilio Cobos Álvarez [:emilio]]

Here's a shareable version of the profile above: https://share.firefox.dev/3DzkFUq

Seems like the jank comes from SessionRestore, serializing a principal to JSON in nsIScriptSecurityManager.principalToJSON, and same in serializeCSP. My guess is that that code is either not intended to take too long, or if it is it shouldn't be running in the main thread...

It might be useful to have a problematic session store file attached to the bug. Reporter, could you attach your sessionstore.jsonlz4 file from your profile if you're comfortable with it? You can see your profile directory in about:profiles, there's a sessionstore.jsonlz4 file that is the relevant one here I believe. That's full of personal info, but when creating the attachment you can tick Make attachment and comment private checkbox to make sure as little people as possible have access to it.

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

The product::component has been changed since the backlog priority was decided, so we're resetting it.
For more information, please visit auto_nag documentation.

Comment 10

[Germano Massullo (Thetra)]

Reporter, could you attach your sessionstore.jsonlz4 file from your profile if you're comfortable with it? [...]

Hello, I prefer to not disclose such file.
Is there anything else I can do to help you debugging?

Comment 11

[Germano Massullo (Thetra)]

is there any patch that I could test?

Comment 12

[Bas Schouten (:bas.schouten)]

Are there any other options here?

Comment 13

[Emilio Cobos Álvarez [:emilio]]

I don't know, I'm not familiar with the session restore code. Farre / Barret, do you know?

Comment 14

[Andreas Farre [:farre]]

Yeah, without a test case we're just guessing here. Did this use to happen in a content process before SHIP, and now that we do it in the parent process we jank the UI?

Does that sound plausible Peter?

I guess doing it in the background is the way to go in that case.

Comment 15

[Beth Rennie [:beth] (she/her)]

I looked at the code and nothing jumped out at me. I'd have to guess the object being serialized is large enough that it takes long enough to jank the thread.

Comment 16

[Wayne Mery (:wsmwk)]

I do currently have some lagging in a session of 1,700 tabs, mainly when typing in edit fields (like bug comments) and in the address bar. (up until a couple weeks ago I didn't have lagging). So perhaps my sessionstore has the same issue. I am willing to share privately in email. Just let me know who to send it to. Perhaps Germano would be willing to do the same?

Comment 17

[Emilio Cobos Álvarez [:emilio]]

I'd prefer for Barret / Farre to poke because they're more familiar with this code, but if they're not available feel free to mail it to either my personal or my moco email (emilio [at] mozilla.com). If you could take a profile of it to confirm it's the same issue that'd also be super-helpful.

Comment 18

[Germano Massullo (Thetra)]

(In reply to Wayne Mery (:wsmwk) from comment #16)

[...]I am willing to share privately in email. Just let me know who to send it to. Perhaps Germano would be willing to do the same?

I am sorry, I will not share my Firefox tabs list

Comment 19

[Peter Van der Beken [:peterv]]

(In reply to Andreas Farre [:farre] from comment #14)

Does that sound plausible Peter?

It's plausible, sure. The BasePrincipal::ToJSON doesn't look super-efficient too.

Comment 20

[Peter Van der Beken [:peterv]]

(In reply to Peter Van der Beken [:peterv] from comment #19)

The BasePrincipal::ToJSON doesn't look super-efficient too.

Bug 1508939 is where we switched the serialization code to the current mechanism (afaict from writing directly to a stream to creating Json::Value objects containing string maps, which then get serialized to a string recursively).

Comment 21

[Germano Massullo (Thetra)]

Another thing I noticed but I haven't mentioned before. You experience a short lag every time you save a file on your disk

Comment 22

[Frank Doty [:fdoty]]

The Performance Impact Calculator has determined this bug's performance impact to be low. If you'd like to request re-triage, you can reset the Performance Impact flag to "?" or needinfo the triage sheriff.

Impact on browser: Causes noticeable jank
+5
Configuration: Rare
×0.3

Comment 23

[Germano Massullo (Thetra)]

(In reply to Frank Doty [:fdoty] from comment #22)

The Performance Impact Calculator has determined this bug's performance impact to be low. If you'd like to request re-triage, you can reset the Performance Impact flag to "?" or needinfo the triage sheriff.

Impact on browser: Causes noticeable jank
+5
Configuration: Rare
×0.3

Well I don't agree at all. This bug can causes lags up to ~15 seconds

Comment 24

[BugBot [:suhaib / :marco/ :calixte]]

The severity field is not set for this bug.
:dao, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 25

[Peter Van der Beken [:peterv]]

IMO the main thing to look at here is the JSON serialization library (jsoncpp). We're spending a ton of time in there, recursing into objects and then repeatedly creating strings, which get passed out to outer calls which then reserialize those string into bigger strings etc. Andreas and I have been looking to see if we can optimize this somehow.

Comment 26

[Andreas Farre [:farre]]

If this has got to do with slowness of serialization of principals, I'm leaning towards it being mostly expanded principals. As far as I can tell, they mostly (only?) show up in the context of extension. Would you be ok sharing your list of extensions? It could help us get a way to reproduce this issue.

Comment 27

[Andreas Farre [:farre]]

Dao, I've been looking into changing how we serialize expanded principals, and it seems promising in that it will speed up both serialization and deserialization. The trouble is that it will break the format in session store, and I'm not sure how we usually handle this. I can make newer versions of Firefox still be able to handle the old format, but I can't make older versions handle the new format. Is this OK?

This will probably not fix this issue, but it will make things better. To fix this issue I think we need to break up serialization of Session History into smaller chunks, but before that I was thinking of adding telemetry. Do you know if we already have good probes? I'll look around a bit, but if there aren't any I plan to add a handful of probes for that as well.

Comment 28

[Andreas Farre [:farre]]

Attachment: Bug 1795312 - Don't Base64 encode principals when serializing. r=peterv!

Also ditch Window.btoa!

Comment 29

[Andreas Farre [:farre]]

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

Comment 30

[Peter Van der Beken [:peterv]]

Attachment: Bug 1795312 - Cache the Json::StreamWriterBuilder for serializing principals. r?farre!

Comment 31

[Peter Van der Beken [:peterv]]

Attachment: Bug 1795312 - Avoid a Json::Value copy. r?farre!

Depends on D166810

Comment 32

[Peter Van der Beken [:peterv]]

Attachment: Bug 1795312 - Optimize serializing enums as JSON string keys for principals. r?farre!

Depends on D166953

Comment 33

[Peter Van der Beken [:peterv]]

I've been looking at ContentPrincipal JSON serialization a bit, and managed to make it a bit faster (reduced to about 1/3 of the original time). Here are the times (in ms) for the different patches for serializing a million ContentPrincipal objects:

Trunk	4670
Cache the Json::StreamWriterBuilder	2260
Avoid a Json::Value copy	1990
Optimize serializing enums	1570

There might be more we could do, but it would probably require patching the JsonCpp code.

We should also probably land telemetry first, so that we can verify the effect of our patches in the real world.

Comment 34

[Andreas Farre [:farre]]

Created Bug 1810704, let's land that and wait a release until trying to land the patches for this bug.

Comment 35

[Andreas Farre [:farre]]

The expanded principal serialization patch is running on try.

Comment 36

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a732c5bcc392
Don't Base64 encode principals when serializing. r=peterv
https://hg.mozilla.org/integration/autoland/rev/38f9e767cc32
Cache the Json::StreamWriterBuilder for serializing principals. r=farre
https://hg.mozilla.org/integration/autoland/rev/bc1c5b1c2d85
Avoid a Json::Value copy. r=farre
https://hg.mozilla.org/integration/autoland/rev/2594a213283c
Optimize serializing enums as JSON string keys for principals. r=farre

Comment 37

[Andreas Farre [:farre]]

Attachment: Bug 1795312 - Remove newly introduced intermittent test. r=peterv!

Comment 38

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c4f9e74d6164
Remove newly introduced intermittent test. r=peterv

Comment 39

[Cristina Horotan [:chorotan]]

Backed out 5 changesets (bug 1795312) for causing build bustage at BasePrincipal.h

Backout: https://hg.mozilla.org/integration/autoland/rev/4f67e1a353a51251ee82eb82e7b7a762fb12eaa1

Failure push: https://treeherder.mozilla.org/jobs?repo=autoland&revision=2594a213283cb5f14e460b73c4bbaaba01f110c8

Failure log: https://treeherder.mozilla.org/logviewer?job_id=405030240&repo=autoland&lineNumber=10061

Comment 40

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/903aa182c02d
Don't Base64 encode principals when serializing. r=peterv
https://hg.mozilla.org/integration/autoland/rev/ff5c9e4043b0
Cache the Json::StreamWriterBuilder for serializing principals. r=farre
https://hg.mozilla.org/integration/autoland/rev/cfada6ca624f
Avoid a Json::Value copy. r=farre
https://hg.mozilla.org/integration/autoland/rev/c126577344db
Optimize serializing enums as JSON string keys for principals. r=farre

Comment 41

[Cristina Horotan [:chorotan]]

https://hg.mozilla.org/mozilla-central/rev/903aa182c02d
https://hg.mozilla.org/mozilla-central/rev/ff5c9e4043b0
https://hg.mozilla.org/mozilla-central/rev/cfada6ca624f
https://hg.mozilla.org/mozilla-central/rev/c126577344db