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

Status: RESOLVED WORKSFORME

(Core :: JavaScript Engine, defect)

Description

[Carsten Book [:Tomcat]]

Attachment: bughunter stack

Found via bughunter and reproduced on aurora opt build

Steps to reproduce:
-> Load http://m.premierinn.com/gb/en/home.html?&cid=KNC_Brn%257C_B_UK_UK_Eng_Enc_HVT-Premier-Inn_EX&mckv=iuouA7y6_dm%7Cpcrid%7C12569863411%7Ckword%7Cpremier%2520inn%7Cmatch%7Ce#/home/start
--> wait
--> Crash 

https://crash-stats.mozilla.com/report/index/9a6bc28f-a7b4-4660-bd22-10e712161014

Comment 1

[Marco Castelluccio [:marco]]

From the stack, it looks like the crash happened after timing out while running some JS script.
I can reproduce this locally.

Comment 2

[Carsten Book [:Tomcat]]

[Tracking Requested - why for this release]:
OOM affecting opt builds on a live website + reproduced by marco

Comment 3

[Marcia Knous [:marcia]]

Tracking 52+ - reproducible crash found by bughunter.

Comment 4

[Liz Henry (:lizzard) (relman/hg->git project)]

Marco does this affect 51? 
Jason can you help find someone to investigate?

Comment 5

[Marco Castelluccio [:marco]]

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).

Comment 6

[Gerry Chang [:gchang]]

Track 51+ as reproducible crash.

Comment 7

[Gerry Chang [:gchang]]

Hi Marco,
what about 51, is it easy to crash in 51?

Comment 8

[Marco Castelluccio [:marco]]

(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.

Comment 9

[Gerry Chang [:gchang]]

Hi kanru,
can you help shed some light here? Thanks.

Comment 10

[Kan-Ru Chen [:kanru] (UTC+9)]

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.

Comment 11

[Kan-Ru Chen [:kanru] (UTC+9)]

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.

Comment 12

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

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.

Comment 13

[Marco Castelluccio [:marco]]

(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.

Comment 14

[Kan-Ru Chen [:kanru] (UTC+9)]

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.

Comment 15

[Kan-Ru Chen [:kanru] (UTC+9)]

Attachment: DMD dump in cumulative mode

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)
  }
}
...

Comment 16

[Richard Leger]

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

Comment 17

[Liz Henry (:lizzard) (relman/hg->git project)]

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.

Comment 18

[Eric Rahm [:erahm]]

I'll test this in other browsers to see how they perform.

Comment 19

[Eric Rahm [:erahm]]

I'm unable to reproduce this on 57 nightly. FWIW it doesn't repro in Chrome unstable (62.0.3198.0) either.