1407505 - Intermittent CCov PROCESS-CRASH | tps | application crashed [@ js::jit::ExecutableAllocator::~ExecutableAllocator]

Status: RESOLVED FIXED

(Core :: JavaScript Engine, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: philringnalda [at] gmail.com

https://treeherder.mozilla.org/logviewer.html#?job_id=136051294&repo=mozilla-central

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

Comment 1

[Joel Maher ( :jmaher ) (UTC -8)]

after bug 1402473 landed, we started seeing this crash.

here is a recent log:
https://public-artifacts.taskcluster.net/SjwzQx-8RdmegGqinUbT2w/0/public/logs/live_backing.log

and here is some of the stack:
task 2017-10-09T23:22:55.106Z] 23:22:55     INFO -  Thread 0 (crashed)
[task 2017-10-09T23:22:55.106Z] 23:22:55     INFO -   0  libxul.so!js::jit::ExecutableAllocator::~ExecutableAllocator [ExecutableAllocator.cpp:2ed5e7fbf39e : 131 + 0x28]
[task 2017-10-09T23:22:55.107Z] 23:22:55     INFO -      rax = 0x00007ffe23876710   rdx = 0x0000000000000000
[task 2017-10-09T23:22:55.107Z] 23:22:55     INFO -      rcx = 0x00007fb56a1a72ad   rbx = 0x000000000224f2a0
[task 2017-10-09T23:22:55.108Z] 23:22:55     INFO -      rsi = 0x00007fb56a476770   rdi = 0x00007fb56a475540
[task 2017-10-09T23:22:55.108Z] 23:22:55     INFO -      rbp = 0x00007ffe238766d0   rsp = 0x00007ffe23876680
[task 2017-10-09T23:22:55.109Z] 23:22:55     INFO -       r8 = 0x00007fb56a476770    r9 = 0x00007fb56b53e740
[task 2017-10-09T23:22:55.109Z] 23:22:55     INFO -      r10 = 0x0000000000000000   r11 = 0x0000000000000000
[task 2017-10-09T23:22:55.110Z] 23:22:55     INFO -      r12 = 0x00007ffe238766f0   r13 = 0x000000000224f2a0
[task 2017-10-09T23:22:55.111Z] 23:22:55     INFO -      r14 = 0x000000000218a470   r15 = 0x000000000218a300
[task 2017-10-09T23:22:55.112Z] 23:22:55     INFO -      rip = 0x00007fb5561dca00
[task 2017-10-09T23:22:55.113Z] 23:22:55     INFO -      Found by: given as instruction pointer in context
[task 2017-10-09T23:22:55.114Z] 23:22:55     INFO -   1  libxul.so!js::jit::JitRuntime::~JitRuntime [ProtectedData.h:2ed5e7fbf39e : 66 + 0x2c]
[task 2017-10-09T23:22:55.114Z] 23:22:55     INFO -      rbx = 0x000000000224f2a0   rbp = 0x00007ffe23876710
[task 2017-10-09T23:22:55.115Z] 23:22:55     INFO -      rsp = 0x00007ffe238766e0   r12 = 0x00007ffe238766f0
[task 2017-10-09T23:22:55.116Z] 23:22:55     INFO -      r13 = 0x000000000224f2a0   r14 = 0x000000000218a470
[task 2017-10-09T23:22:55.117Z] 23:22:55     INFO -      r15 = 0x000000000218a300   rip = 0x00007fb555545ee8
[task 2017-10-09T23:22:55.118Z] 23:22:55     INFO -      Found by: call frame info
[task 2017-10-09T23:22:55.119Z] 23:22:55     INFO -   2  libxul.so!JSRuntime::destroyRuntime [Utility.h:2ed5e7fbf39e : 511 + 0x10]
[task 2017-10-09T23:22:55.120Z] 23:22:55     INFO -      rbx = 0x00000000020ac6c0   rbp = 0x00007ffe23876770
[task 2017-10-09T23:22:55.121Z] 23:22:55     INFO -      rsp = 0x00007ffe23876720   r12 = 0x00007ffe23876730
[task 2017-10-09T23:22:55.122Z] 23:22:55     INFO -      r13 = 0x000000000224f2a0   r14 = 0x000000000218a470
[task 2017-10-09T23:22:55.123Z] 23:22:55     INFO -      r15 = 0x000000000218a300   rip = 0x00007fb555cf3a6e
[task 2017-10-09T23:22:55.123Z] 23:22:55     INFO -      Found by: call frame info
[task 2017-10-09T23:22:55.124Z] 23:22:55     INFO -   3  libxul.so!js::DestroyContext [jscntxt.cpp:2ed5e7fbf39e : 249 + 0xc]
[task 2017-10-09T23:22:55.125Z] 23:22:55     INFO -      rbx = 0x00000000021927d0   rbp = 0x00007ffe23876810
[task 2017-10-09T23:22:55.126Z] 23:22:55     INFO -      rsp = 0x00007ffe23876780   r12 = 0x00000000020ac6c0
[task 2017-10-09T23:22:55.128Z] 23:22:55     INFO -      r13 = 0x00000000020ac6c0   r14 = 0x000000000218a470
[task 2017-10-09T23:22:55.128Z] 23:22:55     INFO -      r15 = 0x000000000218a300   rip = 0x00007fb555954306
[task 2017-10-09T23:22:55.129Z] 23:22:55     INFO -      Found by: call frame info
[task 2017-10-09T23:22:55.130Z] 23:22:55     INFO -   4  libxul.so!JS_DestroyContext [jsapi.cpp:2ed5e7fbf39e : 510 + 0x5]
[task 2017-10-09T23:22:55.131Z] 23:22:55     INFO -      rbx = 0x000000000218a308   rbp = 0x00007ffe23876820
[task 2017-10-09T23:22:55.131Z] 23:22:55     INFO -      rsp = 0x00007ffe23876820   r12 = 0x000000000218a3c0
[task 2017-10-09T23:22:55.132Z] 23:22:55     INFO -      r13 = 0x000000000218a408   r14 = 0x000000000218a470
[task 2017-10-09T23:22:55.132Z] 23:22:55     INFO -      r15 = 0x000000000218a300   rip = 0x00007fb555954701
[task 2017-10-09T23:22:55.133Z] 23:22:55     INFO -      Found by: call frame info
[task 2017-10-09T23:22:55.134Z] 23:22:55     INFO -   5  libxul.so!mozilla::CycleCollectedJSContext::~CycleCollectedJSContext [CycleCollectedJSContext.cpp:2ed5e7fbf39e : 99 + 0x13]
[task 2017-10-09T23:22:55.134Z] 23:22:55     INFO -      rbx = 0x000000000218a308   rbp = 0x00007ffe23876890
[task 2017-10-09T23:22:55.135Z] 23:22:55     INFO -      rsp = 0x00007ffe23876830   r12 = 0x000000000218a3c0
[task 2017-10-09T23:22:55.136Z] 23:22:55     INFO -      r13 = 0x000000000218a408   r14 = 0x000000000218a470
[task 2017-10-09T23:22:55.137Z] 23:22:55     INFO -      r15 = 0x000000000218a300   rip = 0x00007fb550eb46d1
[task 2017-10-09T23:22:55.137Z] 23:22:55     INFO -      Found by: call frame info
[task 2017-10-09T23:22:55.138Z] 23:22:55     INFO -   6  libxul.so!XPCJSContext::~XPCJSContext [XPCJSContext.cpp:2ed5e7fbf39e : 871 + 0x3a]
[task 2017-10-09T23:22:55.140Z] 23:22:55     INFO -      rbx = 0x000000000218a300   rbp = 0x00007ffe238768b0
[task 2017-10-09T23:22:55.140Z] 23:22:55     INFO -      rsp = 0x00007ffe238768a0   r12 = 0x0000000002029dc0
[task 2017-10-09T23:22:55.141Z] 23:22:55     INFO -      r13 = 0x0000000002063028   r14 = 0x00007fb550eed0b2
[task 2017-10-09T23:22:55.141Z] 23:22:55     INFO -      r15 = 0x00000000056a2cf0   rip = 0x00007fb551a151f4
[task 2017-10-09T23:22:55.142Z] 23:22:55     INFO -      Found by: call frame info


