Closed Bug 1593739 Opened 4 months ago Closed 3 months ago

Intermittent LeakSanitizer | leak at js_pod_arena_realloc, maybe_pod_arena_realloc, pod_arena_realloc, pod_realloc

Categories

(Core :: WebRTC: Audio/Video, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla72
Tracking Status
firefox-esr68 --- unaffected
firefox70 --- unaffected
firefox71 --- unaffected
firefox72 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: pehrsons)

References

(Regression)

Details

(Keywords: intermittent-failure, memory-leak, Whiteboard: [comment 28][stockwell disable-recommended])

Attachments

(2 files)

Filed by: dluca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=274407615&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/E3CV-KJWRDqCTmgfiknAwg/runs/0/artifacts/public/logs/live_backing.log


 INFO - GECKO(5993) | MEMORY STAT | vsize 20974871MB | residentFast 966MB
[task 2019-11-04T15:50:15.895Z] 15:50:15     INFO - TEST-OK | dom/media/test/test_mediatrack_events.html | took 2473ms
[task 2019-11-04T15:50:15.936Z] 15:50:15     INFO - TEST-START | dom/media/test/test_multiple_mediastreamtracks.html
[task 2019-11-04T15:50:16.099Z] 15:50:16     INFO - GECKO(5993) | [Parent 5993, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2019-11-04T15:50:16.099Z] 15:50:16     INFO - GECKO(5993) | (firefox:5993): Gtk-CRITICAL **: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2019-11-04T15:50:16.115Z] 15:50:16     INFO - GECKO(5993) | [Parent 5993, Main Thread] WARNING: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed: 'glib warning', file /builds/worker/workspace/build/src/toolkit/xre/nsSigHandlers.cpp, line 135
[task 2019-11-04T15:50:16.115Z] 15:50:16     INFO - GECKO(5993) | (firefox:5993): Gtk-CRITICAL **: gtk_widget_get_window: assertion 'GTK_IS_WIDGET (widget)' failed
[task 2019-11-04T15:50:16.171Z] 15:50:16     INFO - GECKO(5993) | MEMORY STAT | vsize 20974867MB | residentFast 962MB
[task 2019-11-04T15:50:16.191Z] 15:50:16     INFO - TEST-OK | dom/media/test/test_multiple_mediastreamtracks.html | took 255ms
[task 2019-11-04T15:50:16.268Z] 15:50:16     INFO - TEST-START | Shutdown
[task 2019-11-04T15:50:16.269Z] 15:50:16     INFO - Passed:  2214
[task 2019-11-04T15:50:16.269Z] 15:50:16     INFO - Failed:  0
[task 2019-11-04T15:50:16.269Z] 15:50:16     INFO - Todo:    3
[task 2019-11-04T15:50:16.269Z] 15:50:16     INFO - Mode:    e10s
[task 2019-11-04T15:50:16.270Z] 15:50:16     INFO - Slowest: 47374ms - /tests/dom/media/test/test_eme_playback.html
[task 2019-11-04T15:50:16.270Z] 15:50:16     INFO - SimpleTest FINISHED
[task 2019-11-04T15:50:16.270Z] 15:50:16     INFO - TEST-INFO | Ran 1 Loops
[task 2019-11-04T15:50:16.271Z] 15:50:16     INFO - SimpleTest FINISHED
[task 2019-11-04T15:50:16.598Z] 15:50:16     INFO - GECKO(5993) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-11-04T15:50:17.722Z] 15:50:17     INFO - GECKO(5993) | 1572882617717	Marionette	TRACE	Received observer notification xpcom-will-shutdown
[task 2019-11-04T15:50:17.723Z] 15:50:17     INFO - GECKO(5993) | 1572882617720	Marionette	INFO	Stopped listening on port 2828
[task 2019-11-04T15:50:17.724Z] 15:50:17     INFO - GECKO(5993) | 1572882617720	Marionette	DEBUG	Remote service is inactive
[task 2019-11-04T15:50:18.152Z] 15:50:18     INFO - GECKO(5993) | -----------------------------------------------------
[task 2019-11-04T15:50:18.153Z] 15:50:18     INFO - GECKO(5993) | Suppressions used:
[task 2019-11-04T15:50:18.154Z] 15:50:18     INFO - GECKO(5993) |   count      bytes template
[task 2019-11-04T15:50:18.155Z] 15:50:18     INFO - GECKO(5993) |      27        832 nsComponentManagerImpl
[task 2019-11-04T15:50:18.156Z] 15:50:18     INFO - GECKO(5993) |       2        288 libfontconfig.so
[task 2019-11-04T15:50:18.157Z] 15:50:18     INFO - GECKO(5993) | -----------------------------------------------------
[task 2019-11-04T15:50:18.319Z] 15:50:18     INFO - GECKO(5993) | -----------------------------------------------------
[task 2019-11-04T15:50:18.320Z] 15:50:18     INFO - GECKO(5993) | Suppressions used:
[task 2019-11-04T15:50:18.320Z] 15:50:18     INFO - GECKO(5993) |   count      bytes template
[task 2019-11-04T15:50:18.321Z] 15:50:18     INFO - GECKO(5993) |      27        832 nsComponentManagerImpl
[task 2019-11-04T15:50:18.322Z] 15:50:18     INFO - GECKO(5993) |     611      17713 libfontconfig.so
[task 2019-11-04T15:50:18.322Z] 15:50:18     INFO - GECKO(5993) |       1         29 libglib-2.0.so
[task 2019-11-04T15:50:18.323Z] 15:50:18     INFO - GECKO(5993) | -----------------------------------------------------
[task 2019-11-04T15:50:19.130Z] 15:50:19     INFO - GECKO(5993) | -----------------------------------------------------
[task 2019-11-04T15:50:19.130Z] 15:50:19     INFO - GECKO(5993) | Suppressions used:
[task 2019-11-04T15:50:19.130Z] 15:50:19     INFO - GECKO(5993) |   count      bytes template
[task 2019-11-04T15:50:19.130Z] 15:50:19     INFO - GECKO(5993) |       1         32 nsComponentManagerImpl
[task 2019-11-04T15:50:19.130Z] 15:50:19     INFO - GECKO(5993) | -----------------------------------------------------
[task 2019-11-04T15:50:25.826Z] 15:50:25     INFO - GECKO(5993) | ==6040==WARNING: Symbolizer buffer too small
[task 2019-11-04T15:50:25.827Z] 15:50:25     INFO - GECKO(5993) | ==6040==WARNING: Symbolizer buffer too small
[task 2019-11-04T15:50:25.834Z] 15:50:25     INFO - GECKO(5993) | ==6040==WARNING: Symbolizer buffer too small
[task 2019-11-04T15:50:28.506Z] 15:50:28     INFO - GECKO(5993) | ==6040==WARNING: Symbolizer buffer too small
[task 2019-11-04T15:50:36.194Z] 15:50:36     INFO - GECKO(5993) | =================================================================
[task 2019-11-04T15:50:36.196Z] 15:50:36    ERROR - GECKO(5993) | ==6040==ERROR: LeakSanitizer: detected memory leaks
[task 2019-11-04T15:50:36.196Z] 15:50:36     INFO - GECKO(5993) | Direct leak of 7072 byte(s) in 166 object(s) allocated from:
[task 2019-11-04T15:50:36.197Z] 15:50:36     INFO - GECKO(5993) |     #0 0x56290b3f1cdd in malloc /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_malloc_linux.cc:145:3
[task 2019-11-04T15:50:36.197Z] 15:50:36     INFO - GECKO(5993) |     #1 0x7fcab2881ec7 in js_arena_malloc /builds/worker/workspace/build/src/obj-firefox/dist/include/js/Utility.h:392:10
[task 2019-11-04T15:50:36.198Z] 15:50:36     INFO - GECKO(5993) |     #2 0x7fcab2881ec7 in js_pod_arena_malloc<unsigned char> /builds/worker/workspace/build/src/obj-firefox/dist/include/js/Utility.h:600:26
[task 2019-11-04T15:50:36.198Z] 15:50:36     INFO - GECKO(5993) |     #3 0x7fcab2881ec7 in maybe_pod_arena_malloc<unsigned char> /builds/worker/workspace/build/src/js/src/vm/MallocProvider.h:53:12
[task 2019-11-04T15:50:36.198Z] 15:50:36     INFO - GECKO(5993) |     #4 0x7fcab2881ec7 in pod_arena_malloc<unsigned char> /builds/worker/workspace/build/src/js/src/vm/MallocProvider.h:105:12
[task 2019-11-04T15:50:36.199Z] 15:50:36     INFO - GECKO(5993) |     #5 0x7fcab2881ec7 in unsigned char* js::MallocProvider<JSContext>::pod_malloc<unsigned char>(unsigned long) /builds/worker/workspace/build/src/js/src/vm/MallocProvider.h:123:12
[task 2019-11-04T15:50:36.200Z] 15:50:36     INFO - GECKO(5993) |     #6 0x7fcab2861a2e in NewEmptyScopeData<js::FunctionScope> /builds/worker/workspace/build/src/js/src/vm/Scope.cpp:211:24
[task 2019-11-04T15:50:36.200Z] 15:50:36     INFO - GECKO(5993) |     #7 0x7fcab2861a2e in mozilla::Result<mozilla::Ok, JS::TranscodeResult> js::Scope::XDRSizedBindingNames<js::FunctionScope, (js::XDRMode)1>(js::XDRState<(js::XDRMode)1>*, JS::Handle<js::FunctionScope*>, JS::MutableHandle<js::FunctionScope::Data*>) /builds/worker/workspace/build/src/js/src/vm/Scope.cpp:287:14
[task 2019-11-04T15:50:36.200Z] 15:50:36     INFO - GECKO(5993) |     #8 0x7fcab2860e47 in mozilla::Result<mozilla::Ok, JS::TranscodeResult> js::FunctionScope::XDR<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>*, JS::Handle<JSFunction*>, JS::Handle<js::Scope*>, JS::MutableHandle<js::Scope*>) /builds/worker/workspace/build/src/js/src/vm/Scope.cpp:777:3
[task 2019-11-04T15:50:36.201Z] 15:50:36     INFO - GECKO(5993) |     #9 0x7fcab271ec3f in XDRScope<js::XDR_DECODE> /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:513:7
[task 2019-11-04T15:50:36.201Z] 15:50:36     INFO - GECKO(5993) |     #10 0x7fcab271ec3f in XDRScriptGCThing<js::XDR_DECODE> /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:598:7
[task 2019-11-04T15:50:36.207Z] 15:50:36     INFO - GECKO(5993) |     #11 0x7fcab271ec3f in mozilla::Result<mozilla::Ok, JS::TranscodeResult> js::PrivateScriptData::XDR<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>*, JS::Handle<JSScript*>, JS::Handle<js::ScriptSourceObject*>, JS::Handle<js::Scope*>, JS::Handle<JSFunction*>) /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:664:5
[task 2019-11-04T15:50:36.208Z] 15:50:36     INFO - GECKO(5993) |     #12 0x7fcab26a48c9 in mozilla::Result<mozilla::Ok, JS::TranscodeResult> js::XDRScript<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>*, JS::Handle<js::Scope*>, JS::Handle<js::ScriptSourceObject*>, JS::Handle<JSFunction*>, JS::MutableHandle<JSScript*>) /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:1183:3
[task 2019-11-04T15:50:36.208Z] 15:50:36     INFO - GECKO(5993) |     #13 0x7fcab26a14c5 in mozilla::Result<mozilla::Ok, JS::TranscodeResult> js::XDRInterpretedFunction<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>*, JS::Handle<js::Scope*>, JS::Handle<js::ScriptSourceObject*>, JS::MutableHandle<JSFunction*>) /builds/worker/workspace/build/src/js/src/vm/JSFunction.cpp:627:5
[task 2019-11-04T15:50:36.210Z] 15:50:36     INFO - GECKO(5993) |     #14 0x7fcab27628cd in mozilla::Result<mozilla::Ok, JS::TranscodeResult> XDRInnerObject<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>*, js::PrivateScriptData*, JS::Handle<js::ScriptSourceObject*>, JS::MutableHandle<JSObject*>) /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:444:7
[task 2019-11-04T15:50:36.210Z] 15:50:36     INFO - GECKO(5993) |     #15 0x7fcab271e776 in XDRScriptGCThing<js::XDR_DECODE> /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:587:7
[task 2019-11-04T15:50:36.211Z] 15:50:36     INFO - GECKO(5993) |     #16 0x7fcab271e776 in mozilla::Result<mozilla::Ok, JS::TranscodeResult> js::PrivateScriptData::XDR<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>*, JS::Handle<JSScript*>, JS::Handle<js::ScriptSourceObject*>, JS::Handle<js::Scope*>, JS::Handle<JSFunction*>) /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:664:5
[task 2019-11-04T15:50:36.211Z] 15:50:36     INFO - GECKO(5993) |     #17 0x7fcab26a48c9 in mozilla::Result<mozilla::Ok, JS::TranscodeResult> js::XDRScript<(js::XDRMode)1>(js::XDRState<(js::XDRMode)1>*, JS::Handle<js::Scope*>, JS::Handle<js::ScriptSourceObject*>, JS::Handle<JSFunction*>, JS::MutableHandle<JSScript*>) /builds/worker/workspace/build/src/js/src/vm/JSScript.cpp:1183:3
[task 2019-11-04T15:50:36.212Z] 15:50:36     INFO - GECKO(5993) |     #18 0x7fcab2ae1d86 in js::XDRState<(js::XDRMode)1>::codeScript(JS::MutableHandle<JSScript*>) /builds/worker/workspace/build/src/js/src/vm/Xdr.cpp:269:3
[task 2019-11-04T15:50:36.212Z] 15:50:36     INFO - GECKO(5993) |     #19 0x7fcab2502d17 in js::MultiScriptsDecodeTask::parse(JSContext*) /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:725:29
[task 2019-11-04T15:50:36.213Z] 15:50:36     INFO - GECKO(5993) |     #20 0x7fcab2500cd6 in js::ParseTask::runTask() /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:562:3
[task 2019-11-04T15:50:36.214Z] 15:50:36     INFO - GECKO(5993) |     #21 0x7fcab2514060 in js::HelperThread::handleParseWorkload(js::AutoLockHelperThreadState&) /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:2352:11
[task 2019-11-04T15:50:36.215Z] 15:50:36     INFO - GECKO(5993) |     #22 0x7fcab2511e11 in js::HelperThread::threadLoop() /builds/worker/workspace/build/src/js/src/vm/HelperThreads.cpp:2644:5
[task 2019-11-04T15:50:36.216Z] 15:50:36     INFO - GECKO(5993) |     #23 0x7fcab258c687 in callMain<0> /builds/worker/workspace/build/src/js/src/threading/Thread.h:210:5
[task 2019-11-04T15:50:36.216Z] 15:50:36     INFO - GECKO(5993) |     #24 0x7fcab258c687 in js::detail::ThreadTrampoline<void (&)(void*), js::HelperThread*>::Start(void*) /builds/worker/workspace/build/src/js/src/threading/Thread.h:199:11
[task 2019-11-04T15:50:36.217Z] 15:50:36     INFO - GECKO(5993) |     #25 0x7fcac802f6b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)
[task 2019-11-04T15:50:36.218Z] 15:50:36     INFO - GECKO(5993) | Direct leak of 5708 byte(s) in 204 object(s) allocated from:
[task 2019-11-04T15:50:36.219Z] 15:50:36     INFO - GECKO(5993) |     #0 0x56290b3f1cdd in malloc /builds/worker/fetches/llvm-project/llvm/projects/compiler-rt/lib/asan/asan_malloc_linux.cc:145:3
[task 2019-11-04T15:50:36.220Z] 15:50:36     INFO - GECKO(5993) |     #1 0x7fcab29290b2 in js_arena_malloc /builds/worker/workspace/build/src/obj-firefox/dist/include/js/Utility.h:392:10
[task 2019-11-04T15:50:36.221Z] 15:50:36     INFO - GECKO(5993) |     #2 0x7fcab29290b2 in js_pod_arena_malloc<unsigned char> /builds/worker/workspace/build/src/obj-firefox/dist/include/js/Utility.h:600:26
[task 2019-11-04T15:50:36.222Z] 15:50:36     INFO - GECKO(5993) |     #3 0x7fcab29290b2 in maybe_pod_arena_malloc<unsigned char> /builds/worker/workspace/build/src/js/src/vm/MallocProvider.h:53:12
[task 2019-11-04T15:50:36.224Z] 15:50:36     INFO - GECKO(5993) |     #4 0x7fcab29290b2 in pod_arena_malloc<unsigned char> /builds/worker/workspace/build/src/js/src/vm/MallocProvider.h:105:12
[task 2019-11-04T15:50:36.225Z] 15:50:36     INFO - GECKO(5993) |     #5 0x7fcab29290b2 in make_pod_arena_array<unsigned char> /builds/worker/workspace/build/src/js/src/vm/MallocProvider.h:149:43
[task 2019-11-04T15:50:36.226Z] 15:50:36     INFO - GECKO(5993) |     #6 0x7fcab29290b2 in JSLinearString* js::NewStringCopyNDontDeflate<(js::AllowGC)0, unsigned char>(JSContext*, unsigned char const*, unsigned long) /builds/worker/workspace/build/src/js/src/vm/StringType.cpp:1736:19
[task 2019-11-04T15:50:36.227Z] 15:50:36     INFO - GECKO(5993) |     #7 0x7fcab254f20e in MakeLinearStringForAtomization<unsigned char> /builds/worker/workspace/build/src/js/src/vm/JSAtom.cpp:883:10
[task 2019-11-04T15:50:36.228Z] 15:50:36     INFO - GECKO(5993) |     #8 0x7fcab254f20e in AllocateNewAtom<const unsigned char *> /builds/worker/workspace/build/src/js/src/vm/JSAtom.cpp:946:28
[task 2019-11-04T15:50:36.229Z] 15:50:36     INFO - GECKO(5993) |     #9 0x7fcab254f20e in atomizeAndCopyChars<const unsigned char *> /builds/worker/workspace/build/src/js/src/vm/JSAtom.cpp:797:18
[task 2019-11-04T15:50:36.230Z] 15:50:36     INFO - GECKO(5993) |     #10 0x7fcab254f20e in AtomizeAndCopyCharsFromLookup<const unsigned char *> /builds/worker/workspace/build/src/js/src/vm/JSAtom.cpp:724:30
[task 2019-11-04T15:50:36.231Z] 15:50:36     INFO - GECKO(5993) |     #11 0x7fcab254f20e in AtomizeAndCopyChars<unsigned char> /builds/worker/workspace/build/src/js/src/vm/JSAtom.cpp:825:10
[task 2019-11-04T15:50:36.232Z] 15:50:36     INFO - GECKO(5993) |     #12 0x7fcab254f20e in JSAtom* js::AtomizeChars<unsigned char>(JSContext*, unsigned char const*, unsigned long, js::PinningBehavior) /builds/worker/workspace/build/src/js/src/vm/JSAtom.cpp:1030:10
[task 2019-11-04T15:50:36.232Z] 15:50:36     INFO - GECKO(5993) |     #13 0x7fcab23d1895 in js::StringBuffer::finishAtom() /builds/worker/workspace/build/src/js/src/util/StringBuffer.cpp:129:20
[task 2019-11-04T15:50:36.233Z] 15:50:36     INFO - GECKO(5993) |     #14 0x7fcab26c19dd in NameToFunctionName(JSContext*, JS::Handle<JS::Value>, FunctionPrefixKind) /builds/worker/workspace/build/src/js/src/vm/JSFunction.cpp:2418:13
[task 2019-11-04T15:50:36.234Z] 15:50:36     INFO - GECKO(5993) |     #15 0x7fcab26c0de5 in js::IdToFunctionName(JSContext*, JS::Handle<JS::PropertyKey>, FunctionPrefixKind) /builds/worker/workspace/build/src/js/src/vm/JSFunction.cpp:2450:10
[task 2019-11-04T15:50:36.235Z] 15:50:36     INFO - GECKO(5993) |     #16 0x7fcab22da1d7 in DefineAccessorPropertyById(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::PropertyKey>, JSNativeWrapper const&, JSNativeWrapper const&, unsigned int) /builds/worker/workspace/build/src/js/src/jsapi.cpp:2017:25
[task 2019-11-04T15:50:36.236Z] 15:50:36     INFO - GECKO(5993) |     #17 0x7fcab22ebae0 in JS_DefineProperties(JSContext*, JS::Handle<JSObject*>, JSPropertySpec const*) /builds/worker/workspace/build/src/js/src/jsapi.cpp:3031:14
[task 2019-11-04T15:50:36.237Z] 15:50:36     INFO - GECKO(5993) |     #18 0x7fcaab863d33 in Define /builds/worker/workspace/build/src/dom/bindings/BindingUtils.cpp:645:10
[task 2019-11-04T15:50:36.238Z] 15:50:36     INFO - GECKO(5993) |     #19 0x7fcaab863d33 in DefinePrefable<const JSPropertySpec> /builds/worker/workspace/build/src/dom/bindings/BindingUtils.cpp:660:12
[task 2019-11-04T15:50:36.238Z] 15:50:36     INFO - GECKO(5993) |     #20 0x7fcaab863d33 in mozilla::dom::DefineProperties(JSContext*, JS::Handle<JSObject*>, mozilla::dom::NativePropertiesN<7> const*, mozilla::dom::NativePropertiesN<7> const*) /builds/worker/workspace/build/src/dom/bindings/BindingUtils.cpp:929:10
[task 2019-11-04T15:50:36.239Z] 15:50:36     INFO - GECKO(5993) |     #21 0x7fcaab864ac8 in CreateInterfacePrototypeObject /builds/worker/workspace/build/src/dom/bindings/BindingUtils.cpp:874:9
[task 2019-11-04T15:50:36.240Z] 15:50:36     INFO - GECKO(5993) |     #22 0x7fcaab864ac8 in mozilla::dom::CreateInterfaceObjects(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSObject*>, JSClass const*, JS::Heap<JSObject*>*, char const*, JS::Handle<JSObject*>, JSClass const*, unsigned int, mozilla::dom::NamedConstructor const*, JS::Heap<JSObject*>*, mozilla::dom::NativePropertiesN<7> const*, mozilla::dom::NativePropertiesN<7> const*, char const*, bool, char const* const*, bool, char const* const*) /builds/worker/workspace/build/src/dom/bindings/BindingUtils.cpp:1002:13
[task 2019-11-04T15:50:36.241Z] 15:50:36     INFO - GECKO(5993) |     #23 0x7fcaa97bcd72 in mozilla::dom::CSS2Properties_Binding::CreateInterfaceObjects(JSContext*, JS::Handle<JSObject*>, mozilla::dom::ProtoAndIfaceCache&, bool) /builds/worker/workspace/build/src/obj-firefox/dom/bindings/CSS2PropertiesBinding.cpp:55624:3
[task 2019-11-04T15:50:36.242Z] 15:50:36     INFO - GECKO(5993) |     #24 0x7fcaab87b5c2 in mozilla::dom::GetPerInterfaceObjectHandle(JSContext*, unsigned long, void (*)(JSContext*, JS::Handle<JSObject*>, mozilla::dom::ProtoAndIfaceCache&, bool), bool) /builds/worker/workspace/build/src/dom/bindings/BindingUtils.cpp:4131:5
[task 2019-11-04T15:50:36.243Z] 15:50:36     INFO - GECKO(5993) |     #25 0x7fcaa97bbcb8 in GetProtoObjectHandle /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/dom/CSS2PropertiesBinding.h:59:12
[task 2019-11-04T15:50:36.244Z] 15:50:36     INFO - GECKO(5993) |     #26 0x7fcaa97bbcb8 in mozilla::dom::CSS2Properties_Binding::Wrap(JSContext*, nsDOMCSSDeclaration*, nsWrapperCache*, JS::Handle<JSObject*>, JS::MutableHandle<JSObject*>) /builds/worker/workspace/build/src/obj-firefox/dom/bindings/CSS2PropertiesBinding.cpp:55533:42
[task 2019-11-04T15:50:36.245Z] 15:50:36     INFO - GECKO(5993) |     #27 0x7fcaae4d462d in Wrap<nsDOMCSSDeclaration> /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/dom/CSS2PropertiesBinding.h:40:12
[task 2019-11-04T15:50:36.246Z] 15:50:36     INFO - GECKO(5993) |     #28 0x7fcaae4d462d in WrapObject /builds/worker/workspace/build/src/layout/style/nsDOMCSSDeclaration.cpp:32:10
[task 2019-11-04T15:50:36.247Z] 15:50:36     INFO - GECKO(5993) |     #29 0x7fcaae4d462d in non-virtual thunk to nsDOMCSSDeclaration::WrapObject(JSContext*, JS::Handle<JSObject*>) /builds/worker/workspace/build/src/layout/style/nsDOMCSSDeclaration.cpp
[task 2019-11-04T15:50:36.247Z] 15:50:36     INFO - GECKO(5993) |     #30 0x7fcaab4c1e49 in DoGetOrCreateDOMReflector<nsICSSDeclaration, mozilla::dom::binding_detail::eWrapIntoContextCompartment> /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/dom/BindingUtils.h:1050:18
[task 2019-11-04T15:50:36.248Z] 15:50:36     INFO - GECKO(5993) |     #31 0x7fcaab4c1e49 in GetOrCreateDOMReflector<nsICSSDeclaration> /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/dom/BindingUtils.h:1116:10
[task 2019-11-04T15:50:36.249Z] 15:50:36     INFO - GECKO(5993) |     #32 0x7fcaab4c1e49 in mozilla::dom::HTMLElement_Binding::get_style(JSContext*, JS::Handle<JSObject*>, nsGenericHTMLElement*, JSJitGetterCallArgs) /builds/worker/workspace/build/src/obj-firefox/dom/bindings/HTMLElementBinding.cpp:1325:8
[task 2019-11-04T15:50:36.250Z] 15:50:36     INFO - GECKO(5993) |     #33 0x7fcaab8536d5 in bool mozilla::dom::binding_detail::GenericGetter<mozilla::dom::binding_detail::NormalThisPolicy, mozilla::dom::binding_detail::ThrowExceptions>(JSContext*, unsigned int, JS::Value*) /builds/worker/workspace/build/src/dom/bindings/BindingUtils.cpp:3100:13
[task 2019-11-04T15:50:36.250Z] 15:50:36     INFO - GECKO(5993) |     #34 0x7fcab20fd0f9 in CallJSNative /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:456:13
[task 2019-11-04T15:50:36.251Z] 15:50:36     INFO - GECKO(5993) |     #35 0x7fcab20fd0f9 in js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:548:12
[task 2019-11-04T15:50:36.252Z] 15:50:36     INFO - GECKO(5993) |     #36 0x7fcab2102b55 in InternalCall /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:617:10
[task 2019-11-04T15:50:36.252Z] 15:50:36     INFO - GECKO(5993) |     #37 0x7fcab2102b55 in Call /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:634:8
[task 2019-11-04T15:50:36.252Z] 15:50:36     INFO - GECKO(5993) |     #38 0x7fcab2102b55 in js::CallGetter(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:758:10
[task 2019-11-04T15:50:36.254Z] 15:50:36     INFO - GECKO(5993) |     #39 0x7fcab27a6c87 in CallGetter /builds/worker/workspace/build/src/js/src/vm/NativeObject.cpp:2279:12
[task 2019-11-04T15:50:36.254Z] 15:50:36     INFO - GECKO(5993) |     #40 0x7fcab27a6c87 in GetExistingProperty<js::CanGC> /builds/worker/workspace/build/src/js/src/vm/NativeObject.cpp:2331:10
[task 2019-11-04T15:50:36.254Z] 15:50:36     INFO - GECKO(5993) |     #41 0x7fcab27a6c87 in NativeGetPropertyInline<js::CanGC> /builds/worker/workspace/build/src/js/src/vm/NativeObject.cpp:2591:14
[task 2019-11-04T15:50:36.254Z] 15:50:36     INFO - GECKO(5993) |     #42 0x7fcab27a6c87 in js::NativeGetProperty(JSContext*, JS::Handle<js::NativeObject*>, JS::Handle<JS::Value>, JS::Handle<JS::PropertyKey>, JS::MutableHandle<JS::Value>) /builds/worker/workspace/build/src/js/src/vm/NativeObject.cpp:2628:10
[task 2019-11-04T15:50:36.254Z] 15:50:36     INFO - GECKO(5993) |     #43 0x7fcab210adf1 in GetProperty /builds/worker/workspace/build/src/js/src/vm/ObjectOperations-inl.h:117:10
[task 2019-11-04T15:50:36.254Z] 15:50:36     INFO - GECKO(5993) |     #44 0x7fcab210adf1 in GetProperty /builds/worker/workspace/build/src/js/src/vm/ObjectOperations-inl.h:124:10
[task 2019-11-04T15:50:36.254Z] 15:50:36     INFO - GECKO(5993) |     #45 0x7fcab210adf1 in js::GetProperty(JSContext*, JS::Handle<JS::Value>, JS::Handle<js::PropertyName*>, JS::MutableHandle<JS::Value>) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:4539:10
[task 2019-11-04T15:50:36.254Z] 15:50:36     INFO - GECKO(5993) |     #46 0x7fcab20e6329 in GetPropertyOperation /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:218:10
[task 2019-11-04T15:50:36.254Z] 15:50:36     INFO - GECKO(5993) |     #47 0x7fcab20e6329 in Interpret(JSContext*, js::RunState&) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:2795:12
[task 2019-11-04T15:50:36.255Z] 15:50:36     INFO - GECKO(5993) |     #48 0x7fcab20c7f64 in js::RunScript(JSContext*, js::RunState&) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:423:10
[task 2019-11-04T15:50:36.255Z] 15:50:36     INFO - GECKO(5993) |     #49 0x7fcab2103aef in js::ExecuteKernel(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value const&, js::AbstractFramePtr, JS::Value*) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:810:13
[task 2019-11-04T15:50:36.255Z] 15:50:36     INFO - GECKO(5993) |     #50 0x7fcab21042bf in js::Execute(JSContext*, JS::Handle<JSScript*>, JSObject&, JS::Value*) /builds/worker/workspace/build/src/js/src/vm/Interpreter.cpp:843:10
[task 2019-11-04T15:50:36.255Z] 15:50:36     INFO - GECKO(5993) |     #51 0x7fcab247a96e in ExecuteScript(JSContext*, JS::Handle<JS::StackGCVector<JSObject*, js::TempAllocPolicy> >, JS::Handle<JSScript*>, JS::Value*) /builds/worker/workspace/build/src/js/src/vm/CompilationAndEvaluation.cpp:473:10
[task 2019-11-04T15:50:36.255Z] 15:50:36     INFO - GECKO(5993) |     #52 0x7fcaa95dd285 in nsJSUtils::ExecutionContext::ExecScript() /builds/worker/workspace/build/src/dom/base/nsJSUtils.cpp:416:8
[task 2019-11-04T15:50:36.255Z] 15:50:36     INFO - GECKO(5993) |     #53 0x7fcaadc1ecfa in mozilla::dom::ExecuteCompiledScript(JSContext*, mozilla::dom::ScriptLoadRequest*, nsJSUtils::ExecutionContext&) /builds/worker/workspace/build/src/dom/script/ScriptLoader.cpp:2610:16
[task 2019-11-04T15:50:36.255Z] 15:50:36     INFO - GECKO(5993) |     #54 0x7fcaadc1c0b4 in mozilla::dom::ScriptLoader::EvaluateScript(mozilla::dom::ScriptLoadRequest*) /builds/worker/workspace/build/src/dom/script/ScriptLoader.cpp:2834:20
[task 2019-11-04T15:50:36.271Z] 15:50:36     INFO - GECKO(5993) |     #55 0x7fcaadc152fd in mozilla::dom::ScriptLoader::ProcessRequest(mozilla::dom::ScriptLoadRequest*) /builds/worker/workspace/build/src/dom/script/ScriptLoader.cpp:2309:10
[task 2019-11-04T15:50:36.271Z] 15:50:36     INFO - GECKO(5993) |     #56 0x7fcaadc0fef4 in mozilla::dom::ScriptLoader::ProcessExternalScript(nsIScriptElement*, mozilla::dom::ScriptKind, nsTAutoStringN<char16_t, 64ul>, nsIContent*) /builds/worker/workspace/build/src/dom/script/ScriptLoader.cpp:1739:14
[task 2019-11-04T15:50:36.272Z] 15:50:36     INFO - GECKO(5993) | Direct leak of 5708 byte(s) in 204 object(s) allocated from:

