Closed Bug 1464621 Opened Last year Closed 4 months ago

Intermittent toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | assertion count * is more than expected 0 assertions

Categories

(Core :: JavaScript: GC, defect, P5)

defect

Tracking

()

RESOLVED FIXED
mozilla68
Tracking Status
firefox68 --- fixed

People

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

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown][stockwell needswork:owner])

Attachments

(1 file)

Filed by: aciure [at] mozilla.com

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

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

14:05:29     INFO -  27 INFO TEST-OK | toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | took 2689ms
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | [Child 216, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file z:/build/build/src/xpcom/threads/nsThread.cpp, line 803
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
14:05:29     INFO -  GECKO(2036) | [Child 4164, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file z:/build/build/src/xpcom/threads/nsThread.cpp, line 803
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | [Child 3988, Main Thread] WARNING: NS_ENSURE_TRUE(maybeContext) failed: file z:/build/build/src/xpcom/threads/nsThread.cpp, line 803
14:05:29     INFO -  GECKO(2036) | [Parent 2036, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
14:05:29     INFO -  GECKO(2036) | ++DOMWINDOW == 57 (00000299EC294800) [pid = 2036] [serial = 57] [outer = 00000299DBA0EC00]
14:05:29    ERROR -  28 INFO TEST-UNEXPECTED-FAIL | toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | assertion count 5 is more than expected 0 assertions
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → INCOMPLETE
https://treeherder.mozilla.org/logviewer.html#?job_id=192568240&repo=mozilla-beta&lineNumber=1807
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | assertion count 5 is more than expected 0 assertions → Intermittent toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | assertion count 5/2 is more than expected 0 assertions
Summary: Intermittent toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | assertion count 5/2 is more than expected 0 assertions → Intermittent toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | assertion count * is more than expected 0 assertions

There have been 30 failures within the last 7 days:

  • 5 failures on Linux x64 debug
  • 2 failures on Windows 10 x64 ccov debug
  • 23 failures on Linux x64 CCov debug

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=236602052&repo=mozilla-inbound&lineNumber=2689

[task 2019-03-28T13:22:22.886Z] 13:22:22 INFO - GECKO(1220) | MEMORY STAT | vsize 1815MB | residentFast 371MB | heapAllocated 142MB
[task 2019-03-28T13:22:22.887Z] 13:22:22 INFO - TEST-OK | toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | took 5672ms
[task 2019-03-28T13:22:22.887Z] 13:22:22 INFO - GECKO(1220) | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2019-03-28T13:22:22.887Z] 13:22:22 INFO - GECKO(1220) | [Parent 1220, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x80004005: file /builds/worker/workspace/build/src/docshell/shistory/nsSHistory.cpp, line 1204
[task 2019-03-28T13:22:22.887Z] 13:22:22 INFO - GECKO(1220) | [Parent 1220, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, false) failed with result 0x80004005: file /builds/worker/workspace/build/src/docshell/shistory/nsSHistory.cpp, line 1204
[task 2019-03-28T13:22:22.888Z] 13:22:22 INFO - GECKO(1220) | ++DOMWINDOW == 57 (0x7f2612e82000) [pid = 1220] [serial = 66] [outer = 0x7f26102de020]
[task 2019-03-28T13:22:22.888Z] 13:22:22 INFO - GECKO(1220) | --DOCSHELL 0x7f4b778a5800 == 0 [pid = 1326] [id = {ab3def89-aced-49c9-921a-3dafd639a8dd}] [url = about:blank]
[task 2019-03-28T13:22:22.888Z] 13:22:22 INFO - GECKO(1220) | --DOMWINDOW == 2 (0x7f4b778fad40) [pid = 1326] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2019-03-28T13:22:22.889Z] 13:22:22 INFO - GECKO(1220) | --DOMWINDOW == 1 (0x7f4b78b6d800) [pid = 1326] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2019-03-28T13:22:22.889Z] 13:22:22 INFO - GECKO(1220) | --DOMWINDOW == 0 (0x7f4b77968800) [pid = 1326] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-03-28T13:22:22.889Z] 13:22:22 INFO - GECKO(1220) | nsStringStats
[task 2019-03-28T13:22:22.890Z] 13:22:22 INFO - GECKO(1220) | => mAllocCount: 7201
[task 2019-03-28T13:22:22.890Z] 13:22:22 INFO - GECKO(1220) | => mReallocCount: 0
[task 2019-03-28T13:22:22.891Z] 13:22:22 INFO - GECKO(1220) | => mFreeCount: 7201
[task 2019-03-28T13:22:22.891Z] 13:22:22 INFO - GECKO(1220) | => mShareCount: 4621
[task 2019-03-28T13:22:22.892Z] 13:22:22 INFO - GECKO(1220) | => mAdoptCount: 369
[task 2019-03-28T13:22:22.892Z] 13:22:22 INFO - GECKO(1220) | => mAdoptFreeCount: 369
[task 2019-03-28T13:22:22.893Z] 13:22:22 INFO - GECKO(1220) | => Process ID: 1326, Thread ID: 139962543044416
[task 2019-03-28T13:22:22.893Z] 13:22:22 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | assertion count 7 is more than expected 0 assertions

