906269 - peg CPU doing GC for cycle collection when opening nytimes.com article in session with many tabs

Status: RESOLVED FIXED

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

Description

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

I've been noticing for at least a few months that if I open multiple New
York Times articles in tabs, Firefox pegs the CPU at 100% and gets
really sluggish.  (I've learned to avoid doing that, though some of this
knowledge is a result of both (a) having a CPU usage graph on my screen
all the time and (b) breaking in gdb to figure out which pages were
running setTimeouts so I could close them and see if they were the
source of the load.  Neither of these are things average users do.)

I'd note that I'm doing this in a session with a pretty large number of
tabs open, with all the tabs in a single window.  (Probably a few
hundred tabs?)

I took a profile, and it looks (although I don't know how to *usefully*
invert call stacks in perf, so this involves some random sampling of the
places where we're spending time) like pretty much all the time is spent
inside the following stack:

   IncrementalCollectSlice(JSRuntime*, long, JS::gcreason::Reason, js::JSGCInvocationKind)
   GCCycle(JSRuntime*, bool, long, js::JSGCInvocationKind, JS::gcreason::Reason)
   Collect(JSRuntime*, bool, long, js::JSGCInvocationKind, JS::gcreason::Reason)
   FireForgetSkippable(unsigned int, bool)
   CCTimerFired(nsITimer*, void*)
   nsTimerImpl::Fire()
   nsTimerEvent::Run()
   nsThread::ProcessNextEvent(bool, bool*)
   NS_ProcessNextEvent(nsIThread*, bool)
   mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*)
   MessageLoop::RunInternal()
   MessageLoop::Run()
   nsBaseAppShell::Run()
   nsAppStartup::Run()
   XREMain::XRE_mainRun()
   XREMain::XRE_main(int, char**, nsXREAppData const*)
   XRE_main
   do_main(int, char**, nsIFile*)
   main

The top leaves in the profile were:

8.64% libpthread-2 [.] pthread_getspecific
6.06% libnspr4.so  [.] PR_GetThreadPrivate
4.82% libxul.so    [.] js::gc::Cell::tenuredZone() const
3.81% libxul.so    [.] js::gc::Cell::markIfUnmarked(unsigned int) const
3.65% libnspr4.so  [.] PR_GetCurrentThread
2.55% libxul.so    [.] js::ObjectImpl::zone() const
2.41% libxul.so    [.] js::GCMarker::processMarkStackTop(js::SliceBudget&)
2.28% libxul.so    [.] js::gc::Cell::arenaHeader() const
2.19% libxul.so    [.] JS::Zone::isGCMarking()
2.18% libxul.so    [.] js::InSequentialOrExclusiveParallelSection()
2.06% libxul.so    [.] js::gc::Cell::isAligned() const
1.89% libxul.so    [.] void MarkInternal<JSAtom>(JSTracer*, JSAtom**)
1.89% [kernel.kall [k] 0xffffffff8103e0aa
1.73% libxul.so    [.] _ZNK7mozilla16DeadlockDetectorINS_20BlockingResourceBase21DeadlockDetectorEntryEE9IsOrderedEPK11PLHashEntryS6_.isra.25
1.55% libxul.so    [.] js::ForkJoinSlice::Current()
1.51% libxul.so    [.] js::gc::Cell::isMarked(unsigned int) const
1.49% libxul.so    [.] js::gc::GetGCThingMarkWordAndMask(void const*, unsigned int, unsigned long**, unsigned long*)
0.96% libxul.so    [.] js::gc::FreeSpan::checkSpan() const
0.84% libxul.so    [.] mozilla::DeadlockDetector<mozilla::BlockingResourceBase::DeadlockDetectorEntry>::InTransitiveClosure(PLHashEntry const*, PLHashEntry const*) const
0.74% libxul.so    [.] js::gc::ArenaHeader::getThingSize() const
0.72% libxul.so    [.] js::gc::AssertValidColor(void const*, unsigned int)
0.68% libxul.so    [.] PREF_UnregisterCallback
0.63% libnspr4.so  [.] PR_GetCurrentThread@plt
0.60% libxul.so    [.] JSRuntime::assertValidThread() const
0.59% libxul.so    [.] js::gc::Cell::runtime() const
0.58% libxul.so    [.] JSScript::markChildren(JSTracer*)
0.56% libxul.so    [.] void MarkInternal<JSObject>(JSTracer*, JSObject**)
0.56% libxul.so    [.] PushMarkStack(js::GCMarker*, js::Shape*)
0.56% libxul.so    [.] js::gc::Cell::chunk() const
0.54% libxul.so    [.] bool js::gc::Arena::finalize<JSObject>(js::FreeOp*, js::gc::AllocKind, unsigned long)
0.54% libc-2.15.so [.] _int_malloc
0.53% libxul.so    [.] js::gc::ArenaHeader::getAllocKind() const
0.53% libxul.so    [.] js::gc::GetGCThingTraceKind(void const*)


breaking in gdb shows something similar; calls to Collect with
reason=JS::gcreason::CC_FORCED are quite common, and take around a
second to finish.

It really seems like we could do better than CCing all the time in cases
like this.


That said, the page is certainly somewhat at fault here; all nytimes.com
articles (news articles!!) seem to be rapidly creating and destroying
iframes.  Note, for example, what I see if I open up one of the few
items above in the flat profile that's not GC-related:

-   0.68%  pool  libxul.so                    [.] PREF_UnregisterCallback
   + PREF_UnregisterCallback
   - nsPrefBranch::RemoveObserver(char const*, nsIObserver*)
      - 79.37% mozilla::Preferences::RemoveObservers(nsIObserver*, char const**)
           nsEventStateManager::Shutdown()
           nsEventStateManager::~nsEventStateManager()
           nsEventStateManager::~nsEventStateManager()
           SnowWhiteKiller::~SnowWhiteKiller()
           nsCycleCollector::FreeSnowWhite(bool)
           AsyncFreeSnowWhite::Run()
           nsThread::ProcessNextEvent(bool, bool*)
           NS_ProcessNextEvent(nsIThread*, bool)
           mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*)
           MessageLoop::RunInternal()
           MessageLoop::Run()
           nsBaseAppShell::Run()
           nsAppStartup::Run()
           XREMain::XRE_mainRun()
           XREMain::XRE_main(int, char**, nsXREAppData const*)
           XRE_main
           do_main(int, char**, nsIFile*)
           main
           __libc_start_main
      - 20.63% nsDocShell::Destroy()
           nsFrameLoader::Finalize()
           nsDocument::MaybeInitializeFinalizeFrameLoaders()
           nsDocument::EndUpdate(unsigned int)
           nsHTMLDocument::EndUpdate(unsigned int)
           mozAutoDocUpdate::~mozAutoDocUpdate()
           nsINode::doRemoveChildAt(unsigned int, bool, nsIContent*, nsAttrAndChildArray&)
           mozilla::dom::FragmentOrElement::RemoveChildAt(unsigned int, bool)
           nsINode::RemoveChild(nsINode&, mozilla::ErrorResult&)
           mozilla::dom::NodeBinding::removeChild(JSContext*, JS::Handle<JSObject*>, nsINode*, JSJitMethodCallArgs const&)
         + mozilla::dom::NodeBinding::genericMethod(JSContext*, unsigned int, JS::Value*)

