Intermittent jsreftest.html?test=js1_5/Regress/regress-360969-05.js | application timed out after 330 seconds with no output

RESOLVED FIXED in Firefox 38, Firefox OS v2.2

Status

()

Core
JavaScript Engine
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: philor, Assigned: arai)

Tracking

({intermittent-failure})

Trunk
mozilla39
x86
Linux
intermittent-failure
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox37 wontfix, firefox38 fixed, firefox39 fixed, firefox-esr31 unaffected, b2g-v2.2 fixed, b2g-master fixed)

Details

Attachments

(8 attachments, 1 obsolete attachment)

Comment hidden (empty)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Reporter)

Updated

3 years ago
Blocks: 1116663
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 227

3 years ago
Created attachment 8572829 [details] [diff] [review]
Perform full GC before the loop in regress-360969-05.js.

Locally, regress-360969-05.js runs within 30 seconds if I run only regress-360969-*.js in jsreftest, but if I run whole tests under js1_5/, regress-360969-05.js takes too long time and hits timeout.

Then, if I add `gc()` before the loop, regress-360969-05.js takes 30 seconds even on latter case. so I guess GC (maybe a kind of partial GC?) took so long time during the loop.

I added `gc()` to all tests for bug 360969, so bug 1122413, bug 1137221, bug 1116663 should also be fixed by this patch.

Green on try run, and regress-360969-05.js took 11 seconds there:
  https://treeherder.mozilla.org/#/jobs?repo=try&revision=147f51049d70
Attachment #8572829 - Flags: review?(jcoppeard)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(In reply to Tooru Fujisawa [:arai] from comment #227)
Thanks for the patch.  I agree that makes the test pass but I'd really like to know what is going wrong here.  GCs shouldn't make the test take so long.  So I'm going to leave the request outstanding till I work out what to do here.

It's interesting that you managed to reproduce this locally though, I haven't been able to do that.

Also, it's possible that the fix for bug 1139832 might cure this.
(Assignee)

Comment 237

3 years ago
Thank you for your feedback :)
Okay, I'll also try to investigate what actually goes there, and try the patch in bug 1139832 on local build.