Whiteboard: [stockwell needswork]

There are 28 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-04-29&endday=2019-05-06&tree=trunk&bug=1464621

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=244880771&repo=autoland&lineNumber=9360

[task 2019-05-06T15:34:05.407Z] 15:34:05 INFO - TEST-START | toolkit/components/aboutmemory/tests/test_aboutmemory5.xul
[task 2019-05-06T15:34:12.829Z] 15:34:12 INFO - TEST-OK | toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | took 7415ms
[task 2019-05-06T15:34:12.914Z] 15:34:12 INFO - GECKO(2836) | --DOCSHELL 0x7fd7ecba3000 == 0 [pid = 2953] [id = {101a1bce-462c-44cb-b462-a1aad4b8ce9f}] [url = about:blank]
[task 2019-05-06T15:34:12.922Z] 15:34:12 INFO - GECKO(2836) | --DOCSHELL 0x7f6c56fa3000 == 0 [pid = 2977] [id = {5a73c60e-af7c-454e-a9bf-f90d8e1d9e53}] [url = about:blank]
[task 2019-05-06T15:34:12.951Z] 15:34:12 INFO - GECKO(2836) | ++DOMWINDOW == 63 (0x7ff5ba96a400) [pid = 2836] [serial = 69] [outer = 0x7ff5d2b032e0]
[task 2019-05-06T15:34:12.952Z] 15:34:12 INFO - GECKO(2836) | --DOCSHELL 0x7f4f620a4800 == 0 [pid = 2932] [id = {13821941-80d2-402d-a41b-e4e505ebd207}] [url = about:blank]
[task 2019-05-06T15:34:13.014Z] 15:34:13 INFO - GECKO(2836) | --DOMWINDOW == 1 (0x7f4f63052d40) [pid = 2932] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2019-05-06T15:34:13.015Z] 15:34:13 INFO - GECKO(2836) | --DOMWINDOW == 0 (0x7f4f62f4e000) [pid = 2932] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-05-06T15:34:13.057Z] 15:34:13 INFO - GECKO(2836) | nsStringStats
[task 2019-05-06T15:34:13.058Z] 15:34:13 INFO - GECKO(2836) | => mAllocCount: 7621
[task 2019-05-06T15:34:13.059Z] 15:34:13 INFO - GECKO(2836) | => mReallocCount: 0
[task 2019-05-06T15:34:13.060Z] 15:34:13 INFO - GECKO(2836) | => mFreeCount: 7621
[task 2019-05-06T15:34:13.061Z] 15:34:13 INFO - GECKO(2836) | => mShareCount: 4862
[task 2019-05-06T15:34:13.063Z] 15:34:13 INFO - GECKO(2836) | => mAdoptCount: 385
[task 2019-05-06T15:34:13.064Z] 15:34:13 INFO - GECKO(2836) | => mAdoptFreeCount: 385
[task 2019-05-06T15:34:13.065Z] 15:34:13 INFO - GECKO(2836) | => Process ID: 2932, Thread ID: 139979364464448
[task 2019-05-06T15:34:13.113Z] 15:34:13 INFO - GECKO(2836) | --DOMWINDOW == 1 (0x7fd7ecbdbd40) [pid = 2953] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2019-05-06T15:34:13.115Z] 15:34:13 INFO - GECKO(2836) | --DOMWINDOW == 0 (0x7fd7ed468c00) [pid = 2953] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-05-06T15:34:13.134Z] 15:34:13 INFO - GECKO(2836) | --DOMWINDOW == 1 (0x7f6c57fa3d40) [pid = 2977] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2019-05-06T15:34:13.135Z] 15:34:13 INFO - GECKO(2836) | --DOMWINDOW == 0 (0x7f6c57879000) [pid = 2977] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-05-06T15:34:13.156Z] 15:34:13 INFO - GECKO(2836) | nsStringStats
[task 2019-05-06T15:34:13.156Z] 15:34:13 INFO - GECKO(2836) | => mAllocCount: 7560
[task 2019-05-06T15:34:13.156Z] 15:34:13 INFO - GECKO(2836) | => mReallocCount: 0
[task 2019-05-06T15:34:13.158Z] 15:34:13 INFO - GECKO(2836) | => mFreeCount: 7560
[task 2019-05-06T15:34:13.158Z] 15:34:13 INFO - GECKO(2836) | => mShareCount: 4804
[task 2019-05-06T15:34:13.159Z] 15:34:13 INFO - GECKO(2836) | => mAdoptCount: 385
[task 2019-05-06T15:34:13.160Z] 15:34:13 INFO - GECKO(2836) | => mAdoptFreeCount: 385
[task 2019-05-06T15:34:13.161Z] 15:34:13 INFO - GECKO(2836) | => Process ID: 2953, Thread ID: 140565806548800
[task 2019-05-06T15:34:13.197Z] 15:34:13 INFO - GECKO(2836) | nsStringStats
[task 2019-05-06T15:34:13.197Z] 15:34:13 INFO - GECKO(2836) | => mAllocCount: 7522
[task 2019-05-06T15:34:13.198Z] 15:34:13 INFO - GECKO(2836) | => mReallocCount: 0
[task 2019-05-06T15:34:13.199Z] 15:34:13 INFO - GECKO(2836) | => mFreeCount: 7522
[task 2019-05-06T15:34:13.200Z] 15:34:13 INFO - GECKO(2836) | => mShareCount: 4789
[task 2019-05-06T15:34:13.200Z] 15:34:13 INFO - GECKO(2836) | => mAdoptCount: 385
[task 2019-05-06T15:34:13.201Z] 15:34:13 INFO - GECKO(2836) | => mAdoptFreeCount: 385
[task 2019-05-06T15:34:13.202Z] 15:34:13 INFO - GECKO(2836) | => Process ID: 2977, Thread ID: 140103733258048
[task 2019-05-06T15:34:13.281Z] 15:34:13 INFO - TEST-UNEXPECTED-FAIL | toolkit/components/aboutmemory/tests/test_aboutmemory5.xul | assertion count 4 is more than expected 0 assertions
[task 2019-05-06T15:34:13.281Z] 15:34:13 INFO - TEST-START | toolkit/components/aboutmemory/tests/test_aboutmemory6.xul

