754201 - Latency when switching tabs with Firebug due to GC

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect)

Description

[Jan Honza Odvarko [:Honza] (always need-info? me)]

Several Firebug users started complaining about a latency when switching among Firefox tabs. Happens when Firebug is installed.

The original bug is reported here:
http://code.google.com/p/fbug/issues/detail?id=5456

I don't know what Component could be the culprit, my wild guess is JSD (it's active when the Console panel is active).

---

When I switch from or to a tab in which the Firebug Console is opened, Firefox freezes for several seconds.

STR:
I tested in a fresh new profile, with no other extension.

Open several tabs, enable Firebug's console in some of them and start working. After a while, leaving a tab with Firebug opened, or going to a tab where Firebug is opened, takes 2 or 3 seconds, during which the CPU is high.

It becomes more and more noticeable when you have lots of tabs opened. In my working profile, with around 100 tabs opened, I sometime wait 15 or 20 seconds before displaying the tab. If I switch from or to tabs not using Firebug, everything is just fine.

Seems related to the latest nightlies.
I think it appeared around May 5, and it was definitely absent in April.
Seems to be related to Linux

I attached to the process with strace during the freeze. It loops on 2 system calls : 

getrusage(RUSAGE_SELF, {ru_utime={2539, 454706}, ru_stime={219, 85692}, ...}) = 0

gettimeofday({1336668996, 197822}, NULL) = 0

Honza

Comment 1

[Boris Zbarsky [:bzbarsky]]

I can definitely reproduce this.

A profile shows that 90+% of the time is spent firing DOM events.  In particular, each event firing has to do nsXPConnect::Push(JSContext*), which does nsXPConnect::CheckForDebugMode, which does JS_SetDebugModeForCompartment, which calls setDebugModeFromC, which calls updateForDebugMode, which calls Collect.  And then we do a full GC, looks like.  On every single DOM event.  We fire a _lot_ of DOM events on tab switch.

Comment 2

[Boris Zbarsky [:bzbarsky]]

Looks like the GC call was added in bug 725733. on May 5, matching comment 0.

Comment 3

[Boris Zbarsky [:bzbarsky]]

Er, no.  I lied.  There is not a full GC per event.

What we actually have, as far as I can tell from stepping through in a debugger, is that switching from a tab with console enabled to one that does not have console enabled makes one single call to nsXPConnect::CheckForDebugMode.  With two tabs opened (one with console, one without, the URIs are http://web.mit.edu and http://www.mozilla.com), it looks like we have about 150 compartments in the vector returned by js::GetRuntimeCompartments.  Some of these return null from JS_GetCompartmentPrincipals.  But for the rest, we end up in JSCompartment::updateForDebugMode calling:

  GC(rt, GC_NORMAL, gcreason::DEBUG_MODE_GC);

If my debugger is not lying to me, a tab switch in the above setup (two tabs, one with open console one without) hits that line 145 times.

Turning on the JS mem log, those GC calls look about like this:

  GC(T+41.5) Total Time: 3.8ms, Compartments Collected: 1, Total Compartments: 153,
    MMU (20ms): 80%, MMU (50ms): 92%, Reason: DEBUG_MODE_GC, 
    Nonincremental Reason: requested, Allocated: 24MB, +Chunks: 0, -Chunks: 0
  Totals: Mark: 2.2ms, Mark Roots: 2.0ms, Mark Other: 0.1ms, Sweep: 1.6ms,
    Finalize End Callback: 0.8ms

So 3.8ms * 145 == 551ms == noticeable pause.

With more tabs, obviously, there would be more compartments and hence longer pauses....

Would scheduling GC on all the compartments then doing a single GC be faster?

Comment 4

[Boris Zbarsky [:bzbarsky]]

I think it would: the vast majority of the time is taken by XPConnect marking, which is global, so is being done 150 times or so on the same exact data.  15% of the time is js::SweepAtomState, which is also runtime-wide afaik and hence being done on the same data.

Comment 5

[Boris Zbarsky [:bzbarsky]]

One more note: since most of the cost is XPConnect marking, I would expect the per-GC time to scale linearly with number of tabs.  So adding more tabs not only adds more compartments but also makes each GC slower, right now, giving the whole thing O(N^2) behavior in number of tabs.

Comment 6

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Now that we're no longer throwing code away on every GC (see bug 750834), I'm not sure a GC is even what we want to be doing here. To be honest, I never fully understood the problem that bug 725733 was addressing, except that a GC somehow fixes it. Is it that we weren't throwing away enough compiled code? Or was it the TI data that needed to be discarded? Maybe we could come up with a more restricted solution here than a GC.

Also, I don't understand why we need to do any of this when we're just switching tabs. If debug mode is a per-compartment thing, it seems fine to keep it enabled while we're in other tabs.

Comment 7

[Till Schneidereit [:till]]

Attachment: Changes nsXPConnect::CheckForDebugMode to GC all compartments at once

The attached patch introduces JS_SetDebugModeForCompartments and invokes that from nsXPConnect::CheckForDebugMode to trigger one GC for all compartments at once.

With this patch applied, switching from a debugger-enabled tab to a debugger-disabled one correctly triggers one multi-compartment GC, taking about 40ms in my case.

I think that a better encapsulation would actually be to move that functionality into JS_SetRuntimeDebugMode but I'm not entirely sure the required change in order of operations in nsXPConnect::CheckForDebugMode would be ok. The upside would be that no new function in jsdbgapi.h would be required.

Another point is that a second GC is triggered immediately after the DEBUG_MODE_GC, with the reason being DESTROY_CONTEXT. I don't know if there's a way around that, but it would certainly be desirable as that GC takes almost as long as the first one.

Comment 8

[Luke Wagner [:luke]]

Comment on attachment 623211 [details] [diff] [review]
Changes nsXPConnect::CheckForDebugMode to GC all compartments at once

Sorry, I don't really know what this was for in the first place, so I can't comment on its removal :)

