1450128 - Assertion failure: pages_.empty(), at /builds/worker/workspace/build/src/js/src/jit/ProcessExecutableMemory.cpp:492

Status: RESOLVED FIXED

(Calendar :: General, defect)

Description

[Jorg K (CEST = GMT+2)]

Assertion failure: pages_.empty(), at /builds/worker/workspace/build/src/js/src/jit/ProcessExecutableMemory.cpp:492
PROCESS-CRASH | testDummy.js | application crashed [@ ProcessExecutableMemory::release()]

Seen in Thunderbird Mozmill testing:
https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=bbad34510f140583fd3c0faac7d5b5558c8a2b99&selectedJob=171114874
https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=bbad34510f140583fd3c0faac7d5b5558c8a2b99&selectedJob=171115665

Logs:
https://taskcluster-artifacts.net/axLxh0__Sk-uHHbfV4UNlQ/0/public/logs/live_backing.log
https://taskcluster-artifacts.net/bh1vz3B0Spy1G7YhVlXuVA/0/public/logs/live_backing.log
Search for
ERROR: GC found live Cell

Let me know if I can assist with testing patches.

Comment 1

[Intermittent Failures Robot]

3 failures in 718 pushes (0.004 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* comm-central: 3

Platform breakdown:
* osx-10-10: 1
* linux64: 1
* linux32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1450128&startday=2018-03-26&endday=2018-04-01&tree=trunk

Comment 2

[Jorg K (CEST = GMT+2)]

Tooru-san, how can I draw some attention to this bug. It causes perma-red test failures for us.

Comment 3

[Tooru Fujisawa [:arai]]

bug 1290567 may contain some hints, what's the issue and how to figure out the root cause.

Comment 4

[Jorg K (CEST = GMT+2)]

Hmm, but I really don't have time to dig around those internals. Isn't the JS team interested?

Comment 5

[Jan de Mooij [:jandem]]

(In reply to Jorg K (GMT+1) from comment #4)
> Isn't the JS team interested?

I'm interested, but this looks more like a leak in Thunderbird code than a problem in the JS engine. This assertion is important and correct and we shouldn't remove it.

Do you know when this started?

Comment 6

[Jan de Mooij [:jandem]]

Looking at the log, it's likely this JitCode*:

  14:06:42     INFO -  ERROR: GC found live Cell 0x11302add0 of kind JITCODE at shutdown

There's also a bunch of functions and scripts:

  14:06:42     INFO -  ERROR: GC found live Cell 0x1143af040 of kind SCRIPT at shutdown

One thing you could try is to add something like this to the code where we print this line (ArenaLists::checkEmptyArenaList):

if (kind == AllocKind::SCRIPT) {
    JSScript* script = (JSScript*)t;
    fprintf(stderr, "Script: %s:%u\n", script->filename(), script->lineno());
}

That might tell you which scripts are still live when we shut down.

Comment 7

[Jorg K (CEST = GMT+2)]

(In reply to Jan de Mooij [:jandem] from comment #5)
> Do you know when this started?
Yes, with the job mentioned in comment #0:
https://treeherder.mozilla.org/#/jobs?repo=comm-central&revision=bbad34510f140583fd3c0faac7d5b5558c8a2b99&selectedJob=171114874

In this changeset
https://hg.mozilla.org/comm-central/rev/784233e550fda3f0cdafdc18642c4c326077817e
I created a dummy test for calendar's Mozmill suite and that's when that started.

I can't tell whether this is a regressions coming from M-C since before this push Mozmill was broken for a few days, so the regression range would be a few days from when it was last working, but on a different set of tests, not the dummy one.

I can add the print you suggested.

Comment 8

[Jorg K (CEST = GMT+2)]

https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=b0ede0c54ca41b7ffab5f9334955493d920eb3ab
Based on:
https://hg.mozilla.org/try/rev/cc9698e2a0d11f09e53f53416f102c8c5d83a1a9

Comment 9

[Jorg K (CEST = GMT+2)]

https://taskcluster-artifacts.net/ZntC07G3R06dWdyhCjjOrA/0/public/logs/live_backing.log
shows 20 of these with varying line numbers:
02:15:34     INFO -  ERROR: GC found 41 live Cells at shutdown
02:15:34     INFO -  ERROR: GC found live Cell 0x116abb040 of kind SCRIPT at shutdown
02:15:34     INFO -  Script: resource://gre/modules/TelemetrySession.jsm:927

Where from here?

Comment 10

[Jan de Mooij [:jandem]]

(In reply to Jorg K (GMT+1) from comment #9)
> 02:15:34     INFO -  Script: resource://gre/modules/TelemetrySession.jsm:927
> 
> Where from here?

So this suggests there's a TelemetrySession thing that's not dead after the final GC and that's probably hanging on to scripts and JIT code, hence the assertion failure.

Andrew, any ideas on how they can track this down?

Comment 11

[Andrew McCreight [:mccr8]]

It looks like this test suite runs no leak checking, because I don't see "leakcheck" or "BloatView" anywhere in the log that you linked. This assertion just happens to do leak checking. It looks like the patch you landed removes a bunch of tests.

Likely what is happening is that there's some telemetry code that runs shortly after startup, and is normally cleaned up by the time you shut down, but now that you are closing almost immediately, it does not have time to clean up (glancing at the telemetry code, maybe you are shutting down before telemetry has time to fully set up, where it registers some cleanup code).

We've had some similar issues in Firefox with test suites that don't run for long, though there the problem was safe browsing, not telemetry.

Anyways, I would just add some kind of delay to this test so it waits like 5 seconds before it exits, and see if that helps. Otherwise you'll end up spending a bunch of time tracking down everything in the browser that gets set up in the first few seconds of uptime, and figuring out how to disable it or make it shutdown quickly

Comment 12

[Jorg K (CEST = GMT+2)]

I tried with 1 second sleep in the test two days ago and that didn't make a difference. I'll try with 5 seconds now.

Comment 13

[Jorg K (CEST = GMT+2)]

Waiting 5 seconds didn't help:
https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=b072a25500e00f8f01c6216bb39915f3d05b1b13&selectedJob=173635855

I can try 20 seconds.

Comment 14

[Jorg K (CEST = GMT+2)]

Oops, my mistake, the sleep I added din't actually get executed, new try:
https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=08a59d469548734017a73af8ee6294677295240b

Comment 15

[Jorg K (CEST = GMT+2)]

Sleeping 20 seconds (and a dump) fixed the problem.

Comment 16

[Jorg K (CEST = GMT+2)]

Attachment: sleep.patch

Comment 17

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/fc93de1b8856
Make testDummy.js do something (sleep) to avoid quick shutdown and crash (suggestion by Andrew McCreight). rs=bustage-fix