Nicholas, could you please assign this to someone?

Flags: needinfo?(n.nethercote)
Whiteboard: [stockwell unknown] → [stockwell unknown][stockwell needswork:owner]

The assertions are:

###!!! ASSERTION: Invalid value (-1032192 / 268986463) for explicit/js-non-window/(3 tiny)/gc-heap/unused-arenas: 'false', file aboutMemory.js, line 0

I guess this means that unused-arenas are negative? Jon, do you have any ideas why unused-areans might be returning negative values?

I'm going to move this to the JS GC component on the assumption that the memory reporter for unused-arenas is buggy.

Component: about:memory → JavaScript: GC
Flags: needinfo?(n.nethercote) → needinfo?(jcoppeard)
Product: Toolkit → Core

The rest of the assertions in the log I looked at are:
###!!! ASSERTION: Invalid value (-393216 / 101411992) for js-main-runtime/gc-heap/(2 tiny): 'false', file aboutMemory.js, line 0
###!!! ASSERTION: Invalid value (-1032192 / 101411992) for js-main-runtime/gc-heap/(2 tiny)/unused-arenas: 'false', file aboutMemory.js, line 0
###!!! ASSERTION: Invalid value (-1032192 / 40542208) for js-main-runtime-gc-heap-committed/unused/arenas: 'false', file aboutMemory.js, line 0

The code for the assertion is this:
if (!gIsDiff && !(0 <= aT._amount && aT._amount <= aRoot._amount)) {
tIsInvalid = true;
let unsafePath = aUnsafeNames.join("/");
gUnsafePathsWithInvalidValuesForThisProcess.push(unsafePath);
reportAssertionFailure(
Invalid value (${aT._amount} / ${aRoot._amount}) for +
flipBackslashes(unsafePath));
}

So the unused-arenas thing is negative? Somehow?

I looked at my own browsing session, and unused-arenas is 0 everywhere, which seems odd but maybe that's expected.

rtStats->gcHeapUnusedArenas is a size_t, I think, so I'm not sure how a negative value can get in there. Maybe there was an underflow when computing it (it involves a lot of subtraction), creating a very large 64 bit value, that overflowed back into a negative number when it got passed as a signed int64 in nsIHandleReportCallback::callback?

I added some debugging printfs to the calculation of gcHeapUnusedArenas and managed to make it fail in a try build:

[task 2019-05-08T14:16:13.129Z] 14:16:13 INFO - gcHeapChunkTotal 20971520
[task 2019-05-08T14:16:13.129Z] 14:16:13 INFO - gcHeapDecommittedArenas 2043904
[task 2019-05-08T14:16:13.129Z] 14:16:13 INFO - gcHeapUnusedChunks 0
[task 2019-05-08T14:16:13.129Z] 14:16:13 INFO - unusedGCThings 3136576
[task 2019-05-08T14:16:13.129Z] 14:16:13 INFO - gcHeapChunkAdmin 327680
[task 2019-05-08T14:16:13.129Z] 14:16:13 INFO - gcHeapArenaAdmin 379984
[task 2019-05-08T14:16:13.129Z] 14:16:13 INFO - gcHeapGCThings 16115568
[task 2019-05-08T14:16:13.129Z] 14:16:13 INFO - other total 22003712

Here "other total" > gcHeapChunkTotal so something's up...

One thing that can go wrong is that an incremental GC can free chunks after we count them at the start of CollectRuntimeStatsHelper. This happens before we call IterateChunks, which will finish any ongoing incremental GC. I don't know if that is the only problem here but I'll fix that first and if this persists I'll take another look.

Flags: needinfo?(jcoppeard)
Pushed by jcoppeard@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e153188e2d93
Ensure we finish any ongoing incremental GC before collecting stats for memory reporting r=sfink?
Status: REOPENED → RESOLVED
Closed: Last year4 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla68
Assignee: nobody → jcoppeard
You need to log in before you can comment on or make changes to this bug.