Andreas: Can you please take a look at this bug?

I think it might be a regression from Bug 1577505

Flags: needinfo?(apehrson)
Regressed by: 1577505

If I were to throw a wild guess out there I'd suspect some timeupdate elements being dispatched late, or some such. A few of the leaks had allocation stacks with HTMLMediaElement::DispatchEvent and HTMLCanvasElement::GetContext in them. It looks very fun to debug this...

Assignee: nobody → apehrson
Status: NEW → ASSIGNED
Flags: needinfo?(apehrson)

Bug 1473183 is the debug version of this. I'll try further in debug to see if I can figure out the classes the leak checker thinks we're leaking. That has helped in the past.

See Also: → 1473183

We could look at the tips for tracking down a leak linked to bug 1583955.

See Also: → 1583955

I checked the DOMWINDOW logs and for the leaking process there are 5 windows hanging around. 3 inner and 2 outer. One inner-outer pair are created close to process startup. For the other outer there is one inner created right after the start of dom/media/test/test_mediatrack_events.html and one at shutdown.

I'll try to focus on dom/media/test/test_mediatrack_events.html here.

With that test disabled we are no longer leaking: https://treeherder.mozilla.org/#/jobs?repo=try&revision=06e3bde274a2d9617a759886b21f1bd3d7dd6297
And for reproducing, the good news is it can be found with test-verify on only this test (rate is similar or slightly higher compared to mda1): https://treeherder.mozilla.org/#/jobs?repo=try&revision=e5b44b07817439e5007a6390f997873d8c001127