It still seems like we could do better on the CC side here.

Comment 1

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Also, I filed bug 906281, bug 906282, and bug 906283 on that pref observer business.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

So incremental GC has taken so much time that we have decided that postponing CC more is not an
option and we force iGC to finish and start CC cycle...

Or

We start a new iGC while were in CC cycle. That sounds more likely.

Comment 3

[Olli Pettay [:smaug][[e-mail]]]

Attachment: possible patch

David, could you test this?

I think I managed to reproduce the problem once without the patch, but then
had no luck when trying to reproduce with or without the patch.

But anyhow, I think we should take something like this. If we're about to CC soon,
don't be so eager to GC.

https://tbpl.mozilla.org/?tree=Try&rev=057887c10e5d

Comment 4

[Olli Pettay [:smaug][[e-mail]]]

(ah, on my machine the common slow-down with nyt comes from Flash)

Comment 5

[Olli Pettay [:smaug][[e-mail]]]

We could probably just poke CC and not GC after page load or top level page deletion, but
the patch has closer-to-the-old behavior since it at least force a gc.

Comment 6

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

I'll be able to test this once I untangle my tree (mid-bug 898333) and update my tree so that the patch applies, though I don't plan to update my tree until I have a solution to bug 904979 comment 34.

Comment 7

[Olli Pettay [:smaug][[e-mail]]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/776354d56c25

Please test when you have time.

Comment 8

[:Ms2ger (he/him; ⌚ UTC+1/+2)]

https://hg.mozilla.org/mozilla-central/rev/776354d56c25

Comment 9

[David Baron :dbaron: (⌚️UTC-4, no longer working on Mozilla)]

Comment on attachment 791659 [details] [diff] [review]
possible patch

Sorry for the long delay; finally updated my tree.

I tested this, and it doesn't seem to help.  Opening 3 articles in a session with a large number of tabs still nearly pegs the CPU, and perf still shows a lot of the time in that same stack.

(I think there may be iframes whose URLs change repeatedly.)

Comment 10

[Olli Pettay [:smaug][[e-mail]]]

Well, then I don't what is triggering those GCs.

(however, I was told the patch in this bug has helped in some other cases)

Comment 11

[Olli Pettay [:smaug][[e-mail]]]

Perhaps we shouldn't trigger GC so often?