I used virtual machine on virtualbox to reproduce it.
  Host
    Debian jessie 64bit (Linux 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt2-1 (2014-12-08) x86_64 GNU/Linux)
    CPU: Intel(R) Core(TM) i5 CPU 650 @ 3.20GHz
    RAM: 4GB
  Guest
    Debian jessie 32bit (Linux 3.16.0-4-586 #1 Debian 3.16.7-ckt4-3 (2015-02-03) i686 GNU/Linux)
    Processors: 2
    RAM: 2GB
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 242

3 years ago
Added logging in GCRuntime::collect, and tried both pass/fail case (without my gc() patch)

When regress-360969-05.js passes, it's called twice while the loop, with incremental=true and reason=ALLOC_TRIGGER, and test takes 31 seconds.

When regress-360969-05.js fails, it's called 212 times while the loop (almost each 3 seconds), with incremental=true and reason=ALLOC_TRIGGER. Also called twice before the loop, with incremental=true and reason=INTER_SLICE_GC. the test takes 767 seconds.

I'll add more logging.
(Assignee)

Comment 243

3 years ago
Created attachment 8573619 [details] [diff] [review]
(testing) Log GC and loop in regress-360969-05.js.

testing patch for logging.
I'll post results for pass and failure cases.
(Assignee)

Comment 244

3 years ago
Created attachment 8573620 [details]
log_pass.txt
(Assignee)

Comment 245

3 years ago
Created attachment 8573623 [details]
log_fail.txt

in failure case, GC is performed many times but not so much memory is freed.
Comment hidden (Treeherder Robot)
(In reply to Tooru Fujisawa [:arai] from comment #245)
Thanks for logs!  212 collections is really surprising.  Where do the byte values in your logs come from?
(Assignee)

Comment 248

3 years ago
`usage.gcBytes()` in following 2 macros, called in GCRuntime::collect, in attachment 8573619 [details] [diff] [review].
>+#define LOG_BEFORE() fprintf(stderr, "****collect**** [%d: %s] - before: %10zu bytes\n", incremental, reasonToString(reason), usage.gcBytes());
>+#define LOG_AFTER(MESSAGE) fprintf(stderr, "****collect**** [%d: %s] -  after: %10zu bytes (%s)\n", incremental, reasonToString(reason), usage.gcBytes(), MESSAGE);

Now I'm trying logging for GCRuntime::maybeAllocTriggerZoneGC, with usedBytes, thresholdBytes, and igcThresholdBytes, since all reasons are ALLOC_TRIGGER.
(Assignee)

Comment 249

3 years ago
Created attachment 8573952 [details] [diff] [review]
(testing) Log GC and loop in regress-360969-05.js. rev.2: GCRuntime::maybeAllocTriggerZoneGC.

testing patch for logging, in GCRuntime::maybeAllocTriggerZoneGC.
(Assignee)

Comment 250

3 years ago
Created attachment 8573953 [details]
log_pass2.txt

log for attachment 8573952 [details] [diff] [review], with test pass
(Assignee)

Comment 251

3 years ago
Created attachment 8573956 [details]
log_fail2.txt

log for attachment 8573952 [details] [diff] [review], with test failure

in pass case, triggerZoneGC is called only in `usedBytes >= igcThresholdBytes` condition.

in failure case, triggerZoneGC is also called in `usedBytes >= thresholdBytes` condition, and it hits so much time.
so, this maybe the issue related to the value of thresholdBytes?
Comment hidden (Treeherder Robot)
(In reply to Tooru Fujisawa [:arai] from comment #251)
So we are getting many ALLOC_TRIGER GCs where the threshold for the zone stays the same (5259264 bytes).  This indicates that we aren't collecting that zone, because even if we collected a zone but didn't free anything in the zone we should still update (i.e. increase) its threshold value afterwards.

So given that this test creates a lot of local variables I'm guessing that this is the atoms zone we are triggering on.  We're trying to do a zone GC, but we don't actually collect the atoms zone unless we're doing a full GC (as any zone may contain references to atoms and they're not in the cross-compartment map).  So actually we will not collect this zone.

Then, since I fixed bug 1032750 we will not update the threshold values for zones we didn't collect, and so we get this problem.  Checking that bug reveals it landed on 30/12/14... the date this started happening.
(In reply to Jon Coppeard (:jonco) from comment #253)
...wait, zone GC is not the culprit, we already take account of this in GCRuntime::triggerZoneGC() and trigger a full GC if zone GC of the atoms zone is requested.  Maybe collection of atoms is being supressed for another reason.
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 282

3 years ago
The triggerZoneGC call happens inside the Parser for `eval` call, which has AutoKeepAtoms in its member.

https://dxr.mozilla.org/mozilla-central/source/js/src/frontend/Parser.h#356
>     /* Root atoms and objects allocated for the parsed tree. */
>     AutoKeepAtoms       keepAtoms;

----
#0  js::gc::GCRuntime::triggerZoneGC (this=0xac13d1a8, zone=0xad3c1400, reason=JS::gcreason::ALLOC_TRIGGER)
    at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:3319
#1  0xb3c28a7a in js::gc::GCRuntime::maybeAllocTriggerZoneGC (this=0xac13d1a8, zone=0xad3c1400, lock=...)
    at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:3212
#2  0xb3c22f5b in js::gc::GCRuntime::allocateArena (this=0xac13d1a8, chunk=0x98300000, zone=0xad3c1400, 
    thingKind=js::gc::FINALIZE_FAT_INLINE_STRING, lock=...) at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:1056
#3  0xb3c25355 in js::gc::ArenaLists::allocateFromArena (this=0xad3c141c, zone=0xad3c1400, 
    thingKind=js::gc::FINALIZE_FAT_INLINE_STRING, maybeStartBGAlloc=...)
    at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:1852
#4  0xb3c28320 in js::gc::GCRuntime::tryRefillFreeListFromMainThread (cx=0xac164840, 
    thingKind=js::gc::FINALIZE_FAT_INLINE_STRING) at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:2991
#5  0xb3cb2051 in js::gc::GCRuntime::refillFreeListFromMainThread<(js::AllowGC)0> (cx=0xac164840, 
    thingKind=js::gc::FINALIZE_FAT_INLINE_STRING) at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:3021
#6  0xb3c97d68 in js::gc::GCRuntime::refillFreeListFromAnyThread<(js::AllowGC)0> (cx=0xac164840, 
    thingKind=js::gc::FINALIZE_FAT_INLINE_STRING) at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:3086
