488559 - graphs.mozilla.org causes really long GC pauses when a lot of other windows are open

Status: RESOLVED WONTFIX

(Core :: JavaScript Engine, defect)

Description

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

http://graphs.mozilla.org/ causes *really* long GC pauses in a build in which a lot of other windows are open.

Steps to reproduce:
 1. set up a Firefox session in which a lot of other windows are open.  (I'm running a debug build; my current WEBSHELL count is 404; that's a total of 51 browser windows, with a bunch of tabs in them.)
 2. load "graphs.mozilla.org"
 3. change the "Branch" dropdown from "All" to "1.9.2"

Actual results:

After step (1), my GC pauses are around 1.6s-1.8s.

After step (3), I get a single GC pause that's around 100s-120s.  (I have some printfs in js_GC; see the patch at http://hg.mozilla.org/users/dbaron_mozilla.com/patches/file/tip/gc-time-printfs , so I can clearly see that this is a single GC that takes that amount of time.)

Expected results:  Loading http://graphs.mozilla.org/ should not cause a substantial change in the amount of time js_GC takes.

Comment 1

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

Attachment: the top of an oprofile report

oprofile says the culprit is InsertPropertyTreeChild.  This sample was done entirely during a single GC pause.

Comment 2

[Andreas Gal :gal]

graydon, your favorite bug is back (with a slight variation)

Comment 3

[Brendan Eich [:brendan]]

Not the symptom of that delete bug that Graydon fixed (bug 479553). This is possibly induced by delete, though -- where is the source repository holding the graphserver JS code that is likely involved here located, so we can browse it?

/be

Comment 4

[Brendan Eich [:brendan]]

Did this regress recently?

/be

Comment 5

[Shawn Wilsher :sdwilsh]

(In reply to comment #4)
> Did this regress recently?
This has been happening for me since at least Fall of last year.  Not 100s long like dbaron was saying on irc, but sometimes up to a minute.

Comment 6

[Graydon Hoare :graydon]

I am seeing a pause, but it has a decidedly different profile shape.

The profile you posted implicates the stuff I was trying to fix with
bug 479553. Do you know if that was in the build you were testing with?
Can you check your oprofile output again to confirm that you're still
seeing a GC pause attributable to these symbols, and have the fix for
that bug?

Oprofiling my tip today shows the expected pebbles you get when 
there's no real platform bottleneck, just a busy script:

CPU: Core 2, speed 1596 MHz (estimated)
Counted CPU_CLK_UNHALTED events (Clock cycles when not halted)
CPU_CLK_UNHALT...|
  samples|      %|
------------------
   784438 100.000 .../dist/bin/firefox-bin
        CPU_CLK_UNHALT...|
          samples|      %|
        ------------------
           419879 53.5261 .../layout/build/libgklayout.so
            85063 10.8438 .../js/src/libmozjs.so
            77039  9.8209 .../xpcom/build/libxpcom_core.so
            36510  4.6543 .../nsprpub/pr/src/libnspr4.so
            31188  3.9758 .../js/src/xpconnect/src/libxpconnect.so
            29955  3.8187 /lib/tls/i686/cmov/libc-2.6.1.so
            21268  2.7112 /lib/tls/i686/cmov/libpthread-2.6.1.so
            ...

within .../layout/build/libgklayout.so:

samples  %        image name           symbol name
30540     7.2735  libgklayout.so       __i686.get_pc_thunk.bx
7544      1.7967  libgklayout.so       SelectorMatches(...)
6900      1.6433  libgklayout.so       nsCachedStyleData::GetBitForSID(...)
6380      1.5195  libgklayout.so       nsBlockFrame::ReflowDirtyLines(...)
5799      1.3811  libgklayout.so       nsLineList_iterator::operator->()
4196      0.9993  libgklayout.so       nsStyleCoord::GetUnit() const
3863      0.9200  libgklayout.so       nsFrame::ComputeSize(...)
3564      0.8488  libgklayout.so       nsHTMLReflowState::InitConstraints(...)
3416      0.8136  libgklayout.so       nsCSSOffsetState::InitOffsets(...)
...

within .../js/src/libmozjs.so:

samples  %        image name           symbol name
11168    13.1291  libmozjs.so          js_Interpret
3860      4.5378  libmozjs.so          __i686.get_pc_thunk.bx
3858      4.5355  libmozjs.so          JS_CallTracer
2408      2.8308  libmozjs.so          ExecuteREBytecode(...)
2279      2.6792  libmozjs.so          gc_root_traversal(...)
2154      2.5322  libmozjs.so          js_SearchScope
2063      2.4253  libmozjs.so          js_TraceObject
1683      1.9785  libmozjs.so          STOBJ_GET_CLASS
1681      1.9762  libmozjs.so          GetGCThingFlags(...)
...

and so on.

Looks to me like jquery is just hammering on the DOM and style system.
Though it does go to sleep for upwards of 5s. Nothing like 100s though.

(The get_pc_thunk just means "accessing any static data via the GOT")

Comment 7

[Karl Tomlinson (:karlt)]

When I was once trying to work out what was happening here (or something similar), it seemed that the nsJSContext::MaybeCC/IntervalCC/nsUserActivityObserver logic was such that when JS_GC took a long time, the next IntervalCC started, and so it was not possible to interact with the browser.

(This was a while ago, though.  Don't know if the logic has changed since then.
And I had trouble reproducing.)

Comment 8

[Graydon Hoare :graydon]

Long since obsolete.