Closed Bug 1582992 Opened 5 years ago Closed 5 years ago

Intermittent tools/profiler/tests/browser/browser_test_feature_preferencereads.js | application crashed [@ JS::AutoAssertNoGC::~AutoAssertNoGC()]

Categories

(Core :: Gecko Profiler, defect, P1)

Product:
Core
Component:
Gecko Profiler
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla71
Tracking Flags:
Tracking Status
firefox-esr60 --- unaffected
firefox-esr68 --- unaffected
firefox69 --- unaffected
firefox70 --- unaffected
firefox71 --- fixed

People

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

References

(Regression)

Details

(Keywords: crash, intermittent-failure, regression)

Crash Data

Attachments

(1 file)

Bug 1582992 - Removed unneded BlocksRingBuffer's entry destructor, and ProfilerBuffer's JS::AutoSuppressGCAnalysis - r?gregtatum
47 bytes, text/x-phabricator-request
Details | Review

Filed by: cbrindusan [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=267828495&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/W-hwY5UgSI-4m41JJaSRyQ/runs/0/artifacts/public/logs/live_backing.log

[task 2019-09-21T18:55:06.046Z] 18:55:06 INFO - TEST-START | tools/profiler/tests/browser/browser_test_feature_preferencereads.js
[task 2019-09-21T18:55:06.203Z] 18:55:06 INFO - GECKO(6045) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-09-21T18:55:06.204Z] 18:55:06 INFO - GECKO(6045) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpJ6WNaG.mozrunner/runtests_leaks_tab_pid6294.log
[task 2019-09-21T18:55:06.649Z] 18:55:06 INFO - GECKO(6045) | [2019-09-21T18:55:06Z WARN audio_thread_priority::rt_linux] Could not make thread real-time.
[task 2019-09-21T18:55:06.649Z] 18:55:06 INFO - GECKO(6045) | [2019-09-21T18:55:06Z WARN audioipc_client] Could not promote audio threads to real-time during initialization.
[task 2019-09-21T18:55:06.665Z] 18:55:06 INFO - GECKO(6045) | ++DOCSHELL 0x7f90748b5800 == 1 [pid = 6277] [id = {fa610f0d-cbd6-46af-8d6a-fbc075c47506}]
[task 2019-09-21T18:55:06.890Z] 18:55:06 INFO - GECKO(6045) | ++DOMWINDOW == 1 (0x7f907589bf20) [pid = 6277] [serial = 1] [outer = (nil)]
[task 2019-09-21T18:55:06.908Z] 18:55:06 INFO - GECKO(6045) | ++DOMWINDOW == 2 (0x7f9074828400) [pid = 6277] [serial = 2] [outer = 0x7f907589bf20]
[task 2019-09-21T18:55:08.779Z] 18:55:08 INFO - GECKO(6045) | --DOCSHELL 0x7fa06275c800 == 0 [pid = 6205] [id = {ca9ef7a1-356a-4dbf-a50e-54cce58a6dcf}] [url = http://example.com/browser/tools/profiler/tests/browser/do_work_500ms.html]
[task 2019-09-21T18:55:10.691Z] 18:55:10 INFO - GECKO(6045) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-09-21T18:55:11.129Z] 18:55:11 INFO - GECKO(6045) | [2019-09-21T18:55:11Z WARN audio_thread_priority::rt_linux] Could not make thread real-time.
[task 2019-09-21T18:55:11.134Z] 18:55:11 INFO - GECKO(6045) | [2019-09-21T18:55:11Z WARN audioipc_client] Could not promote audio threads to real-time during initialization.
[task 2019-09-21T18:55:11.151Z] 18:55:11 INFO - GECKO(6045) | ++DOCSHELL 0x7ff0b595f000 == 1 [pid = 6294] [id = {8df2cde8-49fd-4402-aa63-d2955e20e783}]
[task 2019-09-21T18:55:11.315Z] 18:55:11 INFO - GECKO(6045) | ++DOMWINDOW == 1 (0x7ff0b5902f20) [pid = 6294] [serial = 1] [outer = (nil)]
[task 2019-09-21T18:55:11.317Z] 18:55:11 INFO - GECKO(6045) | ++DOMWINDOW == 2 (0x7ff0b58d9800) [pid = 6294] [serial = 2] [outer = 0x7ff0b5902f20]
[task 2019-09-21T18:55:11.620Z] 18:55:11 INFO - GECKO(6045) | ++DOMWINDOW == 3 (0x7ff0b63ca800) [pid = 6294] [serial = 3] [outer = 0x7ff0b5902f20]
[task 2019-09-21T18:55:16.319Z] 18:55:16 INFO - GECKO(6045) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpJ6WNaG.mozrunner/runtests_leaks_tab_pid6332.log
[task 2019-09-21T18:55:18.115Z] 18:55:18 INFO - GECKO(6045) | ExceptionHandler::GenerateDump cloned child 6336
[task 2019-09-21T18:55:18.115Z] 18:55:18 INFO - GECKO(6045) | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2019-09-21T18:55:18.122Z] 18:55:18 INFO - GECKO(6045) | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2019-09-21T18:55:18.670Z] 18:55:18 INFO - GECKO(6045) | Exiting due to channel error.
[task 2019-09-21T18:55:18.678Z] 18:55:18 INFO - GECKO(6045) | Exiting due to channel error.
[task 2019-09-21T18:55:18.678Z] 18:55:18 INFO - GECKO(6045) | Exiting due to channel error.
[task 2019-09-21T18:55:18.678Z] 18:55:18 INFO - GECKO(6045) | Exiting due to channel error.
[task 2019-09-21T18:55:18.678Z] 18:55:18 INFO - GECKO(6045) | Exiting due to channel error.
[task 2019-09-21T18:55:18.678Z] 18:55:18 INFO - GECKO(6045) | Exiting due to channel error.
[task 2019-09-21T18:55:18.687Z] 18:55:18 INFO - GECKO(6045) | Exiting due to channel error.
[task 2019-09-21T18:55:19.811Z] 18:55:19 INFO - GECKO(6045) | [Child 6332, Chrome_ChildThread] WARNING: pipe error: Broken pipe: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 728
[task 2019-09-21T18:55:19.812Z] 18:55:19 INFO - GECKO(6045) | [Child 6332, Chrome_ChildThread] WARNING: pipe error: Broken pipe: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 728
[task 2019-09-21T18:55:19.812Z] 18:55:19 INFO - GECKO(6045) | [Child 6332, Chrome_ChildThread] WARNING: pipe error: Broken pipe: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 728
[task 2019-09-21T18:55:19.812Z] 18:55:19 INFO - GECKO(6045) | [Child 6332, Chrome_ChildThread] WARNING: pipe error: Broken pipe: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 728
[task 2019-09-21T18:55:19.812Z] 18:55:19 INFO - GECKO(6045) | [Child 6332, Chrome_ChildThread] WARNING: pipe error: Broken pipe: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 728
[task 2019-09-21T18:55:19.812Z] 18:55:19 INFO - GECKO(6045) | [Child 6332, Chrome_ChildThread] WARNING: pipe error: Broken pipe: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 728
[task 2019-09-21T18:55:19.813Z] 18:55:19 INFO - GECKO(6045) | [Child 6332, Chrome_ChildThread] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 23
[task 2019-09-21T18:55:19.813Z] 18:55:19 INFO - GECKO(6045) | [Child 6332, Chrome_ChildThread] WARNING: FileDescriptorSet destroyed with unconsumed descriptors: file /builds/worker/workspace/build/src/ipc/chromium/src/chrome/common/file_descriptor_set_posix.cc, line 23
[task 2019-09-21T18:55:19.813Z] 18:55:19 INFO - GECKO(6045) | Exiting due to channel error.
[task 2019-09-21T18:55:19.874Z] 18:55:19 INFO - TEST-INFO | Main app process: exit 11[task 2019-09-21T18:55:19.874Z] 18:55:19 ERROR - TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite
[task 2019-09-21T18:55:19.874Z] 18:55:19 INFO - Buffered messages logged at 18:55:06
[task 2019-09-21T18:55:19.883Z] 18:55:19 INFO - Entering test bound test_profile_feature_preferencereads
[task 2019-09-21T18:55:19.887Z] 18:55:19 INFO - TEST-PASS | tools/profiler/tests/browser/browser_test_feature_preferencereads.js | The profiler is not currently active - true == true -
[task 2019-09-21T18:55:19.888Z] 18:55:19 INFO - Buffered messages finished
[task 2019-09-21T18:55:19.888Z] 18:55:19 ERROR - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_preferencereads.js | application terminated with exit code 11
[task 2019-09-21T18:55:19.889Z] 18:55:19 INFO - runtests.py | Application ran for: 0:00:52.268299
[task 2019-09-21T18:55:19.889Z] 18:55:19 INFO - zombiecheck | Reading PID log: /tmp/tmpbnGVGApidlog
[task 2019-09-21T18:55:19.890Z] 18:55:19 INFO - ==> process 6045 launched child process 6063
[task 2019-09-21T18:55:19.890Z] 18:55:19 INFO - ==> process 6045 launched child process 6099
[task 2019-09-21T18:55:19.891Z] 18:55:19 INFO - ==> process 6045 launched child process 6122
[task 2019-09-21T18:55:19.892Z] 18:55:19 INFO - ==> process 6045 launched child process 6174
[task 2019-09-21T18:55:19.892Z] 18:55:19 INFO - ==> process 6045 launched child process 6205
[task 2019-09-21T18:55:19.892Z] 18:55:19 INFO - ==> process 6045 launched child process 6236
[task 2019-09-21T18:55:19.893Z] 18:55:19 INFO - ==> process 6045 launched child process 6277
[task 2019-09-21T18:55:19.893Z] 18:55:19 INFO - ==> process 6045 launched child process 6294
[task 2019-09-21T18:55:19.894Z] 18:55:19 INFO - ==> process 6045 launched child process 6332
[task 2019-09-21T18:55:19.894Z] 18:55:19 INFO - zombiecheck | Checking for orphan process with PID: 6277
[task 2019-09-21T18:55:19.895Z] 18:55:19 INFO - zombiecheck | Checking for orphan process with PID: 6332
[task 2019-09-21T18:55:19.895Z] 18:55:19 INFO - zombiecheck | Checking for orphan process with PID: 6122
[task 2019-09-21T18:55:19.896Z] 18:55:19 INFO - zombiecheck | Checking for orphan process with PID: 6063
[task 2019-09-21T18:55:19.896Z] 18:55:19 INFO - zombiecheck | Checking for orphan process with PID: 6099
[task 2019-09-21T18:55:19.896Z] 18:55:19 INFO - zombiecheck | Checking for orphan process with PID: 6294
[task 2019-09-21T18:55:19.897Z] 18:55:19 INFO - zombiecheck | Checking for orphan process with PID: 6236
[task 2019-09-21T18:55:19.897Z] 18:55:19 INFO - zombiecheck | Checking for orphan process with PID: 6205
[task 2019-09-21T18:55:19.898Z] 18:55:19 INFO - zombiecheck | Checking for orphan process with PID: 6174
[task 2019-09-21T18:55:19.898Z] 18:55:19 INFO - mozcrash Copy/paste: /builds/worker/workspace/build/linux64-minidump_stackwalk /tmp/tmpJ6WNaG.mozrunner/minidumps/3d9222ee-d9e1-6534-eb10-0b5ae0626b7b.dmp /builds/worker/workspace/build/symbols
[task 2019-09-21T18:55:25.500Z] 18:55:25 INFO - mozcrash Saved minidump as /builds/worker/workspace/build/blobber_upload_dir/3d9222ee-d9e1-6534-eb10-0b5ae0626b7b.dmp
[task 2019-09-21T18:55:25.502Z] 18:55:25 INFO - mozcrash Saved app info as /builds/worker/workspace/build/blobber_upload_dir/3d9222ee-d9e1-6534-eb10-0b5ae0626b7b.extra
[task 2019-09-21T18:55:25.637Z] 18:55:25 INFO - PROCESS-CRASH | tools/profiler/tests/browser/browser_test_feature_preferencereads.js | application crashed [@ JS::AutoAssertNoGC::~AutoAssertNoGC()]
[task 2019-09-21T18:55:25.637Z] 18:55:25 INFO - Crash dump filename: /tmp/tmpJ6WNaG.mozrunner/minidumps/3d9222ee-d9e1-6534-eb10-0b5ae0626b7b.dmp
[task 2019-09-21T18:55:25.638Z] 18:55:25 INFO - Operating system: Linux
[task 2019-09-21T18:55:25.639Z] 18:55:25 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-09-21T18:55:25.639Z] 18:55:25 INFO - CPU: amd64
[task 2019-09-21T18:55:25.639Z] 18:55:25 INFO - family 6 model 85 stepping 4
[task 2019-09-21T18:55:25.639Z] 18:55:25 INFO - 1 CPU
[task 2019-09-21T18:55:25.640Z] 18:55:25 INFO -
[task 2019-09-21T18:55:25.640Z] 18:55:25 INFO - GPU: UNKNOWN[task 2019-09-21T18:55:25.640Z] 18:55:25 INFO -
[task 2019-09-21T18:55:25.641Z] 18:55:25 INFO - Crash reason: SIGSEGV /SEGV_ACCERR
[task 2019-09-21T18:55:25.641Z] 18:55:25 INFO - Crash address: 0x7fd9f47cb2b0
[task 2019-09-21T18:55:25.642Z] 18:55:25 INFO - Process uptime: not available
[task 2019-09-21T18:55:25.642Z] 18:55:25 INFO -
[task 2019-09-21T18:55:25.642Z] 18:55:25 INFO - Thread 57 (crashed)
[task 2019-09-21T18:55:25.642Z] 18:55:25 INFO - 0 libxul.so!JS::AutoAssertNoGC::~AutoAssertNoGC() [GC.cpp:5daa02293ca8a816638db073b5642391822c0872 : 8069 + 0x0]
[task 2019-09-21T18:55:25.645Z] 18:55:25 INFO - rax = 0x000000000062813a rdx = 0x00007fda02cb9070
[task 2019-09-21T18:55:25.646Z] 18:55:25 INFO - rcx = 0x0000000000000002 rbx = 0x000000000062813a
[task 2019-09-21T18:55:25.646Z] 18:55:25 INFO - rsi = 0x0000000000000000 rdi = 0x00007fd9d3cfe7d8
[task 2019-09-21T18:55:25.646Z] 18:55:25 INFO - rbp = 0x00007fd9d3cfe820 rsp = 0x00007fd9d3cfe7c8
[task 2019-09-21T18:55:25.646Z] 18:55:25 INFO - r8 = 0x0000000000000000 r9 = 0x00007fd9d3cfe760
[task 2019-09-21T18:55:25.646Z] 18:55:25 INFO - r10 = 0x00007fda02cb9070 r11 = 0x0000000000000246
[task 2019-09-21T18:55:25.647Z] 18:55:25 INFO - r12 = 0x00007fd9d8de35b0 r13 = 0x00007fd9d8dac338
[task 2019-09-21T18:55:25.647Z] 18:55:25 INFO - r14 = 0x00007fda02cb9048 r15 = 0x00007fd9d3cfe7d8
[task 2019-09-21T18:55:25.647Z] 18:55:25 INFO - rip = 0x00007fd9f47cb2b0
[task 2019-09-21T18:55:25.647Z] 18:55:25 INFO - Found by: given as instruction pointer in context
[task 2019-09-21T18:55:25.647Z] 18:55:25 INFO - 1 libxul.so!ProfileBuffer::AddEntry(mozilla::BlocksRingBuffer&, ProfileBufferEntry const&) [ProfileBuffer.cpp:5daa02293ca8a816638db073b5642391822c0872 : 57 + 0x8]
[task 2019-09-21T18:55:25.647Z] 18:55:25 INFO - rbx = 0x000000000062813a rbp = 0x00007fd9d3cfe820
[task 2019-09-21T18:55:25.648Z] 18:55:25 INFO - rsp = 0x00007fd9d3cfe7d0 r12 = 0x00007fd9d8de35b0
[task 2019-09-21T18:55:25.648Z] 18:55:25 INFO - r13 = 0x00007fd9d8dac338 r14 = 0x00007fda02cb9048
[task 2019-09-21T18:55:25.648Z] 18:55:25 INFO - r15 = 0x00007fd9d3cfe7d8 rip = 0x00007fd9f3be02e6
[task 2019-09-21T18:55:25.649Z] 18:55:25 INFO - Found by: call frame info
[task 2019-09-21T18:55:25.649Z] 18:55:25 INFO - 2 libxul.so!SamplerThread::Run() [ProfileBuffer.cpp:5daa02293ca8a816638db073b5642391822c0872 : 68 + 0xf]
[task 2019-09-21T18:55:25.649Z] 18:55:25 INFO - rbx = 0x0000000bc1518350 rbp = 0x00007fd9d3cfef00
[task 2019-09-21T18:55:25.649Z] 18:55:25 INFO - rsp = 0x00007fd9d3cfe830 r12 = 0x00007fd9d8de35b0
[task 2019-09-21T18:55:25.649Z] 18:55:25 INFO - r13 = 0x00007fd9d8dac338 r14 = 0x00007fd9d3cfe9d8
[task 2019-09-21T18:55:25.649Z] 18:55:25 INFO - r15 = 0x00007fd9d8dac340 rip = 0x00007fd9f3bf42ae
[task 2019-09-21T18:55:25.650Z] 18:55:25 INFO - Found by: call frame info
[task 2019-09-21T18:55:25.650Z] 18:55:25 INFO - 3 libxul.so!ThreadEntry(void*) [platform-linux-android.cpp:5daa02293ca8a816638db073b5642391822c0872 : 375 + 0x5]
[task 2019-09-21T18:55:25.650Z] 18:55:25 INFO - rbx = 0x0000000000000000 rbp = 0x00007fd9d3cfef10
[task 2019-09-21T18:55:25.650Z] 18:55:25 INFO - rsp = 0x00007fd9d3cfef10 r12 = 0x0000000000000000
[task 2019-09-21T18:55:25.651Z] 18:55:25 INFO - r13 = 0x00007ffc820ad4af r14 = 0x0000000000800000
[task 2019-09-21T18:55:25.651Z] 18:55:25 INFO - r15 = 0x00007fd9d95ce6a0 rip = 0x00007fd9f3bf5860
[task 2019-09-21T18:55:25.651Z] 18:55:25 INFO - Found by: call frame info[task 2019-09-21T18:55:25.651Z] 18:55:25 INFO - 4 libpthread-2.23.so + 0x76ba
[task 2019-09-21T18:55:25.651Z] 18:55:25 INFO - rbx = 0x0000000000000000 rbp = 0x0000000000000000
[task 2019-09-21T18:55:25.651Z] 18:55:25 INFO - rsp = 0x00007fd9d3cfef20 r12 = 0x0000000000000000
[task 2019-09-21T18:55:25.652Z] 18:55:25 INFO - r13 = 0x00007ffc820ad4af r14 = 0x0000000000800000
[task 2019-09-21T18:55:25.652Z] 18:55:25 INFO - r15 = 0x00007fd9d95ce6a0 rip = 0x00007fda03ee26ba
[task 2019-09-21T18:55:25.652Z] 18:55:25 INFO - Found by: call frame info
[task 2019-09-21T18:55:25.652Z] 18:55:25 INFO - 5 libc-2.23.so + 0x10741d
[task 2019-09-21T18:55:25.653Z] 18:55:25 INFO - rsp = 0x00007fd9d3cfefc0 rip = 0x00007fda02f6b41d
[task 2019-09-21T18:55:25.653Z] 18:55:25 INFO - Found by: stack scanning

