Closed Bug 1310175 Opened 5 years ago Closed 4 years ago

Crash [@ OOM | small ] with nsACString_internal::Assign(char const*) involved

Categories

(Core :: JavaScript Engine, defect)

defect
Not set
normal

Tracking

()

RESOLVED WORKSFORME
Tracking Status
firefox50 --- unaffected
firefox51 + wontfix
firefox52 + fix-optional
firefox53 - fix-optional
firefox54 --- fix-optional

People

(Reporter: cbook, Unassigned)

References

()

Details

(Keywords: crash, Whiteboard: [MemShrink:P3])

Attachments

(2 files)

From the stack, it looks like the crash happened after timing out while running some JS script.
I can reproduce this locally.
Component: String → JavaScript Engine
[Tracking Requested - why for this release]:
OOM affecting opt builds on a live website + reproduced by marco
Tracking 52+ - reproducible crash found by bughunter.
Marco does this affect 51? 
Jason can you help find someone to investigate?
Flags: needinfo?(jorendorff)
In Firefox 50, the slow script dialog appears at some point and stops the memory allocations. In Aurora, the slow script bar appears and disappears continuosly, so the memory allocations continue until Firefox runs out of memory.

I've set Firefox 50 as unaffected because it's much more difficult to crash there (you would need to press "Continue" several times whenever you see the slow script dialog popping up).
Track 51+ as reproducible crash.
Hi Marco,
what about 51, is it easy to crash in 51?
Flags: needinfo?(mcastelluccio)
(In reply to Gerry Chang [:gchang] from comment #7)
> Hi Marco,
> what about 51, is it easy to crash in 51?

Yes, 51 is Aurora currently.
Flags: needinfo?(mcastelluccio)
Hi kanru,
can you help shed some light here? Thanks.
Flags: needinfo?(kchen)
I tried to reproduce on 49 and after I clicked a few times the "continue" in slow script dialog, the process is OOM killed by kernel directly. I'm looking into what is allocating.
Flags: needinfo?(kchen)
I think the site is broken. It constantly runs scripts in the xhr onreadystatechange handler and accumulates garbage very quickly. The slow script dialog will at some point enter the show/disappear cycle and eventually the content process will OOM.

Bill, based on your work in bug 1164931, maybe you know how to resolve this.
Flags: needinfo?(wmccloskey)
It's definitely a bug that the slow script infobar appears and disappears. However, the OOM would still happen because we allow scripts to continue running in e10s even when the infobar is displayed. That's a decision we could change, but it is part of the design.

Kan-Ru, are you able to reproduce the problem? I would like to help debug the appearing/disappearing issue. Does the infobar disappear and then immediately re-appear? Or does it only re-appear after 10 seconds?

In the case of a JS hang, the infobar is supposed to disappear when this happens:
http://searchfox.org/mozilla-central/rev/8562d3859b89ac89f46690b9ed2c473e0728d6c0/js/xpconnect/src/XPCJSContext.cpp#1242
That code is only supposed to run when the JS code returns to the event loop.
Flags: needinfo?(wmccloskey)
(In reply to Bill McCloskey (:billm) from comment #12)
> Does the infobar disappear and then
> immediately re-appear? Or does it only re-appear after 10 seconds?

The infobar continuosly disappears and reappears, with a delay in the order of one second.
I captured a profile

https://cleopatra.io/#report=84034cbd13e86a9a67ebbb0c94bbcff6b3956b8b&selection=0,1

The script always return to the event loop after run about 5s. The infobar rarely appears and disappears quickly. If I change dom.max_script_run_time to 2s then the infobar behaves correctly. Note if the about:newtab page tries to create thumbnail for this page the content process will be locked up because the hang monitor can't stop it.

Maybe we should measure the hang in turns of FPS rendered instead of event queue responsiveness only, because the event queue might be jammed by content generated events.
Cumulative {
  6,006,805 blocks in heap block record 1 of 39,174
  513,067,936 bytes (495,896,022 requested / 17,171,914 slop)
  Individual block sizes: 2,048 x 7; 1,024 x 159; 512 x 3,549; 496 x 27,661; 480 x 4,498; 464 x 71; 448 x 16; 432 x 41; 416 x 35; 400 x 20; 384 x 189; 368 x 91; 352 x 165; 336 x 48; 320 x 89; 304 x 737; 288 x 1,
899; 272 x 1,776; 256 x 119,871; 240 x 3,657; 224 x 1,412; 208 x 637; 192 x 11,123; 176 x 180,698; 160 x 2,324; 144 x 718,031; 128 x 515,597; 112 x 336,182; 96 x 342,643; 80 x 729,082; 64 x 803,351; 48 x 983,640
; 32 x 846,600; 16 x 46,838; 8 x 324,068
  8.55% of the heap (8.55% cumulative)
  Allocated at {
    #01: (no stack trace recorded due to --stacks=partial)
  }
}

Cumulative {
  399,610 blocks in heap block record 2 of 39,174
  313,933,056 bytes (313,933,056 requested / 0 slop)
  Individual block sizes: 1,024 x 215,356; 512 x 180,623; 256 x 3,631
  5.23% of the heap (13.79% cumulative)
  Allocated at {
    #01: replace_calloc (/home/kanru/mozilla/gecko/memory/replace/dmd/DMD.cpp:1298)
    #02: calloc (/home/kanru/mozilla/gecko/memory/build/replace_malloc.c:183)
    #03: js_calloc (/home/kanru/mozilla/gecko/obj-x86_64-pc-linux-gnu/dist/include/js/Utility.h:235)
    #04: pod_calloc<js::detail::HashTableEntry<const jsid> > (/home/kanru/mozilla/gecko/js/src/jsalloc.h:112)
    #05: EnumerateNativeProperties (/home/kanru/mozilla/gecko/js/src/jsiter.cpp:260)
    #06: Snapshot (/home/kanru/mozilla/gecko/js/src/jsiter.cpp:390)
    #07: js::GetIterator(JSContext*, JS::Handle<JSObject*>, unsigned int, JS::MutableHandle<JSObject*>) (/home/kanru/mozilla/gecko/js/src/jsiter.cpp:922)
    #08: js::GetIteratorObject(JSContext*, JS::Handle<JSObject*>, unsigned int) (/home/kanru/mozilla/gecko/js/src/jsiter.cpp:944)
    #09: ??? (???:???)
  }
}

Cumulative {
  209,387 blocks in heap block record 3 of 39,174
  174,545,152 bytes (174,545,152 requested / 0 slop)
  Individual block sizes: 2,048 x 31,085; 1,024 x 63,050; 512 x 65,685; 256 x 49,567
  2.91% of the heap (16.70% cumulative)
  Allocated at {
    #01: replace_realloc (/home/kanru/mozilla/gecko/memory/replace/dmd/DMD.cpp:1329)
    #02: realloc (/home/kanru/mozilla/gecko/memory/build/replace_malloc.c:193)
    #03: js_realloc (/home/kanru/mozilla/gecko/obj-x86_64-pc-linux-gnu/dist/include/js/Utility.h:252)
    #04: append<JSString*> (/home/kanru/mozilla/gecko/obj-x86_64-pc-linux-gnu/dist/include/mozilla/Vector.h:1313)
    #05: JSRope::copyLatin1Chars(js::ExclusiveContext*, js::ScopedJSFreePtr<unsigned char>&) const (/home/kanru/mozilla/gecko/js/src/vm/String.cpp:270)
    #06: HashStringChars<unsigned char> (/home/kanru/mozilla/gecko/js/src/vm/MemoryMetrics.cpp:62)
    #07: js::InefficientNonFlatteningStringHashPolicy::hash(JSString* const&) (/home/kanru/mozilla/gecko/js/src/vm/MemoryMetrics.cpp:75 (discriminator 1))
    #08: ScrambleHashCode (/home/kanru/mozilla/gecko/obj-x86_64-pc-linux-gnu/dist/include/js/Utility.h:543)
    #09: StatsCellCallback<(Granularity)0u> (/home/kanru/mozilla/gecko/js/src/vm/MemoryMetrics.cpp:534)
    #10: js::gc::ArenaCellIterImpl::next() (/home/kanru/mozilla/gecko/js/src/jsgcinlines.h:174 (discriminator 4))
    #11: js::ZonesIter::next() (/home/kanru/mozilla/gecko/js/src/gc/Zone.h:583)
    #12: CollectRuntimeStatsHelper (/home/kanru/mozilla/gecko/js/src/vm/MemoryMetrics.cpp:766)
    #13: JS::CollectRuntimeStats(JSContext*, JS::RuntimeStats*, JS::ObjectPrivateVisitor*, bool) (/home/kanru/mozilla/gecko/js/src/vm/MemoryMetrics.cpp:838)
    #14: xpc::JSReporter::CollectReports(nsDataHashtable<nsUint64HashKey, nsCString>*, nsDataHashtable<nsUint64HashKey, nsCString>*, nsIMemoryReporterCallback*, nsISupports*, bool) (/home/kanru/mozilla/gecko/js/xpconnect/src/XPCJSContext.cpp:2791)
    #15: nsWindowMemoryReporter::CollectReports(nsIMemoryReporterCallback*, nsISupports*, bool) (/home/kanru/mozilla/gecko/dom/base/nsWindowMemoryReporter.cpp:513)
    #16: operator() (/home/kanru/mozilla/gecko/xpcom/base/nsMemoryReporterManager.cpp:1757)
    #17: nsThread::ProcessNextEvent(bool, bool*) (/home/kanru/mozilla/gecko/xpcom/threads/nsThread.cpp:1194)
    #18: NS_ProcessNextEvent(nsIThread*, bool) (/home/kanru/mozilla/gecko/xpcom/glue/nsThreadUtils.cpp:361)
    #19: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) (/home/kanru/mozilla/gecko/ipc/glue/MessagePump.cpp:96)
    #20: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) (/home/kanru/mozilla/gecko/ipc/glue/MessagePump.cpp:302)
    #21: MessageLoop::RunInternal() (/home/kanru/mozilla/gecko/ipc/chromium/src/base/message_loop.cc:233)
    #22: MessageLoop::RunHandler() (/home/kanru/mozilla/gecko/ipc/chromium/src/base/message_loop.cc:226)
    #23: MessageLoop::Run() (/home/kanru/mozilla/gecko/ipc/chromium/src/base/message_loop.cc:205)
    #24: nsBaseAppShell::Run() (/home/kanru/mozilla/gecko/widget/nsBaseAppShell.cpp:158)
  }
}
...
Whiteboard: [MemShrink]
FYI, if that can help...

Thunderbird 45.5.0 Crash Report [@ OOM | small ]
Note from end-user: TB crashed while opened in a separate window
bp-7c0102f3-7455-4d35-a546-d67d02161123     23/11/2016    11:40 MM
https://crash-stats.mozilla.com/report/index/7c0102f3-7455-4d35-a546-d67d02161123
kernel32.dll         6.1.7601.23569         AB6B617AB7E1496AB63555DEBF8A91B12 wkernel32.pdb
ntdll.dll         6.1.7601.23569         E8115772097C49E1B552D29E17AD30DD2         wntdll.pdb

Thunderbird 45.4.0 Crash Report [@ OOM | small ]
bp-1b02b79e-3db1-4437-bc75-552e82161101     01/11/2016    13:08 NR

Thunderbird 45.3.0 Crash Report [@ OOM | small ]
bp-1ff40d2a-5d12-4d5c-bdc8-c557b2160930     30/09/2016    12:34 MAK
Jason, can you help find someone to investigate further? 
I'm not sure it helps for relman to track every possibly actionable OOM | small crash.
I'll test this in other browsers to see how they perform.
Flags: needinfo?(erahm)
Whiteboard: [MemShrink] → [MemShrink:P3]
I'm unable to reproduce this on 57 nightly. FWIW it doesn't repro in Chrome unstable (62.0.3198.0) either.
Status: NEW → RESOLVED
Closed: 4 years ago
Flags: needinfo?(erahm)
Resolution: --- → WORKSFORME
Flags: needinfo?(jorendorff)
You need to log in before you can comment on or make changes to this bug.