1554793 - about:newtab leaking in the Privileged Content process

Status: NEW

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

Description

[Florian Quèze [:florian]]

See this profile: https://perfht.ml/2EBqy5L

Comment 1

[Jon Coppeard (:jonco)]

The cycle collector is in the XPCOM component.

Comment 2

[Nathan Froyd [:froydnj]]

This seems more like a problem with whatever the privileged content process is running (why is it producing so much garbage?) rather than the cycle collector itself.

Comment 3

[Florian Quèze [:florian]]

(In reply to Nathan Froyd [:froydnj] from comment #2)

This seems more like a problem with whatever the privileged content process is running (why is it producing so much garbage?) rather than the cycle collector itself.

Nothing is running there, that process is idle, except for the cycle collector that runs over and over again.

Comment 4

[Nathan Froyd [:froydnj]]

(In reply to Florian Quèze [:florian] from comment #3)

(In reply to Nathan Froyd [:froydnj] from comment #2)

This seems more like a problem with whatever the privileged content process is running (why is it producing so much garbage?) rather than the cycle collector itself.

Nothing is running there, that process is idle, except for the cycle collector that runs over and over again.

This is demonstrably not true, as the profile shows: promises, some performance metrics, etc. I am reasonably sure that the cycle collector won't run--and especially won't run for that long--if there isn't something to do, that is, somebody is creating garbage.

It's possible the cycle collector is just doing useless work on the same object graph, over and over...but that seems very unlikely. The more likely scenario is that something is creating a tangly object graph over and over, causing the cycle collector to do work over and over.

In any event, there's nothing actionable here; STR or some cycle collector logs would be a good start.

Comment 5

[Andrew McCreight [:mccr8]]

If you set javascript.options.mem.log to true in about:config, then the browser console will print out some information about what the cycle collector is doing. It'll look like this:

CC(T+127144.2)[default-78675] max pause: 11ms, total time: 11ms, slices: 1, suspected: 536, visited: 7264 RCed and 21305 GCed, collected: 262 RCed and 14 GCed (47|0|0 waiting for GC)

That'll tell us if there's a lot of garbage, or if the cycle collector is spending a lot of time looking at things that aren't garbage (by looking at the visited and collected numbers). A cycle collector log can give us more detailed information about what exactly the CC is looking at.

You can use about:memory or whatever to get the pid of the privileged process and filter on that. FWIW, the CC doesn't seem to be running much in the privileged content process for me.

Comment 6

[Andrew McCreight [:mccr8]]

(filter on the PID in the browser console, I mean.)

For the CC log, you'll want the one where the file name contains the PID of the privileged content process.

Comment 7

[Florian Quèze [:florian]]

I have not yet been able to reproduce the excessive CPU use on that process tonight. Here is what I got in the console for that content process: https://dpaste.de/6ieo
Some lines there look like long cc pauses happened anyway.

https://dpaste.de/jNXs is what about:memory looks like for that process.

Comment 8

[Andrew McCreight [:mccr8]]

There's a ton of JS objects in the graph, that aren't being collected. In a regular content process, that's a sign of a leaking window. It is also possible that our CC optimizations are failing to work for some reason.

CC(T+1321692.8)[content-31986] max pause: 171ms, total time: 1210ms, slices: 26, suspected: 3923, visited: 68375 RCed and 1268424 GCed, collected: 16481 RCed and 1536 GCed (1536|0|0 waiting for GC)
ForgetSkippable 6 times before CC, min: 1 ms, max: 12 ms, avg: 4 ms, total: 29 ms, max sync: 0 ms, removed: 8403
CC(T+1321695.8)[content-31986] max pause: 39ms, total time: 333ms, slices: 20, suspected: 2511, visited: 54482 RCed and 1266888 GCed, collected: 1 RCed and 22 GCed (1558|0|0 waiting for GC)
ForgetSkippable 2 times before CC, min: 2 ms, max: 2 ms, avg: 2 ms, total: 4 ms, max sync: 0 ms, removed: 362

Comment 9

[Andrew McCreight [:mccr8]]

The about:memory report contains this entry:
460.09 MB (32.63%) -- ghost/window(about:newtab)

This means that the about:newtab page was closed a while ago, but it is still alive. That would cause this sort of CC behavior.

Comment 10

[Andrew McCreight [:mccr8]]

(In reply to Florian Quèze [:florian] from comment #7)

I have not yet been able to reproduce the excessive CPU use on that process tonight.

The cycle collector is a lot better than it used to be at dealing with leaking pages, so your best bet will be looking for ghost windows in the content process.