#7  0xb368dfdf in AllocateNonObject<JSFatInlineString, (js::AllowGC)0> (cx=0xac164840)
    at /home/arai/projects/mozilla-central/js/src/gc/Allocator.cpp:214
#8  0xb367ab20 in js::NewGCFatInlineString<(js::AllowGC)0> (cx=0xac164840)
    at /home/arai/projects/mozilla-central/js/src/gc/Allocator.cpp:304
#9  0xb3861ea7 in JSFatInlineString::new_<(js::AllowGC)0> (cx=0xac164840)
    at /home/arai/projects/mozilla-central/js/src/vm/String-inl.h:258
#10 0xb3828c6f in js::AllocateInlineString<(js::AllowGC)0, unsigned char> (cx=0xac164840, len=8, chars=0xbfaa9cf0)
    at /home/arai/projects/mozilla-central/js/src/vm/String-inl.h:37
#11 0xb38304cd in NewInlineStringDeflated<(js::AllowGC)0> (cx=0xac164840, chars=...)
    at /home/arai/projects/mozilla-central/js/src/vm/String.cpp:884
#12 0xb38290f3 in NewStringDeflated<(js::AllowGC)0> (cx=0xac164840, s=0x9c0b3682 u"pf106602() {}", n=8)
    at /home/arai/projects/mozilla-central/js/src/vm/String.cpp:901
#13 0xb3847c3b in js::NewStringCopyN<(js::AllowGC)0, char16_t> (cx=0xac164840, s=0x9c0b3682 u"pf106602() {}", n=8)
    at /home/arai/projects/mozilla-central/js/src/vm/String.cpp:1045
#14 0xb350d26d in AtomizeAndCopyChars<char16_t> (cx=0xac164840, tbchars=0x9c0b3682 u"pf106602() {}", length=8, 
    ib=js::DoNotInternAtom) at /home/arai/projects/mozilla-central/js/src/jsatom.cpp:350
#15 0xb350fcd1 in js::AtomizeChars<char16_t> (cx=0xac164840, chars=0x9c0b3682 u"pf106602() {}", length=8, 
    ib=js::DoNotInternAtom) at /home/arai/projects/mozilla-central/js/src/jsatom.cpp:437
#16 0xb36400f6 in js::frontend::TokenStream::getTokenInternal (this=0xbfaaa7ec, ttp=0xbfaa9f28, 
    modifier=js::frontend::TokenStream::None) at /home/arai/projects/mozilla-central/js/src/frontend/TokenStream.cpp:1238
#17 0xb35a9698 in js::frontend::TokenStream::getToken (this=0xbfaaa7ec, ttp=0xbfaa9f28, 
    modifier=js::frontend::TokenStream::None) at /home/arai/projects/mozilla-central/js/src/frontend/TokenStream.h:389
#18 0xb3db1084 in js::frontend::Parser<js::frontend::FullParseHandler>::functionStmt (this=0xbfaaa7d4)
    at /home/arai/projects/mozilla-central/js/src/frontend/Parser.cpp:2609
