1313347 - Tracing a mono-type store buffer can trigger a new minor GC

Status: RESOLVED FIXED

(Core :: JavaScript: GC, defect)

Description

[Jon Coppeard (:jonco)]

While investigating promise creation performance, till found the following pattern of minor GCs with promotion rate alternating between something and zero:

MinorGC:    FULL_STORE_BUFFER   5.9%   16    5842      0      0      1    274      0      0      0     14      1      1    287      0      0      1      0     22    416   4823      1
MinorGC:    FULL_STORE_BUFFER   0.0%   16    1047      0      0      1     20      0      1      0     19      0      3      1      0      1      1      0     26    970      0      0
MinorGC:    FULL_STORE_BUFFER   2.9%   16    2003      0      1      0    651      1      0      1     15      0      2    329      0      1      1      0     23    974      1      1
MinorGC:    FULL_STORE_BUFFER   0.0%   16     946      0      1      0      8      1      0      0     10      1      1      0      0      1      1      0     19    900      0      0
MinorGC:    FULL_STORE_BUFFER   2.9%   16    1422      0      1      0    296      0      0      0     15      0      2    301      0      0      2      0     21    781      1      0
MinorGC:    FULL_STORE_BUFFER   0.0%   16     903      0      0      1      8      0      0      0     11      1      2      0      0      1      0      1     18    857      0      0
MinorGC:    FULL_STORE_BUFFER   2.9%   16    1657      0      1      0    500      1      0      0     14      1      2    332      0      1      1      0     20    781      0      1
MinorGC:    FULL_STORE_BUFFER   0.0%   16     795      0      1      1     11      0      0      1     14      0      2      1      1      1      0      0     10    751      0      0
MinorGC:    FULL_STORE_BUFFER   2.9%   16    1652      0      0      1    293      0      0      0      8      0      2    557      0      0      2      0      9    779      1      0
MinorGC:    FULL_STORE_BUFFER   0.0%   16     772      0      0      0      9      0      0      0      6      0      2      0      0      0      1      0      8    745      0      0
MinorGC:    FULL_STORE_BUFFER   2.9%   16    1604      0      1      0    462      0      0      0     14      0      2    342      0      0      1      1     11    767      0      0
MinorGC:    FULL_STORE_BUFFER   0.0%   16     787      0      0      1      9      0      0      0      7      0      2      0      0      1      0      0      8    758      0      0

The stack trace for the ones where we're not tenuring anything is:

* thread #1: tid = 0x70203, 0x00000001000d6c70 js`js::gc::StoreBuffer::setAboutToOverflow(this=0x000000010400b1a8) + 16 at StoreBuffer.cpp:90, queue = 'com.apple.main-thread', stop reason = breakpoint 1.1
  * frame #0: 0x00000001000d6c70 js`js::gc::StoreBuffer::setAboutToOverflow(this=0x000000010400b1a8) + 16 at StoreBuffer.cpp:90
    frame #1: 0x000000010003fd21 js`js::gc::StoreBuffer::MonoTypeBuffer<js::gc::StoreBuffer::SlotsEdge>::sinkStore(this=0x000000010400b258, owner=0x000000010400b1a8) + 289 at StoreBuffer.h:124
    frame #2: 0x0000000100ea0a0c js`js::gc::StoreBuffer::MonoTypeBuffer<js::gc::StoreBuffer::SlotsEdge>::trace(this=0x000000010400b258, owner=0x000000010400b1a8, mover=0x00007fff5fbfa8b8) + 284 at Marking.cpp:2256
    frame #3: 0x0000000100ec0667 js`js::gc::StoreBuffer::traceSlots(this=0x000000010400b1a8, mover=0x00007fff5fbfa8b8) + 39 at StoreBuffer.h:427
    frame #4: 0x0000000100ebf7d0 js`js::Nursery::doCollection(this=0x000000010400ae08, rt=0x000000010400a608, reason=FULL_STORE_BUFFER, tenureCounts=0x00007fff5fbfaa88) + 400 at Nursery.cpp:689
    frame #5: 0x0000000100ebf02e js`js::Nursery::collect(this=0x000000010400ae08, rt=0x000000010400a608, reason=FULL_STORE_BUFFER) + 686 at Nursery.cpp:584
    frame #6: 0x0000000100871e1c js`js::gc::GCRuntime::minorGC(this=0x000000010400adb0, reason=FULL_STORE_BUFFER, phase=PHASE_MINOR_GC) + 300 at jsgc.cpp:6561
    frame #7: 0x000000010085d83d js`js::gc::GCRuntime::gcIfRequested(this=0x000000010400adb0) + 61 at jsgc.cpp:6603
    frame #8: 0x0000000100b69643 js`InvokeInterruptCallback

It looks like we are triggering minor GC inside minor GC!

This is running the following workload, for which the patch in bug 1313049 is required:

if (typeof console !== 'undefined')
    print = console.log.bind(console);

var iterations = 100000;

var start;
function test() {
    start = Date.now();
    // chain up some promises...
    var i = iterations;
    //startTraceLogger();
    var p = Promise.resolve(1);
    while (--i) {
      p = p.then(function(value) { j++; if (j >= iterations-1) print('resolving promises: ' + (Date.now() - start)); return value+1; });
    }

    //stopTraceLogger();
    print('creating promises: ' + (Date.now() - start));
    start = Date.now();
}
test();

var j = 0;

Comment 1

[Jon Coppeard (:jonco)]

Attachment: bug1313347-minor-gc-trigger

Calling MonoTypeBuffer::sinkStore() might trigger another minor GC, so just trace last_ instead.

Comment 2

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/a5d8d7e811c1
Ensure we don't trigger another GC while collecting r=sfink

Comment 3

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/a5d8d7e811c1