Closed Bug 1444557 Opened 6 years ago Closed 6 years ago

Intermittent tools/profiler/tests/chrome/test_profile_worker.html, test_profile_worker_bug_1428076.html | application crashed [@ arena_t::MallocSmall]

Categories

(Core :: Gecko Profiler, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: crash, intermittent-failure)

Crash Data

Filed by: btara [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=167048652&repo=autoland

https://queue.taskcluster.net/v1/task/FJmtr1znTcCoI3UDNorD3w/runs/0/artifacts/public/logs/live_backing.log

[task 2018-03-09T21:05:14.509Z] 21:05:14     INFO -  170 INFO TEST-START | tools/profiler/tests/chrome/test_profile_worker.html
[task 2018-03-09T21:08:41.179Z] 21:08:41     INFO -  INFO | automation.py | Application ran for: 0:05:13.178601
[task 2018-03-09T21:08:41.179Z] 21:08:41     INFO -  INFO | zombiecheck | Reading PID log: /tmp/tmpT5b71Kpidlog
[task 2018-03-09T21:08:42.429Z] 21:08:42     INFO -  mozcrash Copy/paste: /usr/local/bin/linux64-minidump_stackwalk /tmp/tmpor7Xl0/3160dabb-e4fe-f01f-f0d7-847e0d33f609.dmp /builds/worker/workspace/build/symbols
[task 2018-03-09T21:08:52.591Z] 21:08:52     INFO -  mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/3160dabb-e4fe-f01f-f0d7-847e0d33f609.dmp
[task 2018-03-09T21:08:52.591Z] 21:08:52     INFO -  mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/3160dabb-e4fe-f01f-f0d7-847e0d33f609.extra
[task 2018-03-09T21:08:52.593Z] 21:08:52  WARNING -  PROCESS-CRASH | tools/profiler/tests/chrome/test_profile_worker.html | application crashed [@ arena_t::MallocSmall]
[task 2018-03-09T21:08:52.594Z] 21:08:52     INFO -  Crash dump filename: /tmp/tmpor7Xl0/3160dabb-e4fe-f01f-f0d7-847e0d33f609.dmp
[task 2018-03-09T21:08:52.594Z] 21:08:52     INFO -  Operating system: Android
[task 2018-03-09T21:08:52.594Z] 21:08:52     INFO -                    0.0.0 Linux 2.6.29-gea477bb #1 Wed Sep 26 11:04:45 PDT 2012 armv7l
[task 2018-03-09T21:08:52.594Z] 21:08:52     INFO -  CPU: arm
[task 2018-03-09T21:08:52.599Z] 21:08:52     INFO -       ARMv7 ARM Cortex-A8 features: swp,half,thumb,fastmult,vfpv2,edsp,neon,vfpv3
[task 2018-03-09T21:08:52.599Z] 21:08:52     INFO -       1 CPU
[task 2018-03-09T21:08:52.599Z] 21:08:52     INFO -  GPU: UNKNOWN
[task 2018-03-09T21:08:52.599Z] 21:08:52     INFO -  Crash reason:  SIGSEGV
[task 2018-03-09T21:08:52.599Z] 21:08:52     INFO -  Crash address: 0x384adf93
[task 2018-03-09T21:08:52.599Z] 21:08:52     INFO -  Process uptime: not available
[task 2018-03-09T21:08:52.599Z] 21:08:52     INFO -  Thread 11 (crashed)
[task 2018-03-09T21:08:52.599Z] 21:08:52     INFO -   0  libmozglue.so!arena_t::MallocSmall [mozjemalloc.cpp:6df9c07fd8382b748366335218af39616493c6d2 : 2217 + 0x0]
[task 2018-03-09T21:08:52.600Z] 21:08:52     INFO -       r0 = 0xfffffe08    r1 = 0x00000003    r2 = 0x00000060    r3 = 0x5de98040
[task 2018-03-09T21:08:52.600Z] 21:08:52     INFO -       r4 = 0x384adf93    r5 = 0x5de98000    r6 = 0xfffffe00    r7 = 0x52cfdc00
[task 2018-03-09T21:08:52.600Z] 21:08:52     INFO -       r8 = 0x00000000    r9 = 0x00000000   r10 = 0x00000060   r12 = 0x00000001
[task 2018-03-09T21:08:52.600Z] 21:08:52     INFO -       fp = 0x52a045e0    sp = 0x52cfdbc0    lr = 0x528542a9    pc = 0x528542c8
[task 2018-03-09T21:08:52.600Z] 21:08:52     INFO -      Found by: given as instruction pointer in context
[task 2018-03-09T21:08:52.601Z] 21:08:52     INFO -   1  libmozglue.so!BaseAllocator::malloc [mozjemalloc.cpp:6df9c07fd8382b748366335218af39616493c6d2 : 4137 + 0x7]
[task 2018-03-09T21:08:52.601Z] 21:08:52     INFO -       r4 = 0x00000054    r5 = 0x52cfdc1c    r6 = 0x00000000    r7 = 0x52cfdc10
[task 2018-03-09T21:08:52.601Z] 21:08:52     INFO -       r8 = 0x52cfdc60    r9 = 0x52cfdc7c   r10 = 0x00000001    fp = 0x5f44a146
[task 2018-03-09T21:08:52.602Z] 21:08:52     INFO -       sp = 0x52cfdc08    lr = 0x5285579d    pc = 0x5285579d
[task 2018-03-09T21:08:52.602Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.603Z] 21:08:52     INFO -   2  libmozglue.so!Allocator<MozJemallocBase>::moz_arena_malloc [malloc_decls.h:6df9c07fd8382b748366335218af39616493c6d2 : 37 + 0x5]
[task 2018-03-09T21:08:52.603Z] 21:08:52     INFO -       r4 = 0x00000054    r5 = 0x5aa13800    r6 = 0x00000000    r7 = 0x52cfdc28
[task 2018-03-09T21:08:52.603Z] 21:08:52     INFO -       r8 = 0x52cfdc60    r9 = 0x52cfdc7c   r10 = 0x00000001    fp = 0x5f44a146
[task 2018-03-09T21:08:52.603Z] 21:08:52     INFO -       sp = 0x52cfdc18    lr = 0x528556c3    pc = 0x528556c3
[task 2018-03-09T21:08:52.604Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.604Z] 21:08:52     INFO -   3  libxul.so!js::MallocProvider<JSContext>::pod_malloc<char> [Utility.h:6df9c07fd8382b748366335218af39616493c6d2 : 388 + 0x3]
[task 2018-03-09T21:08:52.604Z] 21:08:52     INFO -       r2 = 0x528556a5    r3 = 0x52a044c0    r4 = 0x00000054    r5 = 0x5aa13800
[task 2018-03-09T21:08:52.604Z] 21:08:52     INFO -       r6 = 0x00000000    r7 = 0x52cfdc48    r8 = 0x52cfdc60    r9 = 0x52cfdc7c
[task 2018-03-09T21:08:52.605Z] 21:08:52     INFO -      r10 = 0x00000001    fp = 0x5f44a146    sp = 0x52cfdc30    lr = 0x557b77c5
[task 2018-03-09T21:08:52.605Z] 21:08:52     INFO -       pc = 0x557b77c5
[task 2018-03-09T21:08:52.605Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.605Z] 21:08:52     INFO -   4  libxul.so!js::ObjectGroup::allocationSiteGroup [MallocProvider.h:6df9c07fd8382b748366335218af39616493c6d2 : 187 + 0x7]
[task 2018-03-09T21:08:52.605Z] 21:08:52     INFO -       r4 = 0x5f7548e0    r5 = 0x00000000    r6 = 0x5aa28000    r7 = 0x52cfdd28
[task 2018-03-09T21:08:52.605Z] 21:08:52     INFO -       r8 = 0x52cfdc60    r9 = 0x52cfdc7c   r10 = 0x00000001    fp = 0x5f44a146
[task 2018-03-09T21:08:52.605Z] 21:08:52     INFO -       sp = 0x52cfdc50    lr = 0x55d060b9    pc = 0x55d060b9
[task 2018-03-09T21:08:52.606Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.606Z] 21:08:52     INFO -   5  libxul.so!js::NewObjectOperation [Interpreter.cpp:6df9c07fd8382b748366335218af39616493c6d2 : 4950 + 0xb]
[task 2018-03-09T21:08:52.606Z] 21:08:52     INFO -       r4 = 0x00000001    r5 = 0x0003fff0    r6 = 0x5f44a145    r7 = 0x52cfdd78
[task 2018-03-09T21:08:52.606Z] 21:08:52     INFO -       r8 = 0x00000000    r9 = 0x00000000   r10 = 0x52cfe004    fp = 0x5aa13800
[task 2018-03-09T21:08:52.606Z] 21:08:52     INFO -       sp = 0x52cfdd30    lr = 0x557f5b09    pc = 0x557f5b09
[task 2018-03-09T21:08:52.606Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.606Z] 21:08:52     INFO -   6  libxul.so!Interpret [Interpreter.cpp:6df9c07fd8382b748366335218af39616493c6d2 : 3769 + 0x9]
[task 2018-03-09T21:08:52.607Z] 21:08:52     INFO -       r4 = 0x5c77b130    r5 = 0x000000e7    r6 = 0x00000201    r7 = 0x52cfe130
[task 2018-03-09T21:08:52.607Z] 21:08:52     INFO -       r8 = 0x0003fff8    r9 = 0x52cfe054   r10 = 0x5aa13800    fp = 0xffffff83
[task 2018-03-09T21:08:52.607Z] 21:08:52     INFO -       sp = 0x52cfdd80    lr = 0x557e9a09    pc = 0x557e9a09
[task 2018-03-09T21:08:52.607Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.607Z] 21:08:52     INFO -   7  libxul.so!js::RunScript [Interpreter.cpp:6df9c07fd8382b748366335218af39616493c6d2 : 418 + 0x7]
[task 2018-03-09T21:08:52.607Z] 21:08:52     INFO -       r4 = 0x52cfe174    r5 = 0x5aa13800    r6 = 0x5bd9fcc0    r7 = 0x52cfe158
[task 2018-03-09T21:08:52.607Z] 21:08:52     INFO -       r8 = 0x00000000    r9 = 0x52cfe174   r10 = 0x52cfe18c    fp = 0x52cfe260
[task 2018-03-09T21:08:52.608Z] 21:08:52     INFO -       sp = 0x52cfe138    lr = 0x557de273    pc = 0x557de273
[task 2018-03-09T21:08:52.608Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.608Z] 21:08:52     INFO -   8  libxul.so!js::InternalCallOrConstruct [Interpreter.cpp:6df9c07fd8382b748366335218af39616493c6d2 : 490 + 0x5]
[task 2018-03-09T21:08:52.608Z] 21:08:52     INFO -       r4 = 0x5aa13800    r5 = 0x52cfe208    r6 = 0xffffff86    r7 = 0x52cfe1b0
[task 2018-03-09T21:08:52.608Z] 21:08:52     INFO -       r8 = 0x00000000    r9 = 0x52cfe174   r10 = 0x52cfe18c    fp = 0x52cfe260
[task 2018-03-09T21:08:52.608Z] 21:08:52     INFO -       sp = 0x52cfe160    lr = 0x557ecfd5    pc = 0x557ecfd5
[task 2018-03-09T21:08:52.609Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.609Z] 21:08:52     INFO -   9  libxul.so!InternalCall [Interpreter.cpp:6df9c07fd8382b748366335218af39616493c6d2 : 517 + 0x9]
[task 2018-03-09T21:08:52.609Z] 21:08:52     INFO -       r4 = 0x52cfe208    r5 = 0x5aa13800    r6 = 0xffffff86    r7 = 0x52cfe1d8
[task 2018-03-09T21:08:52.610Z] 21:08:52     INFO -       r8 = 0x52cfe258    r9 = 0xffffff83   r10 = 0x52cfe2b0    fp = 0x52cfe260
[task 2018-03-09T21:08:52.610Z] 21:08:52     INFO -       sp = 0x52cfe1b8    lr = 0x557ed8e9    pc = 0x557ed8e9
[task 2018-03-09T21:08:52.610Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.611Z] 21:08:52     INFO -  10  libxul.so!<name omitted> [Interpreter.cpp:6df9c07fd8382b748366335218af39616493c6d2 : 536 + 0x5]
[task 2018-03-09T21:08:52.611Z] 21:08:52     INFO -       r4 = 0x00000000    r5 = 0x52cfe208    r6 = 0xffffff86    r7 = 0x52cfe1f0
[task 2018-03-09T21:08:52.611Z] 21:08:52     INFO -       r8 = 0x52cfe258    r9 = 0xffffff83   r10 = 0x52cfe2b0    fp = 0x52cfe260
[task 2018-03-09T21:08:52.611Z] 21:08:52     INFO -       sp = 0x52cfe1e0    lr = 0x557ed975    pc = 0x557ed975
[task 2018-03-09T21:08:52.612Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.612Z] 21:08:52     INFO -  11  libxul.so!js::jit::InterpretResume [VMFunctions.cpp:6df9c07fd8382b748366335218af39616493c6d2 : 957 + 0x7]
[task 2018-03-09T21:08:52.612Z] 21:08:52     INFO -       r4 = 0x5aa13800    r5 = 0x52cfe208    r6 = 0xffffff86    r7 = 0x52cfe288
[task 2018-03-09T21:08:52.613Z] 21:08:52     INFO -       r8 = 0x52cfe258    r9 = 0xffffff83   r10 = 0x52cfe2b0    fp = 0x52cfe260
[task 2018-03-09T21:08:52.613Z] 21:08:52     INFO -       sp = 0x52cfe1f8    lr = 0x55b0008d    pc = 0x55b0008d
[task 2018-03-09T21:08:52.613Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.613Z] 21:08:52     INFO -  12  0x372dfe1a
[task 2018-03-09T21:08:52.614Z] 21:08:52     INFO -       r4 = 0x52cfe298    r5 = 0x52cfe2ac    r6 = 0x574f30e8    r7 = 0xffffff83
[task 2018-03-09T21:08:52.614Z] 21:08:52     INFO -       r8 = 0x00002043    r9 = 0x5d39e5b8   r10 = 0x00000001    fp = 0x52cfe304
[task 2018-03-09T21:08:52.614Z] 21:08:52     INFO -       sp = 0x52cfe290    lr = 0x372dfe1c    pc = 0x372dfe1c
[task 2018-03-09T21:08:52.614Z] 21:08:52     INFO -      Found by: call frame info
[task 2018-03-09T21:08:52.615Z] 21:08:52     INFO -  13  libxul.so!wcsrtombs + 0x1abb61d
[task 2018-03-09T21:08:52.615Z] 21:08:52     INFO -       sp = 0x52cfe2a4    pc = 0x580aba00
[task 2018-03-09T21:08:52.615Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.615Z] 21:08:52     INFO -  Thread 0
[task 2018-03-09T21:08:52.616Z] 21:08:52     INFO -   0  libc.so + 0x1c3dc
[task 2018-03-09T21:08:52.616Z] 21:08:52     INFO -       r0 = 0xfffffffc    r1 = 0xbeafa4a8    r2 = 0x00000010    r3 = 0xffffffff
[task 2018-03-09T21:08:52.616Z] 21:08:52     INFO -       r4 = 0x2a040c00    r5 = 0x00000000    r6 = 0x2a040c14    r7 = 0x000000fc
[task 2018-03-09T21:08:52.616Z] 21:08:52     INFO -       r8 = 0x2a040c48    r9 = 0x00000014   r10 = 0x2a00d0a0   r12 = 0xbeafa4a8
[task 2018-03-09T21:08:52.617Z] 21:08:52     INFO -       fp = 0xbeafa61c    sp = 0xbeafa488    lr = 0x400b1fb5    pc = 0x400433dc
[task 2018-03-09T21:08:52.617Z] 21:08:52     INFO -      Found by: given as instruction pointer in context
[task 2018-03-09T21:08:52.617Z] 21:08:52     INFO -   1  libutils.so + 0x1785c
[task 2018-03-09T21:08:52.617Z] 21:08:52     INFO -       sp = 0xbeafa4a0    pc = 0x400b485e
[task 2018-03-09T21:08:52.618Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.618Z] 21:08:52     INFO -   2  libbinder.so + 0x1bc2d
[task 2018-03-09T21:08:52.618Z] 21:08:52     INFO -       sp = 0xbeafa4d8    pc = 0x400f7c2f
[task 2018-03-09T21:08:52.618Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.619Z] 21:08:52     INFO -   3  libbinder.so + 0x18603
[task 2018-03-09T21:08:52.619Z] 21:08:52     INFO -       sp = 0xbeafa4f8    pc = 0x400f4605
[task 2018-03-09T21:08:52.619Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.619Z] 21:08:52     INFO -   4  libbinder.so + 0x2032d
[task 2018-03-09T21:08:52.620Z] 21:08:52     INFO -       sp = 0xbeafa500    pc = 0x400fc32f
[task 2018-03-09T21:08:52.620Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.620Z] 21:08:52     INFO -   5  libc.so + 0x109e9
[task 2018-03-09T21:08:52.620Z] 21:08:52     INFO -       sp = 0xbeafa518    pc = 0x400379eb
[task 2018-03-09T21:08:52.621Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.621Z] 21:08:52     INFO -   6  libc.so + 0xd9bf
[task 2018-03-09T21:08:52.621Z] 21:08:52     INFO -       sp = 0xbeafa530    pc = 0x400349c1
[task 2018-03-09T21:08:52.621Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.622Z] 21:08:52     INFO -   7  libbinder.so + 0x1e561
[task 2018-03-09T21:08:52.622Z] 21:08:52     INFO -       sp = 0xbeafa538    pc = 0x400fa563
[task 2018-03-09T21:08:52.622Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.622Z] 21:08:52     INFO -   8  libbinder.so + 0x1e5cf
[task 2018-03-09T21:08:52.623Z] 21:08:52     INFO -       sp = 0xbeafa550    pc = 0x400fa5d1
[task 2018-03-09T21:08:52.623Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.623Z] 21:08:52     INFO -   9  libbinder.so + 0x18469
[task 2018-03-09T21:08:52.623Z] 21:08:52     INFO -       sp = 0xbeafa554    pc = 0x400f446b
[task 2018-03-09T21:08:52.624Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.624Z] 21:08:52     INFO -  10  libgui.so + 0x2186d
[task 2018-03-09T21:08:52.624Z] 21:08:52     INFO -       sp = 0xbeafa558    pc = 0x4057786f
[task 2018-03-09T21:08:52.624Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.625Z] 21:08:52     INFO -  11  libc.so + 0x3b072
[task 2018-03-09T21:08:52.625Z] 21:08:52     INFO -       sp = 0xbeafa5a8    pc = 0x40062074
[task 2018-03-09T21:08:52.625Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.625Z] 21:08:52     INFO -  12  icudt50l.dat + 0x877511
[task 2018-03-09T21:08:52.626Z] 21:08:52     INFO -       sp = 0xbeafa5ac    pc = 0x508cc513
[task 2018-03-09T21:08:52.626Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.626Z] 21:08:52     INFO -  13  libutils.so + 0x151d7
[task 2018-03-09T21:08:52.626Z] 21:08:52     INFO -       sp = 0xbeafa5d0    pc = 0x400b21d9
[task 2018-03-09T21:08:52.627Z] 21:08:52     INFO -      Found by: stack scanning
[task 2018-03-09T21:08:52.627Z] 21:08:52     INFO -  14  libandroid_runtime.so + 0x67b6b
[task 2018-03-09T21:08:52.627Z] 21:08:52     INFO -       sp = 0xbeafa5f0    pc = 0x4016db6d
[task 2018-03-09T21:08:52.627Z] 21:08:52     INFO -      Found by: stack scanning
Summary: Intermittent tools/profiler/tests/chrome/test_profile_worker.html | application crashed [@ arena_t::MallocSmall] → Intermittent tools/profiler/tests/chrome/test_profile_worker.html, test_profile_worker_bug_1428076.html | application crashed [@ arena_t::MallocSmall]
The crash happens when we run out of memory to allocate a string, which happens during console.log. Console::MaybeExecuteDumpFunction calls JS_ValueToSource which recursively stringifies an object.

consoleBinding::log -> Console::Log -> Console::Method -> Console::MethodInternal -> Console::MaybeExecuteDumpFunction

It looks like we allocate too many "hello world!" strings in the worker which don't get GC'ed before we run out of memory. Which is strange.

This might be a GC bug or a JS_ValueToSource leak. Or maybe it's somewhat expected and we should work around it by calling something other than console.log as fast as we can in a loop.
I think that by calling "console.log" repeatedly, we actually append to the console buffer, so it's normal that it doesn't get GC.

Shouldn't we clear some of the console data when we get close to an OOM? Or maybe we do it with an hardcoded value but the threshold is too high for some ARM devices?
> It looks like we allocate too many "hello world!" strings in the worker which don't get GC'ed before we run out of memory. Which is strange.

Actually we don't loop in this worker, see the code in [1]. So it's even stranger, please disregard my comment 2.

[1] https://searchfox.org/mozilla-central/source/tools/profiler/tests/chrome/test_profile_worker.html#29-32
Crash Signature: [@ arena_t::MallocSmall] → [@ arena_t::MallocSmall][@ arena_t::DallocSmall]
Crash Signature: [@ arena_t::MallocSmall][@ arena_t::DallocSmall] → [@ arena_t::MallocSmall] [@ arena_t::DallocSmall] [@ arena_t::DallocRun]
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.