#19 0xb3db0050 in js::frontend::Parser<js::frontend::FullParseHandler>::statement (this=0xbfaaa7d4, canHaveDirectives=true)
    at /home/arai/projects/mozilla-central/js/src/frontend/Parser.cpp:5964
#20 0xb361c485 in js::frontend::CompileScript (cx=0xac164840, alloc=0xac13d128, scopeChain=..., evalCaller=..., 
    evalStaticScope=..., options=..., srcBuf=..., source_=0x98341080, staticLevel=2, extraSct=0x0)
    at /home/arai/projects/mozilla-central/js/src/frontend/BytecodeCompiler.cpp:346
#21 0xb3548f76 in js::DirectEvalStringFromIon (cx=0xac164840, scopeobj=..., callerScript=..., thisValue=..., str=..., 
    pc=0xa034fdbb "{", vp=...) at /home/arai/projects/mozilla-central/js/src/builtin/Eval.cpp:419
#22 0xad426c1a in ?? ()
----

Also, in GCRuntime::beginMarkPhase, the value of rt->keepAtoms_ is 2. so I guess Parser is also alive here, and it prevents atom zone from collecting. (but there should be one more thing which increments keepAtoms_...)
I'll get the backtrace for GCRuntime::beginMarkPhase too.
(Assignee)

Comment 283

3 years ago
(different run from previous one)
js::gc::GCRuntime::beginMarkPhase is also called inside Parser.

#0  js::gc::GCRuntime::beginMarkPhase (this=0xac03d1a8, reason=JS::gcreason::ALLOC_TRIGGER)
    at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:3981
#1  0xb3c23fda in js::gc::GCRuntime::incrementalCollectSlice (this=0xac03d1a8, budget=..., 
    reason=JS::gcreason::ALLOC_TRIGGER) at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:6046
#2  0xb3c2495a in js::gc::GCRuntime::gcCycle (this=0xac03d1a8, incremental=true, budget=..., 
    reason=JS::gcreason::ALLOC_TRIGGER) at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:6287
#3  0xb3c25044 in js::gc::GCRuntime::collect (this=0xac03d1a8, incremental=true, budget=..., 
    reason=JS::gcreason::ALLOC_TRIGGER) at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:6408
#4  0xb3c25518 in js::gc::GCRuntime::startGC (this=0xac03d1a8, gckind=GC_NORMAL, reason=JS::gcreason::ALLOC_TRIGGER, 
    millis=0) at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:6483
#5  0xb3c25f42 in js::gc::GCRuntime::gcIfRequested (this=0xac03d1a8, cx=0xa12bf0c0)
    at /home/arai/projects/mozilla-central/js/src/jsgc.cpp:6681
#6  0xb36333f5 in GCIfNeeded (cx=0xa12bf0c0) at /home/arai/projects/mozilla-central/js/src/gc/Allocator.cpp:77
#7  0xb36510ee in CheckAllocatorState<(js::AllowGC)1> (cx=0xa12bf0c0, kind=js::gc::FINALIZE_OBJECT2_BACKGROUND)
    at /home/arai/projects/mozilla-central/js/src/gc/Allocator.cpp:99
#8  0xb367a8ac in AllocateObject<(js::AllowGC)1> (cx=0xa12bf0c0, kind=js::gc::FINALIZE_OBJECT2_BACKGROUND, 
    nDynamicSlots=0, heap=js::gc::TenuredHeap, clasp=0xb6cff9c0 <JSFunction::class_>)
    at /home/arai/projects/mozilla-central/js/src/gc/Allocator.cpp:164
#9  0xb366ba18 in js::NewGCObject<(js::AllowGC)1> (cx=0xa12bf0c0, kind=js::gc::FINALIZE_OBJECT2_BACKGROUND, 
    nDynamicSlots=0, heap=js::gc::TenuredHeap, clasp=0xb6cff9c0 <JSFunction::class_>)
    at /home/arai/projects/mozilla-central/js/src/gc/Allocator.cpp:269