this is perma failing on code coverage builds- we do run code coverage builds in "debug" mode so we can accurately get all the information from each process, this is different as talos is only run in "opt" mode normally.

:jonco, do you have any ideas on how to solve this?

Comment 2

[Jon Coppeard (:jonco)]

Well I guess that confirms the diagnosis in bug 1402473; this is just failing later on for the same reason.

It's this assertion failing:

    MOZ_ASSERT_IF(m_pools.initialized(), m_pools.empty()); 

It's strange we're not seeing the assertion message.  Maybe the log is getting truncated or something.

Comment 3

[Jon Coppeard (:jonco)]

Attachment: bug1407505-exec-pools-assertion

Similar fix as for the other bug.  Relax the assertion if the embedding leaked GC things at shutdown.

(These bugs are annoying.  I filed bug 1407593 for the root cause.)

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/3d373c760a7f
Relax assertion in ExecutableAllocator destructor if the embedding leaked r=jandem

Comment 5

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/3d373c760a7f

Comment 6

[Joel Maher ( :jmaher ) (UTC -8)]

now we have a new failure:
[task 2017-10-13T08:22:11.997Z] 08:22:11     INFO -   0  libxul.so!js::jit::ReleaseProcessExecutableMemory [ProcessExecutableMemory.cpp:23d2b8b32713 : 483 + 0x28]
[task 2017-10-13T08:22:11.997Z] 08:22:11     INFO -      rax = 0x00007ffc4f58b5b0   rdx = 0x0000000000000000
[task 2017-10-13T08:22:11.997Z] 08:22:11     INFO -      rcx = 0x00007f3edb0492ad   rbx = 0x00007ffc4f58b5a8
[task 2017-10-13T08:22:11.998Z] 08:22:11     INFO -      rsi = 0x00007f3edb318770   rdi = 0x00007f3edb317540
[task 2017-10-13T08:22:11.998Z] 08:22:11     INFO -      rbp = 0x00007ffc4f58b560   rsp = 0x00007ffc4f58b560
[task 2017-10-13T08:22:11.998Z] 08:22:11     INFO -       r8 = 0x00007f3edb318770    r9 = 0x00007f3edc3e0740
[task 2017-10-13T08:22:11.999Z] 08:22:11     INFO -      r10 = 0x0000000000000000   r11 = 0x0000000000000000
[task 2017-10-13T08:22:11.999Z] 08:22:11     INFO -      r12 = 0x00007ffc4f58b5b8   r13 = 0x00007ffc4f58b5b0
[task 2017-10-13T08:22:12.000Z] 08:22:11     INFO -      r14 = 0x00007f3ec1ccc49a   r15 = 0x0000000005c9c270
[task 2017-10-13T08:22:12.000Z] 08:22:11     INFO -      rip = 0x00007f3ec6535aa0
[task 2017-10-13T08:22:12.000Z] 08:22:12     INFO -      Found by: given as instruction pointer in context
[task 2017-10-13T08:22:12.000Z] 08:22:12     INFO -   1  libxul.so!JS_ShutDown [Initialization.cpp:23d2b8b32713 : 199 + 0x5]
[task 2017-10-13T08:22:12.001Z] 08:22:12     INFO -      rbx = 0x00007ffc4f58b5a8   rbp = 0x00007ffc4f58b570
[task 2017-10-13T08:22:12.001Z] 08:22:12     INFO -      rsp = 0x00007ffc4f58b570   r12 = 0x00007ffc4f58b5b8
[task 2017-10-13T08:22:12.001Z] 08:22:12     INFO -      r13 = 0x00007ffc4f58b5b0   r14 = 0x00007f3ec1ccc49a
[task 2017-10-13T08:22:12.001Z] 08:22:12     INFO -      r15 = 0x0000000005c9c270   rip = 0x00007f3ec6a9ded4
[task 2017-10-13T08:22:12.002Z] 08:22:12     INFO -      Found by: call frame info
[task 2017-10-13T08:22:12.002Z] 08:22:12     INFO -   2  libxul.so!mozilla::ShutdownXPCOM [XPCOMInit.cpp:23d2b8b32713 : 1023 + 0x5]
[task 2017-10-13T08:22:12.003Z] 08:22:12     INFO -      rbx = 0x00007ffc4f58b5a8   rbp = 0x00007ffc4f58b600
[task 2017-10-13T08:22:12.003Z] 08:22:12     INFO -      rsp = 0x00007ffc4f58b580   r12 = 0x00007ffc4f58b5b8
[task 2017-10-13T08:22:12.003Z] 08:22:12     INFO -      r13 = 0x00007ffc4f58b5b0   r14 = 0x00007f3ec1ccc49a
[task 2017-10-13T08:22:12.004Z] 08:22:12     INFO -      r15 = 0x0000000005c9c270   rip = 0x00007f3ec1d7ca06
[task 2017-10-13T08:22:12.004Z] 08:22:12     INFO -      Found by: call frame info


It seems like we fix one failure, then we find the next one, repeat.

:jonco, does it make sense to fix this failure as we have done in the past (and the next ones we see), or work on bug 1407593?

Comment 7

[Jon Coppeard (:jonco)]

(In reply to Joel Maher ( :jmaher) (UTC-5) from comment #6)
Oh man.  I'll try and push on that bug.

Comment 8

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

New failure is being tracked in bug 1408403.

Comment 9

[Intermittent Failures Robot]

17 failures in 947 pushes (0.018 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* mozilla-central: 17

Platform breakdown:
* linux64-ccov: 17

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1407505&startday=2017-10-09&endday=2017-10-15&tree=all