Comment 9

[Boris Zbarsky [:bzbarsky]]

> If debug mode is a per-compartment thing,

It might be in the JS engine internally, but it's not as far as XPConnect knows, and certainly isn't as far as jsd is concerned: turning on jsd turns on debug mode for all compartments.

Comment 11

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Comment on attachment 623211 [details] [diff] [review]
Changes nsXPConnect::CheckForDebugMode to GC all compartments at once

I think this is the right way to go. Here are some preliminary comments. Can you post a new patch and ask :jorendorff for review? He works on debugger stuff.

It looks like updateForDebugMode is also called from JSCompartment::{add,remove}Debuggee. So those function need to call GC now.

Also, I would like to keep the PrepareCompartmentForGC close to calls to GC. So could you shift this call so it happens right before the GC calls.

Finally, since I'm pretty sure that the removeDebuggee caller may happen during GC, you probably need to keep the !gcRunning test when calling GC there.

Comment 12

[Till Schneidereit [:till]]

Attachment: Changes nsXPConnect::CheckForDebugMode to GC all compartments at once, v2

Thanks for the feedback, billm!

All requested changes are implemented except for:

> Also, I would like to keep the PrepareCompartmentForGC close to calls to GC. 
> So could you shift this call so it happens right before the GC calls.

The calls are pretty much as close to the GC as they can be already. The only way to move them any closer still would be to remove them from updateForDebugMode and iterate over all compartments a second time if no call to updateForDebugMode failed. If that's a better solution, I'm of course happy to implement it.

@Jason: please also look at comment 7, especially the question whether all of this should be moved into SetRuntimeDebugMode, as that seems like the right encapsulation to me.

Comment 13

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

Actually, I guess you're way is good. I'd forgotten that setDebugModeFromC doesn't always call updateForDebugMode, and in that case we don't want to schedule the compartment for GC.

Comment 14

[Till Schneidereit [:till]]

(In reply to Bill McCloskey (:billm) from comment #13)
> Actually, I guess you're way is good. I'd forgotten that setDebugModeFromC
> doesn't always call updateForDebugMode, and in that case we don't want to
> schedule the compartment for GC.

All the better, then :) Thanks for the confirmation!

Comment 15

[FX Poster]

Any news on applying this to Nightly? Cause it's almost impossible now to use Nightly for web development :(

Comment 16

[Jason Orendorff [:jorendorff]]

Comment on attachment 623362 [details] [diff] [review]
Changes nsXPConnect::CheckForDebugMode to GC all compartments at once, v2

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

r=me with one renaming thing. Thanks.

::: js/src/jscompartment.cpp
@@ +659,1 @@
>          PrepareCompartmentForGC(this);

Please update the comment too. In particular it should say that unless GC is already running, the caller is responsible for calling GC after updateForDebugMode.

I dunno. The fact that the caller must know about this responsibility is just slightly worrying (after all, if you missed it in a previous version of this patch, then someone coming along later certainly could miss it just as easily) but I think we're OK. You could use the C++ type system to make that mistake impossible (move this method into a separate class whose destructor performs GC if needed) but maybe that is more work than you want to do, and if so, fine. Certainly it's extra code.

::: js/src/jsdbgapi.h
@@ +124,5 @@
> + * Turn on/off debugging mode for all compartments. This returns false if any code
> + * from any of the runtime's compartments is running or on the stack.
> + */
> +JS_FRIEND_API(JSBool)
> +JS_SetDebugModeForCompartments(JSContext *cx, JSBool debug);

Please add the word "all" to the name: JS_SetDebugModeForAllCompartments.

Comment 17

[Jason Orendorff [:jorendorff]]

Try server points out that this patch triggers the JS_ASSERT(any) assertion in AutoGCSession::AutoGCSession when running jit-tests with -d.

I think the answer is to do what comment 16 suggests -- I'll implement it and post for review early tomorrow.

This means the bug will be in one more Nightly. It'll be fixed in Wednesday's, with high probability.

Comment 18

[Jason Orendorff [:jorendorff]]

Attachment: v3 - Add AutoDebugModeGC helper class

Comment 19

[Till Schneidereit [:till]]

Thanks for the fix, Jason! The AutoDebugModeGC is a much better way to implement the GC invocation indeed.

Comment 20

[Steve Fink [:sfink] [:s:]]

Comment on attachment 624144 [details] [diff] [review]
v3 - Add AutoDebugModeGC helper class

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

This is really the wrong fix, since the right fix would be to eliminate the GC entirely. But until someone can get around to doing that, it's definitely better to land this. I filed bug 755574 for killing the GC.

I notice that with this patch, Debugger is still GCing one compartment at a time, and post-CPG it seems like it may be enabling debug mode for large numbers of compartments too (especially when debugging chrome.) I'll let a Debugger person file a bug for that if it is wanted, though.

Comment 21

[Jason Orendorff [:jorendorff]]

Landed directly onto mozilla-central:
https://hg.mozilla.org/mozilla-central/rev/c00a9c1940c5