#10 0xb3794fab in JSObject::create (cx=0xa12bf0c0, kind=js::gc::FINALIZE_OBJECT2_BACKGROUND, heap=js::gc::TenuredHeap, 
    shape=..., group=...) at /home/arai/projects/mozilla-central/js/src/jsobjinlines.h:265
#11 0xb3c35360 in NewObject (cx=0xa12bf0c0, group=..., parent=..., kind=js::gc::FINALIZE_OBJECT2_BACKGROUND, 
    newKind=js::MaybeSingletonObject) at /home/arai/projects/mozilla-central/js/src/jsobj.cpp:1201
#12 0xb3c3664f in js::NewObjectWithClassProtoCommon (cxArg=0xa12bf0c0, clasp=0xb6cff9c0 <JSFunction::class_>, 
    protoArg=..., maybeParent=..., allocKind=js::gc::FINALIZE_OBJECT2_BACKGROUND, newKind=js::MaybeSingletonObject)
    at /home/arai/projects/mozilla-central/js/src/jsobj.cpp:1450
#13 0xb35a9063 in js::NewObjectWithClassProto (cx=0xa12bf0c0, clasp=0xb6cff9c0 <JSFunction::class_>, proto=..., 
    parent=..., allocKind=js::gc::FINALIZE_OBJECT2_BACKGROUND, newKind=js::MaybeSingletonObject)
    at /home/arai/projects/mozilla-central/js/src/jsobjinlines.h:677
#14 0xb3c10cf9 in js::NewFunctionWithProto (cx=0xa12bf0c0, funobjArg=..., native=0x0, nargs=0, 
    flags=JSFunction::INTERPRETED, parent=..., atom=..., proto=..., allocKind=js::gc::FINALIZE_OBJECT2_BACKGROUND, 
    newKind=js::MaybeSingletonObject) at /home/arai/projects/mozilla-central/js/src/jsfun.cpp:2046
#15 0xb3da0790 in js::frontend::Parser<js::frontend::FullParseHandler>::newFunction (this=0xbfd0aa94, atom=..., 
    kind=js::frontend::Statement, proto=...) at /home/arai/projects/mozilla-central/js/src/frontend/Parser.cpp:1240
#16 0xb3da9202 in js::frontend::Parser<js::frontend::FullParseHandler>::functionDef (this=0xbfd0aa94, funName=..., 
    type=js::frontend::Normal, kind=js::frontend::Statement, generatorKind=js::NotGenerator, 
    invoked=js::frontend::Parser<js::frontend::FullParseHandler>::PredictUninvoked)
    at /home/arai/projects/mozilla-central/js/src/frontend/Parser.cpp:2175
#17 0xb3da223f in js::frontend::Parser<js::frontend::FullParseHandler>::functionStmt (this=0xbfd0aa94)
    at /home/arai/projects/mozilla-central/js/src/frontend/Parser.cpp:2635
#18 0xb3da1050 in js::frontend::Parser<js::frontend::FullParseHandler>::statement (this=0xbfd0aa94, canHaveDirectives=true)
    at /home/arai/projects/mozilla-central/js/src/frontend/Parser.cpp:5964
#19 0xb360d485 in js::frontend::CompileScript (cx=0xa12bf0c0, alloc=0xac03d128, scopeChain=..., evalCaller=..., 
    evalStaticScope=..., options=..., srcBuf=..., source_=0x9f3e5fe0, staticLevel=2, extraSct=0x0)
    at /home/arai/projects/mozilla-central/js/src/frontend/BytecodeCompiler.cpp:346
#20 0xb3539f76 in js::DirectEvalStringFromIon (cx=0xa12bf0c0, scopeobj=..., callerScript=..., thisValue=..., str=..., 
    pc=0xaa23983b "{", vp=...) at /home/arai/projects/mozilla-central/js/src/builtin/Eval.cpp:419
#21 0xad405c1a in ?? ()
(Assignee)

Comment 284

3 years ago
maybe we should run full GC again after parsing (or eval) done for this case?
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 296

3 years ago
Created attachment 8577964 [details] [diff] [review]
Perform full GC after keepAtoms gets false if full GC was triggered by atom zone but keepAtoms was true then.

Added ALLOC_TRIGGER_ATOMS reason, which requests extra full GC if rt->keepAtoms() is true, which runs after rt->keepAtoms() gets false, in AutoKeepAtoms destructor or JSRuntime::clearUsedByExclusiveThread.
Is this appropriate solution?

With logging for requestFullGCForAtoms and performFullGCForAtoms, it shows following. requestFullGCForAtoms is called (from AutoKeepAtoms destructor), and performFullGCForAtoms is called 3 seconds later (after full GC without atoms), then full GC with atoms is performed, and the test passes without extra requestFullGCForAtoms call.

 7:24.03 REFTEST TEST-START | file:///home/arai/projects/mozilla-central/obj-master-debug/dist/test-stage/jsreftest/tests/jsreftest.html?test=js1_5/Regress/regress-360969-05.js
 7:24.05 REFTEST REFTEST TEST-LOAD | file:///home/arai/projects/mozilla-central/obj-master-debug/dist/test-stage/jsreftest/tests/jsreftest.html?test=js1_5/Regress/regress-360969-05.js | 289 / 701 (41%)
 7:24.14 ++DOMWINDOW == 14 (0x9f20a800) [pid = 22193] [serial = 565] [outer = 0xa0d8b200]
 7:24.38 TEST-INFO | BUGNUMBER: 360969
 7:24.40 TEST-INFO | STATUS: 2^17: local function
 7:52.21 requestFullGCForAtoms
 7:55.50 performFullGCForAtoms
 8:05.10 TEST-INFO | Elapsed time: 40 seconds
 8:05.26 REFTEST TEST-PASS | file:///home/arai/projects/mozilla-central/obj-master-debug/dist/test-stage/jsreftest/tests/jsreftest.html?test=js1_5/Regress/regress-360969-05.js | 2^17: local function  item 1
 8:05.26 REFTEST REFTEST INFO | Loading a blank page
 8:05.29 ++DOMWINDOW == 15 (0x9d137800) [pid = 22193] [serial = 566] [outer = 0xa0d8b200]
 8:05.34 REFTEST REFTEST TEST-END | file:///home/arai/projects/mozilla-central/obj-master-debug/dist/test-stage/jsreftest/tests/jsreftest.html?test=js1_5/Regress/regress-360969-05.js

Green on try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=3103d9066d75
Attachment #8577964 - Flags: feedback?(jcoppeard)
Comment on attachment 8577964 [details] [diff] [review]
Perform full GC after keepAtoms gets false if full GC was triggered by atom zone but keepAtoms was true then.

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

Thanks for taking this on!  I think running a collection when keepAtoms becomes false is the right way to go here.

With this patch we will still run GCs when the atoms zone is over its threshold though.  Instead, how about setting the flag and skipping the collection in GCRuntime::triggerZoneGC() if the zone is the atoms zone but keepAtoms is true?

::: js/src/vm/Runtime.h
@@ +1190,5 @@
>      // compartment. Therefore, we avoid collecting the atoms compartment when
>      // exclusive threads are running.
>    private:
>      unsigned keepAtoms_;
> +    bool fullGCForAtomsRequested_;

Please move the new state to GCRuntime in gc/GCRuntime.h
Attachment #8577964 - Flags: feedback?(jcoppeard) → feedback+
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)

Updated

3 years ago
Attachment #8572829 - Flags: review?(jcoppeard)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 307

3 years ago
Created attachment 8578873 [details] [diff] [review]
Skip full GC triggered by atoms zone if keepAtoms is true, and retrigger it after keepAtoms becomes false.

Thank you for reviewing!
Fixed to skip GC for atoms zone if keepAtoms is true.

Green on try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c9c0cf4f6c3b
Attachment #8577964 - Attachment is obsolete: true
Attachment #8578873 - Flags: review?(jcoppeard)
Comment hidden (Treeherder Robot)
Comment on attachment 8578873 [details] [diff] [review]
Skip full GC triggered by atoms zone if keepAtoms is true, and retrigger it after keepAtoms becomes false.

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

Perfect, thanks for fixing!
Attachment #8578873 - Flags: review?(jcoppeard) → review+
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
(Assignee)

Comment 314

3 years ago
Thank you for reviewing!

https://hg.mozilla.org/integration/mozilla-inbound/rev/5462a753d849
Assignee: nobody → arai.unmht
https://hg.mozilla.org/mozilla-central/rev/5462a753d849
Status: NEW → RESOLVED
Last Resolved: 3 years ago
status-firefox39: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla39
Comment hidden (Treeherder Robot)
Please nominate this for Aurora/Beta approval when you get a chance.
status-b2g-v2.2: --- → affected
status-b2g-master: --- → fixed
status-firefox37: --- → affected
status-firefox38: --- → affected
status-firefox-esr31: --- → unaffected
Flags: needinfo?(arai.unmht)

Updated

3 years ago
Blocks: 1032750
Comment on attachment 8578873 [details] [diff] [review]
Skip full GC triggered by atoms zone if keepAtoms is true, and retrigger it after keepAtoms becomes false.

Approval Request Comment
[Feature/regressing bug #]: Bug 1032750 (this caused the test timeouts, although it only revealed the underlying problem)
[User impact if declined]: Possible slowness while parsing scripts
[Describe test coverage new/current, TreeHerder]: Try, on m-c since March 19th only.
[Risks and why]: Low
[String/UUID change made/needed]: None
Attachment #8578873 - Flags: approval-mozilla-aurora?
Attachment #8578873 - Flags: approval-mozilla-beta?
https://hg.mozilla.org/releases/mozilla-aurora/rev/decce7b6987f
status-firefox38: affected → fixed
Comment on attachment 8578873 [details] [diff] [review]
Skip full GC triggered by atoms zone if keepAtoms is true, and retrigger it after keepAtoms becomes false.

I think it's too late in Beta to take this change. Certainly suitable for Aurora thought. Beta- Aurora+
Attachment #8578873 - Flags: approval-mozilla-beta?
Attachment #8578873 - Flags: approval-mozilla-beta-
Attachment #8578873 - Flags: approval-mozilla-aurora?
Attachment #8578873 - Flags: approval-mozilla-aurora+
Comment on attachment 8578873 [details] [diff] [review]
Skip full GC triggered by atoms zone if keepAtoms is true, and retrigger it after keepAtoms becomes false.

See comment 318 for questionnaire answers. This is a widespread issue that hits many platforms and would be good to get on b2g37 so we're not living with it for the next year and change. FWIW, most of the issues have been manifesting on more resource-constrained platforms, so there's probably a legit B2G win here too.
Attachment #8578873 - Flags: approval-mozilla-b2g37?
status-firefox37: affected → wontfix

Updated

3 years ago
Attachment #8578873 - Flags: approval-mozilla-b2g37? → approval-mozilla-b2g37+
(Assignee)

Comment 322

3 years ago
Thank you all :D

https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/02654a8b4f24
status-b2g-v2.2: affected → fixed
Flags: needinfo?(arai.unmht)
Comment hidden (Treeherder Robot)

Updated

3 years ago
Duplicate of this bug: 1122413

Updated

3 years ago
Duplicate of this bug: 1137221
Comment hidden (Treeherder Robot)
Comment hidden (Treeherder Robot)
You need to log in before you can comment on or make changes to this bug.