I haven't had success locally so far though.

Following the brief instructions in bug 1567448 comment 42 and the linked mdn page, I got cc-logging and dmd hooked up in automation with the mochitest test-verify job. I'll attach the patch that achieved this later.

The repro rate was not affected.

So far I have the root from the cc log figured out:

pehrsons@pehrsons-X299:~/dev/leaks/dmd-on-try/1$ python ~/dev/heapgraph/find_roots.py ./cc-edges.2588-1.log 0x7f0140bd3400
Parsing ./cc-edges.2588-1.log. Done loading graph.

0x7f0140fd7760 [nsNodeInfoManager]
--[mDocument]--> 0x7f013e6df000 [Document normal (xhtml) https://example.com/tests/dom/media/test/test_mediatrack_events.html]
--[Preserved wrapper]--> 0x20530f3c72e0 [JS Object (HTMLDocument)]
--[group_global]--> 0x20530f3ad100 [JS Object (Window)]
--[UnwrapDOMObject(obj)]--> 0x7f0140bd3400 [nsGlobalWindowInner # 4294967343 inner https://example.com/tests/dom/media/test/test_mediatrack_events.html]

Root 0x7f0140fd7760 is a ref counted object with 1 unknown edge(s).
known edges:
   0x7f0141a9a300 [NodeInfo (xhtml) title] --[mOwnerManager]--> 0x7f0140fd7760
   0x7f014144c980 [NodeInfo ([none]) #document] --[mOwnerManager]--> 0x7f0140fd7760
   0x7f0140b30500 [NodeInfo (xhtml) iframe] --[mOwnerManager]--> 0x7f0140fd7760
   0x7f0141943680 [NodeInfo (xhtml) head] --[mOwnerManager]--> 0x7f0140fd7760
   0x7f01416c9c00 [NodeInfo (xhtml) body] --[mOwnerManager]--> 0x7f0140fd7760
   0x7f0141a9ab80 [NodeInfo (xhtml) script] --[mOwnerManager]--> 0x7f0140fd7760
   0x7f0141942500 [NodeInfo ([none]) #document-type] --[mOwnerManager]--> 0x7f0140fd7760
   0x7f01419a3500 [NodeInfo (xhtml) html] --[mOwnerManager]--> 0x7f0140fd7760
   0x7f0141a9a200 [NodeInfo ([none]) #text] --[mOwnerManager]--> 0x7f0140fd7760
   0x7f0142153900 [NodeInfo (xhtml) link] --[mOwnerManager]--> 0x7f0140fd7760
   0x7f0142077380 [NodeInfo (xhtml) pre] --[mOwnerManager]--> 0x7f0140fd7760

I'm continuing per the mdn page to figure out the unknown edge.

Per DMD, the unknown edge is:

0x7f013e6df000 size = 3224 bytes at byte offset 512  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                               
  moz_xmalloc [memory/mozalloc/mozalloc.cpp:53]                                                                                                                                                                    
  NS_NewHTMLDocument(mozilla::dom::Document**, bool) [dom/html/nsHTMLDocument.cpp:131]                                                                                                                             
  nsContentDLF::CreateInstance(char const*, nsIChannel*, nsILoadGroup*, nsTSubstring<char> const&, nsIDocShell*, nsISupports*, nsIStreamListener**,                                                                
  nsContentDLF::CreateDocument(char const*, nsIChannel*, nsILoadGroup*, nsIDocShell*, already_AddRefed<mozilla::dom::Document> (*)(), nsIStreamList                                                                
  nsContentDLF::CreateInstance(char const*, nsIChannel*, nsILoadGroup*, nsTSubstring<char> const&, nsIDocShell*, nsISupports*, nsIStreamListener**,                                                                
  nsDocShell::NewContentViewerObj(nsTSubstring<char> const&, nsIRequest*, nsILoadGroup*, nsIStreamListener**, nsIContentViewer**) [docshell/base/ns                                                                
  nsDocShell::CreateContentViewer(nsTSubstring<char> const&, nsIRequest*, nsIStreamListener**) [docshell/base/nsDocShell.cpp:7807]

And this object was also held by the nsNodeInfoManager:

--[mDocument]--> 0x7f013e6df000 [Document normal (xhtml) https://example.com/tests/dom/media/test/test_mediatrack_events.html]

Unsure what to make of this so far.

Comment 16 means that the reference is from an nsHTMLDocument. However, nsHTMLDocument::mInfoManager is actually a weak reference, so I think it can't be holding the info manager alive. If there are really no heap references to the nsNodeInfoManager that don't also appear in the known edges list (and I'd double check that before going any further), then the only thing I can think of is there might be some refcounting error for the node info manager. That would be a little surprising, though, because the info manager stuff is pretty standard and hidden away from most DOM code, so I wouldn't think you could end up with errors there.

What I would have guessed based only on comment 15 is that there's some DOM node that is leaking the info manager via its node info, because I think node infos are the only things that hold strong refs to the node info manager, and nodes are the only thing that hold strong refs to node infos. But comment 16 indicates that might not be the case.

Well, here's the patch to get the logs going on try for mochitest. Might be useful.

I'll note that when symbolicating the DMD logs (with the help of BREAKPAD_SYMBOLS_PATH) there were two libxul.so in the crashreporter_symbols tarball, and because fileid wasn't packaged with the build from try it couldn't figure out which to use. I ran block_analyzer.py on both and only one of them gave me stacks that made sense...

(In reply to Andrew McCreight [:mccr8] from comment #17)

Comment 16 means that the reference is from an nsHTMLDocument. However, nsHTMLDocument::mInfoManager is actually a weak reference, so I think it can't be holding the info manager alive. If there are really no heap references to the nsNodeInfoManager that don't also appear in the known edges list (and I'd double check that before going any further), then the only thing I can think of is there might be some refcounting error for the node info manager. That would be a little surprising, though, because the info manager stuff is pretty standard and hidden away from most DOM code, so I wouldn't think you could end up with errors there.

What I would have guessed based only on comment 15 is that there's some DOM node that is leaking the info manager via its node info, because I think node infos are the only things that hold strong refs to the node info manager, and nodes are the only thing that hold strong refs to node infos. But comment 16 indicates that might not be the case.

Thanks for the input.

I've noted this weak reference as well and confirmed that the document that DMD is pointing out also has a known strong ref through mNodeInfo:

0x7f0140fd7760 [nsNodeInfoManager]
    --[mDocument]--> 0x7f013e6df000 [Document normal (xhtml) https://example.com/tests/dom/media/test/test_mediatrack_events.html]
    --[mNodeInfo]--> 0x7f014144c980 [NodeInfo ([none]) #document]

--[mNodeInfo]--> 0x7f014144c980 [NodeInfo ([none]) #document] is seen in comment 15 as a known edge.

DMD points out exactly the 11 known edges from comment 15, and the weak ref in comment 16. Here's the output from block_analyzer.py on 0x7f0140fd7760 (stacks removed):

  1 0x7f0141a9ab80 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                             
  2 0x7f0140b30500 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                             
  3 0x7f0142077380 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                             
  4 0x7f013e6df000 size = 3224 bytes at byte offset 512  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                           
  5 0x7f0141942500 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                             
  6 0x7f014144c980 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                             
  7 0x7f01419a3500 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                             
  8 0x7f0142153900 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                             
  9 0x7f0141a9a200 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                             
 10 0x7f01416c9c00 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                             
 11 0x7f0141943680 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]                                                                                             
 12 0x7f0141a9a300 size = 128 bytes at byte offset 72  replace_malloc(unsigned long) [memory/replace/dmd/DMD.cpp:1071]

Olli, do you have any ideas? This leak sounds pretty odd.

Flags: needinfo?(bugs)

I'm not sure how useful it will be but it does appear that we caught this in Pernosco.

https://pernos.co/debug/nR83VsAZNGlNzqEtWjDFtw/index.html

Soooo, that was a fun exercise.

To crack this (I went down the wrong nsNodeInfoManager at first) I copied the NodePool's internal state as it got cleared after CC shutdown.

With a minor vim exercise I then eliminated all GCed objects (refcount 0) and those that had matching mInternalRefs to mRefCount (expected). Left were 4 objects:

[161] = { mPointer=0x7f0cffe9d040, mParticipant=0x7f0d1060d018《::BrowsingContext::_cycleCollectorGlobal》, mColor=0, mInternalRefs=1, mRefCount=3, mFirstChild.mPointer=0x7f0cf866b7b0 },
[336] = { mPointer=0x7f0d1a839840, mParticipant=0x7f0d1060d5e8《nsWebBrowser::_cycleCollectorGlobal》, mColor=0, mInternalRefs=1, mRefCount=2, mFirstChild.mPointer=0x7f0cf866d318 },
[2140] = { mPointer=0x7f0d006fdac0, mParticipant=0x7f0d1060d018《::BrowsingContext::_cycleCollectorGlobal》, mColor=0, mInternalRefs=2, mRefCount=3, mFirstChild.mPointer=0x7f0cf8686490 },
[2680] = { mPointer=0x7f0cf6034030, mParticipant=0x7f0d105ec0c8《nsNodeInfoManager::_cycleCollectorGlobal》, mColor=0, mInternalRefs=11, mRefCount=12, mFirstChild.mPointer=0x7f0cf6cc0608 },

Seeing that CC logs suggested nsNodeInfoManager in the past (comment 15) I went for that one.

With the Dataflow of mRefCount I could see when the mRefCount=12 got read from the nsNodeInfoManager's refcount. And with a watchpoint on mInternalRefs I could see which NodeInfos were traversed.

I also tracked the nsNodeInfoManager's mRefCntAndFlags to see which reference was not accounted for.

It turned out to be quite the shutdown sequence that led to this leak, and it did indeed involve a media element, and bug 1577505 is indeed the regressor. Though with a fair bit of indirection.


The sequence:

  • nsCycleCollector::ShutdownCollect() happens and runs two shutdown collections (at least, but we only care about the first two)
  • The first shutdown collection traverses an HTMLMediaElement. It gets unlinked too. But is kept alive by a non-cc-participating PerCallbackWatcher Runnable.
  • The second shutdown collection does not traverse the HTMLMediaElement or its mNodeInfo (it was unlinked, I guess), but it still holds a strong-ref to the nsNodeInfoManager (through said mNodeInfo). This is the unknown edge seen in comment 15.
  • Because of this unknown edge, the nsNodeInfoManager is not unlinked.
  • After the cycle collector has shut down the HTMLMediaElement is deleted. There are now only 11 strong-refs to the nsNodeInfoManager on the heap.

The cause:
The patch I already have on this bug was strikingly close to solve this in its first rev, had the added line just been a bit higher up.
The Runnable that kept the media element alive came from EndSrcMediaStreamPlayback(). Specifically from this line which with bug 1577505 assigns to a watchable which adds a direct task with a strong ref to the media element.

Flags: needinfo?(bugs)
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/0f20566c7b2f
Shut down the watch manager during Unlink to prevent future notify tasks. r=bryce

(In reply to Andreas Pehrson [:pehrsons] from comment #23)

  • The first shutdown collection traverses an HTMLMediaElement. It gets unlinked too. But is kept alive by a non-cc-participating PerCallbackWatcher Runnable.

I don't understand this step. Why does the CC think that it can unlink the media element if there is a strong reference to it from the runnable?

  • The second shutdown collection does not traverse the HTMLMediaElement or its mNodeInfo (it was unlinked, I guess), but it still holds a strong-ref to the nsNodeInfoManager (through said mNodeInfo). This is the unknown edge seen in comment 15.

Interesting. I guess we traverse mNodeInfo, but don't unlink it, and normally that is okay because node to nodeinfo is kind of acyclic. Even in this case, we're only leaking the info manager because we're leaking the media element anyways (to this point).

  • After the cycle collector has shut down the HTMLMediaElement is deleted. There are now only 11 strong-refs to the nsNodeInfoManager on the heap.

I guess the runnable finally gets destroyed when we shut down threads or something, but that's after the CC is gone, and if there's a cycle that needs the CC to be broken, then we just leak.

Whiteboard: [stockwell disable-recommended] → [stockwell needswork][comment 28]

(In reply to Andrew McCreight [:mccr8] from comment #28)

(In reply to Andreas Pehrson [:pehrsons] from comment #23)

  • The first shutdown collection traverses an HTMLMediaElement. It gets unlinked too. But is kept alive by a non-cc-participating PerCallbackWatcher Runnable.

I don't understand this step. Why does the CC think that it can unlink the media element if there is a strong reference to it from the runnable?

There isn't. That strong reference is created during unlink.

  • The second shutdown collection does not traverse the HTMLMediaElement or its mNodeInfo (it was unlinked, I guess), but it still holds a strong-ref to the nsNodeInfoManager (through said mNodeInfo). This is the unknown edge seen in comment 15.

Interesting. I guess we traverse mNodeInfo, but don't unlink it, and normally that is okay because node to nodeinfo is kind of acyclic. Even in this case, we're only leaking the info manager because we're leaking the media element anyways (to this point).

  • After the cycle collector has shut down the HTMLMediaElement is deleted. There are now only 11 strong-refs to the nsNodeInfoManager on the heap.

I guess the runnable finally gets destroyed when we shut down threads or something, but that's after the CC is gone, and if there's a cycle that needs the CC to be broken, then we just leak.

It's a direct task so it runs at the end of shutdown, in ProcessStableStateQueue(). See the stack in pernosco. But yes, this would need another CC to be broken.

Flags: needinfo?(apehrson)
Attachment #9106692 - Attachment description: Bug 1593739 - Shut down the watch manager during Unlink to prevent future notify tasks. r?bryce → Bug 1593739 - Create a dedicated Unlink path for mSrcStream. r?bryce

(In reply to Andreas Pehrson [:pehrsons] from comment #32)

There isn't. That strong reference is created during unlink.

Ah, I see. That's a questionable pattern, because we're generally assuming that unlinked objects are going to go away, so I don't think we can guarantee anything reasonable will happen. I'll try to keep that in mind.

Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/100092ccffcd
Create a dedicated Unlink path for mSrcStream. r=bryce

Backed out changeset 100092ccffcd (Bug 1593739) for RefPtr mda perma-failures

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=linux%2Cx64%2Cquantumrender%2Cdebug%2Cmochitests%2Cwith%2Cfission%2Cenabled%2Ctest-linux64-qr%2Fdebug-mochitest-media-fis-e10s&fromchange=90678a02990b0a6e81066a5c790d0b60a6a792d2&tochange=25cfc79bf77c58372a6233bc15b5b93161b30cef&selectedJob=276854849

Backout link: https://hg.mozilla.org/integration/autoland/rev/25cfc79bf77c58372a6233bc15b5b93161b30cef

Failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=276854849&repo=autoland&lineNumber=28604

[task 2019-11-18T22:18:42.037Z] 22:18:42 INFO - TEST-START | dom/media/tests/mochitest/test_peerConnection_basicAudioVideoVerifyExtmapSendonly.html
[task 2019-11-18T22:18:42.073Z] 22:18:42 INFO - GECKO(4139) | --DOCSHELL 0x7f2d58343800 == 2 [pid = 4315] [id = {b27e99e3-e4b8-4dfd-9736-cd72c679ddac}] [url = about:blank]
[task 2019-11-18T22:18:42.115Z] 22:18:42 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4563
[task 2019-11-18T22:18:42.185Z] 22:18:42 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: NS_ENSURE_TRUE(aCSP) failed: file /builds/worker/workspace/build/src/dom/security/FramingChecker.cpp, line 176
[task 2019-11-18T22:18:42.246Z] 22:18:42 INFO - GECKO(4139) | ++DOMWINDOW == 8 (0x7f2d64e2fc00) [pid = 4315] [serial = 289] [outer = 0x7f2d682fc6a0]
[task 2019-11-18T22:18:42.356Z] 22:18:42 INFO - GECKO(4139) | ++DOCSHELL 0x7f2d58320000 == 3 [pid = 4315] [id = {fbb074e2-f95a-4277-b5f4-20619f14fe04}]
[task 2019-11-18T22:18:42.357Z] 22:18:42 INFO - GECKO(4139) | ++DOMWINDOW == 9 (0x7f2d647e3f20) [pid = 4315] [serial = 290] [outer = (nil)]
[task 2019-11-18T22:18:42.373Z] 22:18:42 INFO - GECKO(4139) | ++DOMWINDOW == 10 (0x7f2d675b7c00) [pid = 4315] [serial = 291] [outer = 0x7f2d647e3f20]
[task 2019-11-18T22:18:42.388Z] 22:18:42 INFO - GECKO(4139) | TEST DEVICES: Got loopback audio: Monitor of Null Output
[task 2019-11-18T22:18:42.390Z] 22:18:42 INFO - GECKO(4139) | TEST DEVICES: Got loopback video: Dummy video device (0x0000)
[task 2019-11-18T22:18:42.506Z] 22:18:42 INFO - GECKO(4139) | Timecard created 1574115520.480085
[task 2019-11-18T22:18:42.507Z] 22:18:42 INFO - GECKO(4139) | Timestamp | Delta | Event | File | Function
[task 2019-11-18T22:18:42.508Z] 22:18:42 INFO - GECKO(4139) | ========================================================================================================
[task 2019-11-18T22:18:42.508Z] 22:18:42 INFO - GECKO(4139) | 0.000029 | 0.000029 | Constructor Completed | PeerConnectionImpl.cpp:336 | PeerConnectionImpl
[task 2019-11-18T22:18:42.509Z] 22:18:42 INFO - GECKO(4139) | 0.000917 | 0.000888 | Initializing PC Ctx | PeerConnectionImpl.cpp:462 | Initialize
[task 2019-11-18T22:18:42.510Z] 22:18:42 INFO - GECKO(4139) | 1.021143 | 1.020226 | Create Offer | PeerConnectionImpl.cpp:1258 | CreateOffer
[task 2019-11-18T22:18:42.511Z] 22:18:42 INFO - GECKO(4139) | 1.030076 | 0.008933 | Set Local Description | PeerConnectionImpl.cpp:1319 | SetLocalDescription
[task 2019-11-18T22:18:42.511Z] 22:18:42 INFO - GECKO(4139) | 2.019815 | 0.989739 | Destructor Invoked | PeerConnectionImpl.cpp:345 | ~PeerConnectionImpl
[task 2019-11-18T22:18:42.512Z] 22:18:42 INFO - GECKO(4139) | [Child 4315: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:370: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for b6b3195f85f7026c
[task 2019-11-18T22:18:42.513Z] 22:18:42 INFO - GECKO(4139) | Timecard created 1574115520.485803
[task 2019-11-18T22:18:42.513Z] 22:18:42 INFO - GECKO(4139) | Timestamp | Delta | Event | File | Function
[task 2019-11-18T22:18:42.514Z] 22:18:42 INFO - GECKO(4139) | ==========================================================================================================
[task 2019-11-18T22:18:42.515Z] 22:18:42 INFO - GECKO(4139) | 0.000024 | 0.000024 | Constructor Completed | PeerConnectionImpl.cpp:336 | PeerConnectionImpl
[task 2019-11-18T22:18:42.516Z] 22:18:42 INFO - GECKO(4139) | 0.000735 | 0.000711 | Initializing PC Ctx | PeerConnectionImpl.cpp:462 | Initialize
[task 2019-11-18T22:18:42.516Z] 22:18:42 INFO - GECKO(4139) | 1.055788 | 1.055053 | Set Remote Description | PeerConnectionImpl.cpp:1407 | SetRemoteDescription
[task 2019-11-18T22:18:42.517Z] 22:18:42 INFO - GECKO(4139) | 1.179028 | 0.123240 | Create Answer | PeerConnectionImpl.cpp:1285 | CreateAnswer
[task 2019-11-18T22:18:42.519Z] 22:18:42 INFO - GECKO(4139) | 1.189791 | 0.010763 | Set Local Description | PeerConnectionImpl.cpp:1319 | SetLocalDescription
[task 2019-11-18T22:18:42.519Z] 22:18:42 INFO - GECKO(4139) | 2.014399 | 0.824608 | Destructor Invoked | PeerConnectionImpl.cpp:345 | ~PeerConnectionImpl
[task 2019-11-18T22:18:42.520Z] 22:18:42 INFO - GECKO(4139) | [Child 4315: Main Thread]: I/signaling [main|PeerConnectionImpl] PeerConnectionImpl.cpp:370: ~PeerConnectionImpl: PeerConnectionImpl destructor invoked for 14f189f4de5f7d7d
[task 2019-11-18T22:18:42.603Z] 22:18:42 INFO - GECKO(4139) | [Child 4315, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6827
[task 2019-11-18T22:18:42.604Z] 22:18:42 INFO - GECKO(4139) | [Child 4315, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6827
[task 2019-11-18T22:18:42.605Z] 22:18:42 INFO - GECKO(4139) | [Child 4315, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6827
[task 2019-11-18T22:18:42.606Z] 22:18:42 INFO - GECKO(4139) | [Child 4315, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6827
[task 2019-11-18T22:18:42.608Z] 22:18:42 INFO - GECKO(4139) | [Child 4315, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6827
[task 2019-11-18T22:18:42.609Z] 22:18:42 INFO - GECKO(4139) | [Child 4315, Main Thread] WARNING: Wrong inner/outer window combination!: file /builds/worker/workspace/build/src/dom/base/Document.cpp, line 6827
[task 2019-11-18T22:18:42.708Z] 22:18:42 INFO - GECKO(4139) | --DOMWINDOW == 9 (0x7f2d583f5800) [pid = 4315] [serial = 287] [outer = (nil)] [url = about:blank]
[task 2019-11-18T22:18:42.710Z] 22:18:42 INFO - GECKO(4139) | --DOMWINDOW == 8 (0x7f2d64e6f800) [pid = 4315] [serial = 288] [outer = (nil)] [url = https://example.com/tests/SimpleTest/iframe-between-tests.html]
[task 2019-11-18T22:18:42.711Z] 22:18:42 INFO - GECKO(4139) | --DOMWINDOW == 7 (0x7f2d647e3d40) [pid = 4315] [serial = 286] [outer = (nil)] [url = about:blank]
[task 2019-11-18T22:18:42.712Z] 22:18:42 INFO - GECKO(4139) | --DOMWINDOW == 6 (0x7f2d58395800) [pid = 4315] [serial = 285] [outer = (nil)] [url = https://example.com/tests/dom/media/tests/mochitest/test_peerConnection_basicAudioVideoVerifyExtmap.html]
[task 2019-11-18T22:18:42.716Z] 22:18:42 INFO - GECKO(4139) | Assertion failure: mRawPtr != nullptr (You can't dereference a NULL RefPtr with operator->().), at /builds/worker/workspace/build/src/obj-firefox/dist/include/mozilla/RefPtr.h:307
[task 2019-11-18T22:19:05.369Z] 22:19:05 INFO - GECKO(4139) | #01: mozilla::dom::HTMLMediaElement::UpdateMediaSize(mozilla::gfx::IntSizeTyped<mozilla::gfx::UnknownUnits> const&) [dom/html/HTMLMediaElement.cpp:6232]
[task 2019-11-18T22:19:05.371Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.372Z] 22:19:05 INFO - GECKO(4139) | #02: mozilla::dom::HTMLVideoElement::UpdateMediaSize(mozilla::gfx::IntSizeTyped<mozilla::gfx::UnknownUnits> const&) [dom/html/HTMLVideoElement.cpp:100]
[task 2019-11-18T22:19:05.372Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.373Z] 22:19:05 INFO - GECKO(4139) | #03: mozilla::dom::HTMLMediaElement::Invalidate(bool, mozilla::Maybe<mozilla::gfx::IntSizeTyped<mozilla::gfx::UnknownUnits> >&, bool) [dom/html/HTMLMediaElement.cpp:6197]
[task 2019-11-18T22:19:05.374Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.375Z] 22:19:05 INFO - GECKO(4139) | #04: mozilla::dom::HTMLVideoElement::Invalidate(bool, mozilla::Maybe<mozilla::gfx::IntSizeTyped<mozilla::gfx::UnknownUnits> >&, bool) [dom/html/HTMLVideoElement.cpp:138]
[task 2019-11-18T22:19:05.376Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.376Z] 22:19:05 INFO - GECKO(4139) | #05: mozilla::VideoFrameContainer::InvalidateWithFlags(unsigned int) [dom/media/VideoFrameContainer.cpp:261]
[task 2019-11-18T22:19:05.377Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.378Z] 22:19:05 INFO - GECKO(4139) | #06: mozilla::detail::RunnableMethodImpl<RefPtr<mozilla::VideoFrameContainer> const, void (mozilla::VideoFrameContainer::)(), true, (mozilla::RunnableKind)0>::Run() [xpcom/threads/nsThreadUtils.h:1179]
[task 2019-11-18T22:19:05.379Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.379Z] 22:19:05 INFO - GECKO(4139) | #07: mozilla::EventTargetWrapper::Runner::Run() [xpcom/threads/AbstractThread.cpp:113]
[task 2019-11-18T22:19:05.380Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.381Z] 22:19:05 INFO - GECKO(4139) | #08: mozilla::SchedulerGroup::Runnable::Run() [xpcom/threads/SchedulerGroup.cpp:295]
[task 2019-11-18T22:19:05.382Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.382Z] 22:19:05 INFO - GECKO(4139) | #09: nsThread::ProcessNextEvent(bool, bool
) [xpcom/threads/nsThread.cpp:1250]
[task 2019-11-18T22:19:05.383Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.384Z] 22:19:05 INFO - GECKO(4139) | #10: NS_ProcessNextEvent(nsIThread*, bool) [xpcom/threads/nsThreadUtils.cpp:486]
[task 2019-11-18T22:19:05.384Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.386Z] 22:19:05 INFO - GECKO(4139) | #11: mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:88]
[task 2019-11-18T22:19:05.387Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.388Z] 22:19:05 INFO - GECKO(4139) | #12: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:291]
[task 2019-11-18T22:19:05.388Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.389Z] 22:19:05 INFO - GECKO(4139) | #13: nsBaseAppShell::Run() [widget/nsBaseAppShell.cpp:139]
[task 2019-11-18T22:19:05.390Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.391Z] 22:19:05 INFO - GECKO(4139) | #14: XRE_RunAppShell() [toolkit/xre/nsEmbedFunctions.cpp:934]
[task 2019-11-18T22:19:05.391Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.392Z] 22:19:05 INFO - GECKO(4139) | #15: mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) [ipc/glue/MessagePump.cpp:238]
[task 2019-11-18T22:19:05.393Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.394Z] 22:19:05 INFO - GECKO(4139) | #16: MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:291]
[task 2019-11-18T22:19:05.395Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.396Z] 22:19:05 INFO - GECKO(4139) | #17: XRE_InitChildProcess(int, char**, XREChildData const*) [toolkit/xre/nsEmbedFunctions.cpp:769]
[task 2019-11-18T22:19:05.397Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.579Z] 22:19:05 INFO - GECKO(4139) | #18: content_process_main(mozilla::Bootstrap*, int, char**) [ipc/contentproc/plugin-container.cpp:57]
[task 2019-11-18T22:19:05.580Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.580Z] 22:19:05 INFO - GECKO(4139) | #19: main [browser/app/nsBrowserApp.cpp:272]
[task 2019-11-18T22:19:05.581Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.582Z] 22:19:05 INFO - GECKO(4139) | #20: libc.so.6 + 0x20830
[task 2019-11-18T22:19:05.582Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.582Z] 22:19:05 INFO - GECKO(4139) | #21: _start
[task 2019-11-18T22:19:05.583Z] 22:19:05 INFO -
[task 2019-11-18T22:19:05.583Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/workspace/build/src/ipc/glue/ProtocolUtils.cpp, line 481
[task 2019-11-18T22:19:05.586Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: IPC message discarded: actor cannot send: file /builds/worker/workspace/build/src/ipc/glue/ProtocolUtils.cpp, line 481
[task 2019-11-18T22:19:05.586Z] 22:19:05 INFO - GECKO(4139) | ++DOCSHELL 0x7fd61c140800 == 7 [pid = 4139] [id = {6c736cd3-51da-4b44-b677-b18a9b359dbe}]
[task 2019-11-18T22:19:05.587Z] 22:19:05 INFO - GECKO(4139) | ++DOMWINDOW == 14 (0x7fd61d8213e0) [pid = 4139] [serial = 192] [outer = (nil)]
[task 2019-11-18T22:19:05.588Z] 22:19:05 INFO - GECKO(4139) | ++DOMWINDOW == 15 (0x7fd61c322c00) [pid = 4139] [serial = 193] [outer = 0x7fd61d8213e0]
[task 2019-11-18T22:19:05.588Z] 22:19:05 ERROR - GECKO(4139) | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
[task 2019-11-18T22:19:05.589Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4563
[task 2019-11-18T22:19:05.595Z] 22:19:05 INFO - GECKO(4139) | --DOCSHELL 0x7f342213c800 == 2 [pid = 4266] [id = {4778e9ff-61cd-4d3f-9501-8e69aa249a0e}] [url = moz-extension://03aea81a-db59-4cbe-94d4-96345f05bf31/_generated_background_page.html]
[task 2019-11-18T22:19:05.595Z] 22:19:05 INFO - GECKO(4139) | --DOCSHELL 0x7f342213a800 == 1 [pid = 4266] [id = {ce42fafc-8cf2-4701-ae85-3e65ddae2cd4}] [url = moz-extension://9c636594-3b1c-4723-845b-455dc224ec0d/_generated_background_page.html]
[task 2019-11-18T22:19:05.596Z] 22:19:05 INFO - GECKO(4139) | --DOCSHELL 0x7f3421b0d000 == 0 [pid = 4266] [id = {51bae7f5-8897-4110-b5a0-3c1dfd350aa9}] [url = moz-extension://8ff869c1-1c9d-4fc7-b925-08b1eae076de/_generated_background_page.html]
[task 2019-11-18T22:19:05.596Z] 22:19:05 INFO - GECKO(4139) | ++DOMWINDOW == 16 (0x7fd61e2ed000) [pid = 4139] [serial = 194] [outer = 0x7fd61d8213e0]
[task 2019-11-18T22:19:05.597Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4563
[task 2019-11-18T22:19:05.598Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: '!mIMContext', file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 6371
[task 2019-11-18T22:19:05.598Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: '!mIMContext', file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 6371
[task 2019-11-18T22:19:05.599Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Cannot set transparency mode on non-popup windows.: file /builds/worker/workspace/build/src/widget/gtk/nsWindow.cpp, line 4563
[task 2019-11-18T22:19:05.599Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: '!inner', file /builds/worker/workspace/build/src/dom/ipc/JSWindowActorService.cpp, line 181
[task 2019-11-18T22:19:05.600Z] 22:19:05 INFO - GECKO(4139) | [GPU 4162, Compositor] WARNING: Possibly dropping task posted to updater thread: file /builds/worker/workspace/build/src/gfx/layers/apz/src/APZUpdater.cpp, line 429
[task 2019-11-18T22:19:05.600Z] 22:19:05 INFO - GECKO(4139) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-11-18T22:19:05.601Z] 22:19:05 INFO - GECKO(4139) | [2019-11-18T22:18:43Z WARN xulstore::persist] tried to remove key that isn't in the store
[task 2019-11-18T22:19:05.601Z] 22:19:05 INFO - GECKO(4139) | [2019-11-18T22:18:43Z WARN xulstore::persist] tried to remove key that isn't in the store
[task 2019-11-18T22:19:05.602Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Existing entry in StartupCache.: file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 434
[task 2019-11-18T22:19:05.602Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/cache/nsCacheService.cpp, line 859
[task 2019-11-18T22:19:05.603Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/cache/nsCacheService.cpp, line 822
[task 2019-11-18T22:19:05.603Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80040111: file /builds/worker/workspace/build/src/netwerk/cache/nsApplicationCacheService.cpp, line 159
[task 2019-11-18T22:19:05.603Z] 22:19:05 INFO - GECKO(4139) | --DOMWINDOW == 5 (0x7f343b0ee3e0) [pid = 4266] [serial = 5] [outer = (nil)] [url = moz-extension://03aea81a-db59-4cbe-94d4-96345f05bf31/_generated_background_page.html]
[task 2019-11-18T22:19:05.604Z] 22:19:05 INFO - GECKO(4139) | --DOMWINDOW == 4 (0x7f343b0ef4c0) [pid = 4266] [serial = 3] [outer = (nil)] [url = moz-extension://9c636594-3b1c-4723-845b-455dc224ec0d/_generated_background_page.html]
[task 2019-11-18T22:19:05.604Z] 22:19:05 INFO - GECKO(4139) | --DOMWINDOW == 3 (0x7f343b0ef2e0) [pid = 4266] [serial = 1] [outer = (nil)] [url = moz-extension://8ff869c1-1c9d-4fc7-b925-08b1eae076de/_generated_background_page.html]
[task 2019-11-18T22:19:05.605Z] 22:19:05 INFO - GECKO(4139) | --DOMWINDOW == 2 (0x7f3422128000) [pid = 4266] [serial = 7] [outer = (nil)] [url = moz-extension://8ff869c1-1c9d-4fc7-b925-08b1eae076de/_generated_background_page.html]
[task 2019-11-18T22:19:05.605Z] 22:19:05 INFO - GECKO(4139) | --DOMWINDOW == 1 (0x7f342212a000) [pid = 4266] [serial = 8] [outer = (nil)] [url = moz-extension://9c636594-3b1c-4723-845b-455dc224ec0d/_generated_background_page.html]
[task 2019-11-18T22:19:05.606Z] 22:19:05 INFO - GECKO(4139) | --DOMWINDOW == 0 (0x7f342212c400) [pid = 4266] [serial = 9] [outer = (nil)] [url = moz-extension://03aea81a-db59-4cbe-94d4-96345f05bf31/_generated_background_page.html]
[task 2019-11-18T22:19:05.606Z] 22:19:05 INFO - GECKO(4139) | nsStringStats
[task 2019-11-18T22:19:05.606Z] 22:19:05 INFO - GECKO(4139) | => mAllocCount: 15713
[task 2019-11-18T22:19:05.607Z] 22:19:05 INFO - GECKO(4139) | => mReallocCount: 0
[task 2019-11-18T22:19:05.607Z] 22:19:05 INFO - GECKO(4139) | => mFreeCount: 15713
[task 2019-11-18T22:19:05.607Z] 22:19:05 INFO - GECKO(4139) | => mShareCount: 8385
[task 2019-11-18T22:19:05.608Z] 22:19:05 INFO - GECKO(4139) | => mAdoptCount: 504
[task 2019-11-18T22:19:05.608Z] 22:19:05 INFO - GECKO(4139) | => mAdoptFreeCount: 522
[task 2019-11-18T22:19:05.609Z] 22:19:05 INFO - GECKO(4139) | => Process ID: 4266, Thread ID: 139862328416064
[task 2019-11-18T22:19:05.609Z] 22:19:05 INFO - GECKO(4139) | --DOCSHELL 0x7fc460ada800 == 0 [pid = 4209] [id = {f8468733-b5dc-4683-842c-9f0746289262}] [url = about:newtab]
[task 2019-11-18T22:19:05.610Z] 22:19:05 INFO - GECKO(4139) | --DOMWINDOW == 1 (0x7fc461387880) [pid = 4209] [serial = 4] [outer = (nil)] [url = about:newtab]
[task 2019-11-18T22:19:05.611Z] 22:19:05 INFO - GECKO(4139) | --DOMWINDOW == 0 (0x7fc460afb000) [pid = 4209] [serial = 6] [outer = (nil)] [url = about:newtab]
[task 2019-11-18T22:19:05.611Z] 22:19:05 INFO - GECKO(4139) | nsStringStats
[task 2019-11-18T22:19:05.612Z] 22:19:05 INFO - GECKO(4139) | => mAllocCount: 16900
[task 2019-11-18T22:19:05.612Z] 22:19:05 INFO - GECKO(4139) | => mReallocCount: 0
[task 2019-11-18T22:19:05.613Z] 22:19:05 INFO - GECKO(4139) | => mFreeCount: 16900
[task 2019-11-18T22:19:05.616Z] 22:19:05 INFO - GECKO(4139) | => mShareCount: 19392
[task 2019-11-18T22:19:05.616Z] 22:19:05 INFO - GECKO(4139) | => mAdoptCount: 476
[task 2019-11-18T22:19:05.617Z] 22:19:05 INFO - GECKO(4139) | => mAdoptFreeCount: 480
[task 2019-11-18T22:19:05.617Z] 22:19:05 INFO - GECKO(4139) | => Process ID: 4209, Thread ID: 140481861920576
[task 2019-11-18T22:19:05.618Z] 22:19:05 INFO - GECKO(4139) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-11-18T22:19:05.618Z] 22:19:05 INFO - GECKO(4139) | --DOMWINDOW == 15 (0x7fd61c32cc00) [pid = 4139] [serial = 187] [outer = (nil)] [url = about:blank]
[task 2019-11-18T22:19:05.619Z] 22:19:05 INFO - GECKO(4139) | --DOCSHELL 0x7fd61c13c000 == 6 [pid = 4139] [id = {0567030f-64a2-453e-ab28-2fde59d00349}] [url = chrome://browser/content/webrtcIndicator.xul]
[task 2019-11-18T22:19:05.619Z] 22:19:05 INFO - GECKO(4139) | nsStringStats
[task 2019-11-18T22:19:05.620Z] 22:19:05 INFO - GECKO(4139) | => mAllocCount: 8593
[task 2019-11-18T22:19:05.620Z] 22:19:05 INFO - GECKO(4139) | => mReallocCount: 0
[task 2019-11-18T22:19:05.621Z] 22:19:05 INFO - GECKO(4139) | => mFreeCount: 8593
[task 2019-11-18T22:19:05.621Z] 22:19:05 INFO - GECKO(4139) | => mShareCount: 4055
[task 2019-11-18T22:19:05.621Z] 22:19:05 INFO - GECKO(4139) | => mAdoptCount: 67
[task 2019-11-18T22:19:05.622Z] 22:19:05 INFO - GECKO(4139) | => mAdoptFreeCount: 67
[task 2019-11-18T22:19:05.622Z] 22:19:05 INFO - GECKO(4139) | => Process ID: 4236, Thread ID: 140272340358976
[task 2019-11-18T22:19:05.623Z] 22:19:05 INFO - GECKO(4139) | --DOCSHELL 0x7fd61c14c000 == 5 [pid = 4139] [id = {49c61cb6-0509-43a8-96af-a828425c0d96}] [url = chrome://browser/content/webrtcIndicator.xul]
[task 2019-11-18T22:19:05.623Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Existing entry in StartupCache.: file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 434
[task 2019-11-18T22:19:05.623Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Existing entry in StartupCache.: file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 434
[task 2019-11-18T22:19:05.624Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Existing entry in StartupCache.: file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 434
[task 2019-11-18T22:19:05.624Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Existing entry in StartupCache.: file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 434
[task 2019-11-18T22:19:05.625Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Existing entry in StartupCache.: file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 434
[task 2019-11-18T22:19:05.626Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Existing entry in StartupCache.: file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 434
[task 2019-11-18T22:19:05.626Z] 22:19:05 INFO - GECKO(4139) | [Parent 4139, Main Thread] WARNING: Existing entry in StartupCache.: file /builds/worker/workspace/build/src/startupcache/StartupCache.cpp, line 434
[task 2019-11-18T22:19:05.626Z] 22:19:05 INFO - GECKO(4139) | 1574115525038 Marionette TRACE Received observer notification xpcom-will-shutdown
...
...
[task 2019-11-18T22:19:05.657Z] 22:19:05 INFO - TEST-INFO | Main app process: exit 0
[task 2019-11-18T22:19:05.657Z] 22:19:05 INFO - runtests.py | Application ran for: 0:05:38.397447
[task 2019-11-18T22:19:05.657Z] 22:19:05 INFO - zombiecheck | Reading PID log: /tmp/tmpVYyeMVpidlog
[task 2019-11-18T22:19:05.658Z] 22:19:05 INFO - ==> process 4139 launched child process 4158
[task 2019-11-18T22:19:05.658Z] 22:19:05 INFO - ==> process 4139 launched child process 4162
[task 2019-11-18T22:19:05.659Z] 22:19:05 INFO - ==> process 4139 launched child process 4209
[task 2019-11-18T22:19:05.659Z] 22:19:05 INFO - ==> process 4139 launched child process 4236
[task 2019-11-18T22:19:05.659Z] 22:19:05 INFO - ==> process 4139 launched child process 4266
[task 2019-11-18T22:19:05.660Z] 22:19:05 INFO - ==> process 4139 launched child process 4315
[task 2019-11-18T22:19:05.660Z] 22:19:05 INFO - ==> process 4139 launched child process 4748
[task 2019-11-18T22:19:05.660Z] 22:19:05 INFO - ==> process 4139 launched child process 5713
[task 2019-11-18T22:19:05.661Z] 22:19:05 INFO - zombiecheck | Checking for orphan process with PID: 4162
[task 2019-11-18T22:19:05.661Z] 22:19:05 INFO - zombiecheck | Checking for orphan process with PID: 5713
[task 2019-11-18T22:19:05.662Z] 22:19:05 INFO - zombiecheck | Checking for orphan process with PID: 4748
[task 2019-11-18T22:19:05.662Z] 22:19:05 INFO - zombiecheck | Checking for orphan process with PID: 4266
[task 2019-11-18T22:19:05.662Z] 22:19:05 INFO - zombiecheck | Checking for orphan process with PID: 4236
[task 2019-11-18T22:19:05.663Z] 22:19:05 INFO - zombiecheck | Checking for orphan process with PID: 4209
[task 2019-11-18T22:19:05.663Z] 22:19:05 INFO - zombiecheck | Checking for orphan process with PID: 4315
[task 2019-11-18T22:19:05.663Z] 22:19:05 INFO - zombiecheck | Checking for orphan process with PID: 4158
[task 2019-11-18T22:19:05.664Z] 22:19:05 INFO - mozcrash Copy/paste: /builds/worker/workspace/build/linux64-minidump_stackwalk /tmp/tmppK4_zn.mozrunner/minidumps/388a5ad9-43b5-afb7-8002-d959be11f108.dmp /builds/worker/workspace/build/symbols
[task 2019-11-18T22:19:10.414Z] 22:19:10 INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/388a5ad9-43b5-afb7-8002-d959be11f108.dmp
[task 2019-11-18T22:19:10.415Z] 22:19:10 INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/388a5ad9-43b5-afb7-8002-d959be11f108.extra
[task 2019-11-18T22:19:10.514Z] 22:19:10 INFO - PROCESS-CRASH | Main app process exited normally | application crashed [@ RefPtr<mozilla::dom::VideoStreamTrack>::operator->() const]
[task 2019-11-18T22:19:10.515Z] 22:19:10 INFO - Crash dump filename: /tmp/tmppK4_zn.mozrunner/minidumps/388a5ad9-43b5-afb7-8002-d959be11f108.dmp
[task 2019-11-18T22:19:10.515Z] 22:19:10 INFO - Operating system: Linux
[task 2019-11-18T22:19:10.516Z] 22:19:10 INFO - 0.0.0 Linux 4.4.0-1014-aws #14taskcluster1-Ubuntu SMP Tue Apr 3 10:27:00 UTC 2018 x86_64
[task 2019-11-18T22:19:10.516Z] 22:19:10 INFO - CPU: amd64
[task 2019-11-18T22:19:10.516Z] 22:19:10 INFO - family 6 model 85 stepping 4
[task 2019-11-18T22:19:10.517Z] 22:19:10 INFO - 1 CPU
[task 2019-11-18T22:19:10.517Z] 22:19:10 INFO -
[task 2019-11-18T22:19:10.517Z] 22:19:10 INFO - GPU: UNKNOWN
[task 2019-11-18T22:19:10.518Z] 22:19:10 INFO -
[task 2019-11-18T22:19:10.518Z] 22:19:10 INFO - Crash reason: SIGSEGV /SEGV_MAPERR
[task 2019-11-18T22:19:10.518Z] 22:19:10 INFO - Crash address: 0x0
[task 2019-11-18T22:19:10.519Z] 22:19:10 INFO - Process uptime: not available
[task 2019-11-18T22:19:10.519Z] 22:19:10 INFO -
[task 2019-11-18T22:19:10.519Z] 22:19:10 INFO - Thread 0 (crashed)
[task 2019-11-18T22:19:10.519Z] 22:19:10 INFO - 0 libxul.so!RefPtr<mozilla::dom::VideoStreamTrack>::operator->() const [RefPtr.h:100092ccffcdcdeea743bad5bc80c7696fba1844 : 306 + 0x29]
[task 2019-11-18T22:19:10.520Z] 22:19:10 INFO - rax = 0x00007f2d7444f4ec rdx = 0x0000000000000000
[task 2019-11-18T22:19:10.520Z] 22:19:10 INFO - rcx = 0x0000555649a01e28 rbx = 0x00007f2d5aa11000
[task 2019-11-18T22:19:10.520Z] 22:19:10 INFO - rsi = 0x00007f2d8183b770 rdi = 0x00007f2d8183a540
[task 2019-11-18T22:19:10.520Z] 22:19:10 INFO - rbp = 0x00007ffcfd8b6910 rsp = 0x00007ffcfd8b6910
[task 2019-11-18T22:19:10.520Z] 22:19:10 INFO - r8 = 0x00007f2d8183b770 r9 = 0x00007f2d82897740
[task 2019-11-18T22:19:10.521Z] 22:19:10 INFO - r10 = 0x0000000000000000 r11 = 0x0000000000000000
[task 2019-11-18T22:19:10.521Z] 22:19:10 INFO - r12 = 0x0000000000000000 r13 = 0x00000000ffffffff
[task 2019-11-18T22:19:10.521Z] 22:19:10 INFO - r14 = 0x00007ffcfd8b69a8 r15 = 0x0000000000000001
[task 2019-11-18T22:19:10.521Z] 22:19:10 INFO - rip = 0x00007f2d6f1f9b67
[task 2019-11-18T22:19:10.521Z] 22:19:10 INFO - Found by: given as instruction pointer in context
[task 2019-11-18T22:19:10.522Z] 22:19:10 INFO - 1 libxul.so!mozilla::dom::HTMLMediaElement::UpdateMediaSize(mozilla::gfx::IntSizeTyped<mozilla::gfx::UnknownUnits> const&) [HTMLMediaElement.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 6232 + 0xc]
[task 2019-11-18T22:19:10.522Z] 22:19:10 INFO - rbx = 0x00007f2d5aa11000 rbp = 0x00007ffcfd8b6950
[task 2019-11-18T22:19:10.522Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b6920 r12 = 0x0000000000000000
[task 2019-11-18T22:19:10.522Z] 22:19:10 INFO - r13 = 0x00000000ffffffff r14 = 0x00007ffcfd8b69a8
[task 2019-11-18T22:19:10.522Z] 22:19:10 INFO - r15 = 0x0000000000000001 rip = 0x00007f2d708a1fd1
[task 2019-11-18T22:19:10.523Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.523Z] 22:19:10 INFO - 2 libxul.so!mozilla::dom::HTMLVideoElement::UpdateMediaSize(mozilla::gfx::IntSizeTyped<mozilla::gfx::UnknownUnits> const&) [HTMLVideoElement.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 98 + 0x5]
[task 2019-11-18T22:19:10.523Z] 22:19:10 INFO - rbx = 0x00007f2d5aa11000 rbp = 0x00007ffcfd8b6990
[task 2019-11-18T22:19:10.523Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b6960 r12 = 0x0000000000000000
[task 2019-11-18T22:19:10.524Z] 22:19:10 INFO - r13 = 0x00000000ffffffff r14 = 0x00007ffcfd8b69a8
[task 2019-11-18T22:19:10.524Z] 22:19:10 INFO - r15 = 0x0000000000000001 rip = 0x00007f2d708db5ad
[task 2019-11-18T22:19:10.524Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.524Z] 22:19:10 INFO - 3 libxul.so!mozilla::dom::HTMLMediaElement::Invalidate(bool, mozilla::Maybe<mozilla::gfx::IntSizeTyped<mozilla::gfx::UnknownUnits> >&, bool) [HTMLMediaElement.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 6196 + 0xf]
[task 2019-11-18T22:19:10.524Z] 22:19:10 INFO - rbx = 0x00007f2d5aa11000 rbp = 0x00007ffcfd8b69e0
[task 2019-11-18T22:19:10.525Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b69a0 r12 = 0x0000000000000000
[task 2019-11-18T22:19:10.525Z] 22:19:10 INFO - r13 = 0x00000000ffffffff r14 = 0x0000000000000000
[task 2019-11-18T22:19:10.525Z] 22:19:10 INFO - r15 = 0x0000000000000001 rip = 0x00007f2d708a1ded
[task 2019-11-18T22:19:10.525Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.525Z] 22:19:10 INFO - 4 libxul.so!mozilla::dom::HTMLVideoElement::Invalidate(bool, mozilla::Maybe<mozilla::gfx::IntSizeTyped<mozilla::gfx::UnknownUnits> >&, bool) [HTMLVideoElement.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 136 + 0x5]
[task 2019-11-18T22:19:10.526Z] 22:19:10 INFO - rbx = 0x00007f2d5aa11000 rbp = 0x00007ffcfd8b6a00
[task 2019-11-18T22:19:10.526Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b69f0 r12 = 0x00007f2d81293901
[task 2019-11-18T22:19:10.526Z] 22:19:10 INFO - r13 = 0x00000000ffffffff r14 = 0x0000000000000000
[task 2019-11-18T22:19:10.526Z] 22:19:10 INFO - r15 = 0x00007ffcfd8b6a18 rip = 0x00007f2d708db698
[task 2019-11-18T22:19:10.526Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.527Z] 22:19:10 INFO - 5 libxul.so!mozilla::VideoFrameContainer::InvalidateWithFlags(unsigned int) [VideoFrameContainer.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 260 + 0x17]
[task 2019-11-18T22:19:10.527Z] 22:19:10 INFO - rbx = 0x00007ffcfd8b6a28 rbp = 0x00007ffcfd8b6a60
[task 2019-11-18T22:19:10.527Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b6a10 r12 = 0x00007f2d81293901
[task 2019-11-18T22:19:10.527Z] 22:19:10 INFO - r13 = 0x00000000ffffffff r14 = 0x0000000000000000
[task 2019-11-18T22:19:10.528Z] 22:19:10 INFO - r15 = 0x00007ffcfd8b6a18 rip = 0x00007f2d7093045b
[task 2019-11-18T22:19:10.528Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.528Z] 22:19:10 INFO - 6 libxul.so!mozilla::detail::RunnableMethodImpl<RefPtr<mozilla::VideoFrameContainer> const, void (mozilla::VideoFrameContainer::)(), true, (mozilla::RunnableKind)0>::Run() [nsThreadUtils.h:100092ccffcdcdeea743bad5bc80c7696fba1844 : 1176 + 0x17]
[task 2019-11-18T22:19:10.528Z] 22:19:10 INFO - rbx = 0x00007f2d5aad7f38 rbp = 0x00007ffcfd8b6a70
[task 2019-11-18T22:19:10.528Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b6a70 r12 = 0x00007f2d81293900
[task 2019-11-18T22:19:10.529Z] 22:19:10 INFO - r13 = 0x00000000ffffffff r14 = 0x00007f2d812ae000
[task 2019-11-18T22:19:10.529Z] 22:19:10 INFO - r15 = 0x00007f2d5b1ce2c0 rip = 0x00007f2d708b02af
[task 2019-11-18T22:19:10.529Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.529Z] 22:19:10 INFO - 7 libxul.so!mozilla::EventTargetWrapper::Runner::Run() [AbstractThread.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 113 + 0x15]
[task 2019-11-18T22:19:10.529Z] 22:19:10 INFO - rbx = 0x00007f2d5aad7f38 rbp = 0x00007ffcfd8b6aa0
[task 2019-11-18T22:19:10.530Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b6a80 r12 = 0x00007f2d81293900
[task 2019-11-18T22:19:10.530Z] 22:19:10 INFO - r13 = 0x00000000ffffffff r14 = 0x00007f2d812ae000
[task 2019-11-18T22:19:10.530Z] 22:19:10 INFO - r15 = 0x00007f2d5b1ce2c0 rip = 0x00007f2d6e72b85a
[task 2019-11-18T22:19:10.530Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.530Z] 22:19:10 INFO - 8 libxul.so!mozilla::SchedulerGroup::Runnable::Run() [SchedulerGroup.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 295 + 0x15]
[task 2019-11-18T22:19:10.530Z] 22:19:10 INFO - rbx = 0x00007f2d5b1ce290 rbp = 0x00007ffcfd8b6ad0
[task 2019-11-18T22:19:10.531Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b6ab0 r12 = 0x00007f2d81293900
[task 2019-11-18T22:19:10.531Z] 22:19:10 INFO - r13 = 0x00000000ffffffff r14 = 0x0000000000000001
[task 2019-11-18T22:19:10.531Z] 22:19:10 INFO - r15 = 0x00007f2d5b1ce2c0 rip = 0x00007f2d6e728e32
[task 2019-11-18T22:19:10.531Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.531Z] 22:19:10 INFO - 9 libxul.so!nsThread::ProcessNextEvent(bool, bool
) [nsThread.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 1250 + 0x11]
[task 2019-11-18T22:19:10.532Z] 22:19:10 INFO - rbx = 0x00007ffcfd8b6b20 rbp = 0x00007ffcfd8b7030
[task 2019-11-18T22:19:10.532Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b6ae0 r12 = 0x00007f2d81293900
[task 2019-11-18T22:19:10.532Z] 22:19:10 INFO - r13 = 0x00000000ffffffff r14 = 0x0000000000000001
[task 2019-11-18T22:19:10.532Z] 22:19:10 INFO - r15 = 0x00007f2d812939f0 rip = 0x00007f2d6e73d378
[task 2019-11-18T22:19:10.533Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.533Z] 22:19:10 INFO - 10 libxul.so!NS_ProcessNextEvent(nsIThread*, bool) [nsThreadUtils.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 486 + 0xc]
[task 2019-11-18T22:19:10.533Z] 22:19:10 INFO - rbx = 0x0000000000000000 rbp = 0x00007ffcfd8b7060
[task 2019-11-18T22:19:10.533Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b7040 r12 = 0x0000000000000001
[task 2019-11-18T22:19:10.534Z] 22:19:10 INFO - r13 = 0x00007f2d8129ccb0 r14 = 0x00007ffcfd8b7047
[task 2019-11-18T22:19:10.534Z] 22:19:10 INFO - r15 = 0x0000000000000001 rip = 0x00007f2d6e74050f
[task 2019-11-18T22:19:10.534Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.534Z] 22:19:10 INFO - 11 libxul.so!mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) [MessagePump.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 88 + 0x7]
[task 2019-11-18T22:19:10.534Z] 22:19:10 INFO - rbx = 0x00007f2d8129cc90 rbp = 0x00007ffcfd8b70c0
[task 2019-11-18T22:19:10.535Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b7070 r12 = 0x0000000000000001
[task 2019-11-18T22:19:10.535Z] 22:19:10 INFO - r13 = 0x00007f2d8129ccb0 r14 = 0x00007ffcfd8b7228
[task 2019-11-18T22:19:10.535Z] 22:19:10 INFO - r15 = 0x0000000000000001 rip = 0x00007f2d6ecd61e0
[task 2019-11-18T22:19:10.535Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.536Z] 22:19:10 INFO - 12 libxul.so!MessageLoop::Run() [message_loop.cc:100092ccffcdcdeea743bad5bc80c7696fba1844 : 290 + 0x8]
[task 2019-11-18T22:19:10.536Z] 22:19:10 INFO - rbx = 0x00007ffcfd8b7228 rbp = 0x00007ffcfd8b7100
[task 2019-11-18T22:19:10.536Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b70d0 r12 = 0x00007f2d812e3000
[task 2019-11-18T22:19:10.544Z] 22:19:10 INFO - r13 = 0x00007ffcfd8b8668 r14 = 0x00007ffcfd8b70d0
[task 2019-11-18T22:19:10.544Z] 22:19:10 INFO - r15 = 0x000000000000102b rip = 0x00007f2d6ec89e17
[task 2019-11-18T22:19:10.544Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.545Z] 22:19:10 INFO - 13 libxul.so!nsBaseAppShell::Run() [nsBaseAppShell.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 137 + 0xd]
[task 2019-11-18T22:19:10.545Z] 22:19:10 INFO - rbx = 0x00007f2d6844dac0 rbp = 0x00007ffcfd8b7120
[task 2019-11-18T22:19:10.546Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b7110 r12 = 0x00007f2d812e3000
[task 2019-11-18T22:19:10.546Z] 22:19:10 INFO - r13 = 0x00007ffcfd8b8668 r14 = 0x00007f2d81293900
[task 2019-11-18T22:19:10.547Z] 22:19:10 INFO - r15 = 0x000000000000102b rip = 0x00007f2d712615d1
[task 2019-11-18T22:19:10.547Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.547Z] 22:19:10 INFO - 14 libxul.so!XRE_RunAppShell() [nsEmbedFunctions.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 934 + 0xe]
[task 2019-11-18T22:19:10.548Z] 22:19:10 INFO - rbx = 0x00007ffcfd8b7130 rbp = 0x00007ffcfd8b7150
[task 2019-11-18T22:19:10.548Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b7130 r12 = 0x00007f2d812e3000
[task 2019-11-18T22:19:10.548Z] 22:19:10 INFO - r13 = 0x00007ffcfd8b8668 r14 = 0x0000000000000000
[task 2019-11-18T22:19:10.549Z] 22:19:10 INFO - r15 = 0x000000000000102b rip = 0x00007f2d72398e38
[task 2019-11-18T22:19:10.549Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.550Z] 22:19:10 INFO - 15 libxul.so!mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) [MessagePump.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 238 + 0x5]
[task 2019-11-18T22:19:10.550Z] 22:19:10 INFO - rbx = 0x00007ffcfd8b7228 rbp = 0x00007ffcfd8b7180
[task 2019-11-18T22:19:10.550Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b7160 r12 = 0x00007f2d812e3000
[task 2019-11-18T22:19:10.551Z] 22:19:10 INFO - r13 = 0x00007ffcfd8b8668 r14 = 0x00007f2d8129cc90
[task 2019-11-18T22:19:10.551Z] 22:19:10 INFO - r15 = 0x000000000000102b rip = 0x00007f2d6ecd6789
[task 2019-11-18T22:19:10.551Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.552Z] 22:19:10 INFO - 16 libxul.so!MessageLoop::Run() [message_loop.cc:100092ccffcdcdeea743bad5bc80c7696fba1844 : 290 + 0x8]
[task 2019-11-18T22:19:10.552Z] 22:19:10 INFO - rbx = 0x00007ffcfd8b7228 rbp = 0x00007ffcfd8b71c0
[task 2019-11-18T22:19:10.552Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b7190 r12 = 0x00007f2d812e3000
[task 2019-11-18T22:19:10.553Z] 22:19:10 INFO - r13 = 0x00007ffcfd8b8668 r14 = 0x00007ffcfd8b7190
[task 2019-11-18T22:19:10.553Z] 22:19:10 INFO - r15 = 0x000000000000102b rip = 0x00007f2d6ec89e17
[task 2019-11-18T22:19:10.554Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.554Z] 22:19:10 INFO - 17 libxul.so!XRE_InitChildProcess(int, char**, XREChildData const*) [nsEmbedFunctions.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 769 + 0x5]
[task 2019-11-18T22:19:10.554Z] 22:19:10 INFO - rbx = 0x0000000000000001 rbp = 0x00007ffcfd8b74c0
[task 2019-11-18T22:19:10.555Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b71d0 r12 = 0x00007f2d812e3000
[task 2019-11-18T22:19:10.555Z] 22:19:10 INFO - r13 = 0x00007ffcfd8b8668 r14 = 0x0000000080004005
[task 2019-11-18T22:19:10.555Z] 22:19:10 INFO - r15 = 0x000000000000102b rip = 0x00007f2d72398aa1
[task 2019-11-18T22:19:10.556Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.556Z] 22:19:10 INFO - 18 firefox-bin!content_process_main(mozilla::Bootstrap*, int, char**) [plugin-container.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 56 + 0x11]
[task 2019-11-18T22:19:10.556Z] 22:19:10 INFO - rbx = 0x0000000000000013 rbp = 0x00007ffcfd8b7500
[task 2019-11-18T22:19:10.556Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b74d0 r12 = 0x00007ffcfd8b74d0
[task 2019-11-18T22:19:10.557Z] 22:19:10 INFO - r13 = 0x0000090dc11d1e20 r14 = 0x00007ffcfd8b8668
[task 2019-11-18T22:19:10.558Z] 22:19:10 INFO - r15 = 0x00007f2d81202730 rip = 0x000055564993dd2e
[task 2019-11-18T22:19:10.558Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.558Z] 22:19:10 INFO - 19 firefox-bin!main [nsBrowserApp.cpp:100092ccffcdcdeea743bad5bc80c7696fba1844 : 272 + 0x19]
[task 2019-11-18T22:19:10.559Z] 22:19:10 INFO - rbx = 0x00007ffcfd8b7550 rbp = 0x00007ffcfd8b8580
[task 2019-11-18T22:19:10.559Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b7510 r12 = 0x00007ffcfd8b8668
[task 2019-11-18T22:19:10.559Z] 22:19:10 INFO - r13 = 0x0000090dc11d1e20 r14 = 0x0000000000000014
[task 2019-11-18T22:19:10.560Z] 22:19:10 INFO - r15 = 0x0000555649a01668 rip = 0x000055564993e034
[task 2019-11-18T22:19:10.560Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.560Z] 22:19:10 INFO - 20 libc-2.23.so + 0x20830
[task 2019-11-18T22:19:10.561Z] 22:19:10 INFO - rbx = 0x0000000000000000 rbp = 0x00005556499d2b50
[task 2019-11-18T22:19:10.561Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b8590 r12 = 0x000055564993dbb4
[task 2019-11-18T22:19:10.562Z] 22:19:10 INFO - r13 = 0x00007ffcfd8b8660 r14 = 0x0000000000000000
[task 2019-11-18T22:19:10.562Z] 22:19:10 INFO - r15 = 0x0000000000000000 rip = 0x00007f2d81495830
[task 2019-11-18T22:19:10.563Z] 22:19:10 INFO - Found by: call frame info
[task 2019-11-18T22:19:10.563Z] 22:19:10 INFO - 21 libmozsandbox.so!_fini + 0xa880
[task 2019-11-18T22:19:10.564Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b8598 rip = 0x00007f2d8292c3d8
[task 2019-11-18T22:19:10.564Z] 22:19:10 INFO - Found by: stack scanning
[task 2019-11-18T22:19:10.564Z] 22:19:10 INFO - 22 firefox-bin!<name omitted> [UniquePtr.h:100092ccffcdcdeea743bad5bc80c7696fba1844 : 274 + 0x17]
[task 2019-11-18T22:19:10.565Z] 22:19:10 INFO - rsp = 0x00007ffcfd8b85b0 rip = 0x000055564993dd71
[task 2019-11-18T22:19:10.565Z] 22:19:10 INFO - Found by: stack scanning
[task 2019-11-18T22:19:10.565Z] 22:19:10 INFO -
...

Flags: needinfo?(apehrson)
Pushed by pehrsons@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/d2ac59316460
Create a dedicated Unlink path for mSrcStream. r=bryce
Status: ASSIGNED → RESOLVED
Closed: 3 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla72

Phew. Fun. To follow up on this: Andrew, do you think anything could be done in the cycle collector to mitigate issues like these? I'm thinking forbidding AddRef on a cycle collection participant while it is being unlinked would be helpful. Would it be reasonable and feasible to do?

Flags: needinfo?(continuation)

(In reply to Andreas Pehrson [:pehrsons] from comment #41)

Phew. Fun. To follow up on this: Andrew, do you think anything could be done in the cycle collector to mitigate issues like these? I'm thinking forbidding AddRef on a cycle collection participant while it is being unlinked would be helpful. Would it be reasonable and feasible to do?

That's an interesting idea, but I think there are some practical difficulties.

We actually do something like that during the Traverse phase, because somebody was actually calling AddRef and Release during Traverse which caused problems (bug 1189122). This is done by setting nsCycleCollector::mScanInProgress.

This mechanism doesn't currently distinguish AddRef from Release, and we call Release during Unlink by necessity, so it would require rejiggering (probably something like passing in a flag to Suspect in debug builds to indicate if we're addref or release). It wouldn't catch the case where we did a release before we did an addref (this could happen if some other object with a reference to the object happens to get unlinked first), because we only suspect an object once, but it could still catch things sometimes.

Unlink code also tends to involve more wacky stuff than Traverse code so I would be worried about spurious failures. There's probably code that takes stack references to objects while it is running, which should be okay.

Flags: needinfo?(continuation)
No longer blocks: 1598245
See Also: → 1598245

(In reply to Andrew McCreight [:mccr8] from comment #42)

(In reply to Andreas Pehrson [:pehrsons] from comment #41)

Phew. Fun. To follow up on this: Andrew, do you think anything could be done in the cycle collector to mitigate issues like these? I'm thinking forbidding AddRef on a cycle collection participant while it is being unlinked would be helpful. Would it be reasonable and feasible to do?

That's an interesting idea, but I think there are some practical difficulties.

We actually do something like that during the Traverse phase, because somebody was actually calling AddRef and Release during Traverse which caused problems (bug 1189122). This is done by setting nsCycleCollector::mScanInProgress.

This mechanism doesn't currently distinguish AddRef from Release, and we call Release during Unlink by necessity, so it would require rejiggering (probably something like passing in a flag to Suspect in debug builds to indicate if we're addref or release). It wouldn't catch the case where we did a release before we did an addref (this could happen if some other object with a reference to the object happens to get unlinked first), because we only suspect an object once, but it could still catch things sometimes.

Unlink code also tends to involve more wacky stuff than Traverse code so I would be worried about spurious failures. There's probably code that takes stack references to objects while it is running, which should be okay.

Yeah I'm thinking of only forbidding AddRef on the object being Unlinked, to keep things as narrow as possible. And I assume the CC is keeping a reference to the object it is unlinking, so if any object's Unlink takes a stack reference to itself, that should be easily changed in my mind.

I guess this would leave out a class of bugs where an object in Unlink takes a (non-stack) reference to another object that was already Unlinked. Perhaps another measure could mitigate that somehow.

Unlink method implementations may do some work asynchronously to reduce jank. ContentUnbinder comes to my mind - it is used to
break down DOM trees. And such async helper object needs to of course have strong pointers to the objects to destroy.

(In reply to Olli Pettay [:smaug] from comment #44)

Unlink method implementations may do some work asynchronously to reduce jank. ContentUnbinder comes to my mind - it is used to
break down DOM trees. And such async helper object needs to of course have strong pointers to the objects to destroy.

Are the objects that this async helper takes strongrefs to cycle collection participants? Is it possible that those objects themselves are not ready to be unlinked yet -- or have been unlinked and have strong references to some object that is not ready to be unlinked yet? If yes to both, isn't that this bug all over again?

That said, forbidding AddRef only on the object being Unlinked would still allow for those strong refs to be taken.

You need to log in before you can comment on or make changes to this bug.