I guess I put the JS::AutoSuppressGCAnalysis in a too-generic spot, which may be called from places where the GC may run in parallel.

We could try moving it to MergeStacks() (where the js rooting hazard was found, see https://bugzilla.mozilla.org/show_bug.cgi?id=1576551#c7 ), but I'm scared that this may also fail: MergeStacks() could be used for a suspended thread that doesn't deal with Javascript (and therefore there won't be any js objects actually used) while another thread runs Javascript and its GC. To be investigated further...

Assignee: nobody → gsquelart
Priority: -- → P1

BlocksRingBuffer had an "entry destructor" to make it a more generic
container, and it was useful during early prototyping of the new profiler
storage (so that we could store owning pointers).
But this entry destructor is stored in an std::function, which gets marked as
a potential GC caller by the js rooting hazard analyzer; and as this bug found,
it's not obvious where to place JS::AutoSuppressGCAnalysis, because profiler
entries (including stacks) could be added on one thread while GC happens
elsewhere, which triggers the embedded AutoAssertNoGC check.

Since we don't actually use the entry destructor facility in the profiler, it's
easier to just get rid of it. As a bonus, it's a small optimization.
Tests that were using an entry destructor now use the State instead, to verify
that entries are pushed and cleared as expected.

If needed in the future outside of the profiler, BlocksRingBuffer could again
include an entry destructor, but it would have to be through templating, so that
the class used in the profiler wouldn't contain an std::function.

Pushed by gsquelart@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7ea3346267bd
Removed unneded BlocksRingBuffer's entry destructor, and ProfilerBuffer's JS::AutoSuppressGCAnalysis - r=gregtatum

https://hg.mozilla.org/mozilla-central/rev/7ea3346267bd

Status: NEW → RESOLVED
Closed: 5 years ago
status-firefox71: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla71
Has Regression Range: --- → yes
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: