1653640 - Intermittent tools/profiler/tests/browser/browser_test_feature_nostacksampling.js | Uncaught exception - at chrome://mochitests/content/browser/tools/profiler/tests/browser/head.js:42 - Error: Could not find the content process.

Status: RESOLVED INCOMPLETE

(Core :: Gecko Profiler, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=310189595&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/CHBT1N7vQlW-b-nuB-qxUA/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-07-17T17:01:29.939Z] 17:01:29 INFO - TEST-START | tools/profiler/tests/browser/browser_test_feature_nostacksampling.js
[task 2020-07-17T17:01:29.955Z] 17:01:29 INFO - GECKO(18480) | [Parent 18480, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:29.971Z] 17:01:29 INFO - GECKO(18480) | [Child 18789: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f1f313a8800 == 0 [pid = 18789] [id = {7c05c0c2-5370-4863-9b30-d2db30293807}] [url = http://example.com/browser/tools/profiler/tests/browser/do_work_500ms.html]
[task 2020-07-17T17:01:29.972Z] 17:01:29 INFO - GECKO(18480) | [Child 18588, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:29.976Z] 17:01:29 INFO - GECKO(18480) | [Child 18916, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:29.978Z] 17:01:29 INFO - GECKO(18480) | [Child 18608, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:29.978Z] 17:01:29 INFO - GECKO(18480) | [Child 18689, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:29.981Z] 17:01:29 INFO - GECKO(18480) | [Child 18793, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:29.981Z] 17:01:29 INFO - GECKO(18480) | [Child 18873, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:29.982Z] 17:01:29 INFO - GECKO(18480) | [Child 18665, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:30.022Z] 17:01:30 INFO - GECKO(18480) | [Child 18793: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f62165a9800 == 1 [pid = 18793] [id = {9f6b98d5-59e7-4b4d-b4ee-4ea6bf93d529}]
[task 2020-07-17T17:01:30.030Z] 17:01:30 INFO - GECKO(18480) | [Child 18789: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0x7f1f5d8fb6f0) [pid = 18789] [serial = 1] [outer = (nil)] [url = http://example.com/browser/tools/profiler/tests/browser/do_work_500ms.html]
[task 2020-07-17T17:01:30.030Z] 17:01:30 INFO - GECKO(18480) | [Child 18789: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7f1f30ff1800) [pid = 18789] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-07-17T17:01:30.030Z] 17:01:30 INFO - GECKO(18480) | [Child 18789: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f1f30fe7400) [pid = 18789] [serial = 4] [outer = (nil)] [url = http://example.com/browser/tools/profiler/tests/browser/do_work_500ms.html]
[task 2020-07-17T17:01:30.030Z] 17:01:30 INFO - GECKO(18480) | [Child 18789: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f1f313dfc00) [pid = 18789] [serial = 3] [outer = (nil)] [url = http://example.com/browser/tools/profiler/tests/browser/do_work_500ms.html]
[task 2020-07-17T17:01:30.051Z] 17:01:30 INFO - GECKO(18480) | [Child 18789, Main Thread] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/worker/checkouts/gecko/xpcom/base/nsCycleCollector.cpp, line 3359
[task 2020-07-17T17:01:30.071Z] 17:01:30 INFO - GECKO(18480) | [Child 18789, Main Thread] WARNING: NS_ENSURE_TRUE(Preferences::InitStaticMembers()) failed: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp, line 4382
[task 2020-07-17T17:01:30.095Z] 17:01:30 INFO - GECKO(18480) | [Child 18793: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7f6242afb6f0) [pid = 18793] [serial = 1] [outer = (nil)]
[task 2020-07-17T17:01:30.111Z] 17:01:30 INFO - GECKO(18480) | [Child 18793: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7f62161f3800) [pid = 18793] [serial = 2] [outer = 0x7f6242afb6f0]
[task 2020-07-17T17:01:30.441Z] 17:01:30 INFO - GECKO(18480) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmp0to4UO.mozrunner/runtests_leaks_tab_pid18982.log
[task 2020-07-17T17:01:30.442Z] 17:01:30 INFO - GECKO(18480) | [18982, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:30.443Z] 17:01:30 INFO - GECKO(18480) | [18982, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:30.459Z] 17:01:30 INFO - GECKO(18480) | [18982, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:30.522Z] 17:01:30 INFO - GECKO(18480) | [Child 18793, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 351
[task 2020-07-17T17:01:30.537Z] 17:01:30 INFO - GECKO(18480) | [Child 18793: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7f62165dd400) [pid = 18793] [serial = 3] [outer = 0x7f6242afb6f0]
[task 2020-07-17T17:01:32.576Z] 17:01:32 INFO - GECKO(18480) | [Child 18689: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 3 (0x7f599b6936f0) [pid = 18689] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2020-07-17T17:01:33.395Z] 17:01:33 INFO - GECKO(18480) | [Parent 18480, Main Thread] WARNING: Profiler failed to gather profiles from all sub-processes: file /builds/worker/checkouts/gecko/tools/profiler/gecko/nsProfiler.cpp, line 792
[task 2020-07-17T17:01:33.560Z] 17:01:33 INFO - GECKO(18480) | [Parent 18480, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:33.576Z] 17:01:33 INFO - GECKO(18480) | [Child 18588, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:33.577Z] 17:01:33 INFO - GECKO(18480) | [Child 18608, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:33.584Z] 17:01:33 INFO - GECKO(18480) | [Child 18916, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:33.584Z] 17:01:33 INFO - GECKO(18480) | [Child 18873, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:33.584Z] 17:01:33 INFO - GECKO(18480) | [Child 18793, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:33.585Z] 17:01:33 INFO - GECKO(18480) | [Child 18665, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:33.585Z] 17:01:33 INFO - GECKO(18480) | [Child 18689, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:33.761Z] 17:01:33 INFO - GECKO(18480) | [Child 18793: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 4 (0x7f6215f74c00) [pid = 18793] [serial = 4] [outer = 0x7f6242afb6f0]
[task 2020-07-17T17:01:34.300Z] 17:01:34 INFO - GECKO(18480) | [Child 18982, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp, line 1630
[task 2020-07-17T17:01:34.577Z] 17:01:34 INFO - GECKO(18480) | [Child 18982, ProfilerChild] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp, line 246
[task 2020-07-17T17:01:34.779Z] 17:01:34 INFO - TEST-INFO | started process screentopng
[task 2020-07-17T17:01:35.265Z] 17:01:35 INFO - TEST-INFO | screentopng: exit 0
[task 2020-07-17T17:01:35.265Z] 17:01:35 INFO - Buffered messages logged at 17:01:29
[task 2020-07-17T17:01:35.265Z] 17:01:35 INFO - Entering test bound test_profile_feature_nostacksampling
[task 2020-07-17T17:01:35.265Z] 17:01:35 INFO - TEST-PASS | tools/profiler/tests/browser/browser_test_feature_nostacksampling.js | The profiler is not currently active - true == true -
[task 2020-07-17T17:01:35.270Z] 17:01:35 INFO - Buffered messages logged at 17:01:33
[task 2020-07-17T17:01:35.273Z] 17:01:35 INFO - TEST-PASS | tools/profiler/tests/browser/browser_test_feature_nostacksampling.js | Stack samples were recorded from the parent process' main threadwhen the No Stack Sampling feature was turned on. - 0 == 0 -
[task 2020-07-17T17:01:35.275Z] 17:01:35 INFO - TEST-PASS | tools/profiler/tests/browser/browser_test_feature_nostacksampling.js | Stack samples were recorded from the content process' main threadwhen the No Stack Sampling feature was turned on. - 0 == 0 -
[task 2020-07-17T17:01:35.280Z] 17:01:35 INFO - Buffered messages finished
[task 2020-07-17T17:01:35.282Z] 17:01:35 INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_nostacksampling.js | Uncaught exception - at chrome://mochitests/content/browser/tools/profiler/tests/browser/head.js:42 - Error: Could not find the content process.
[task 2020-07-17T17:01:35.282Z] 17:01:35 INFO - Stack trace:
[task 2020-07-17T17:01:35.282Z] 17:01:35 INFO - stopProfilerNowAndGetThreads@chrome://mochitests/content/browser/tools/profiler/tests/browser/head.js:42:11
[task 2020-07-17T17:01:35.285Z] 17:01:35 INFO - Leaving test bound test_profile_feature_nostacksampling
[task 2020-07-17T17:01:35.287Z] 17:01:35 INFO - GECKO(18480) | MEMORY STAT | vsize 3259MB | residentFast 505MB | heapAllocated 252MB
[task 2020-07-17T17:01:35.289Z] 17:01:35 INFO - TEST-OK | tools/profiler/tests/browser/browser_test_feature_nostacksampling.js | took 4865ms
[task 2020-07-17T17:01:35.291Z] 17:01:35 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-07-17T17:01:35.293Z] 17:01:35 INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_nostacksampling.js | Found an unexpected tab at the end of test run: http://example.com/browser/tools/profiler/tests/browser/do_work_500ms.html -

Comment 1

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

(Similar to bug 1653473)

I think this is "thanks to" bug 1648324, which added a timeout when fetching profiles from content profiles.
Before that, we probably would have seen a time out, like in bug 1562945.

Not setting "regressed by" bug 1648324, because bug 1648324 didn't cause this issue, it only changed how it manifests itself. But it means we still have a real content-process issue that needs investigating... It would be great if we could force-kill the process and grab its crash dump for analysis.

Comment 2

[Intermittent Failures Robot]

1 failures in 4014 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-07-13&endday=2020-07-19&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2
• mozilla-central: 1

Platform breakdown:

• linux1804-64: 2
• linux1804-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-07-20&endday=2020-07-26&tree=all

Comment 4

[Intermittent Failures Robot]

5 failures in 4289 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3
• autoland: 2

Platform breakdown:

• linux1804-64: 3
• linux1804-64-ccov: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-07-27&endday=2020-08-02&tree=all

Comment 5

[Intermittent Failures Robot]

4 failures in 4618 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 3
• mozilla-central: 1

Platform breakdown:

• linux1804-64: 3
• linux1804-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-08-03&endday=2020-08-09&tree=all

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1
• autoland: 2

Platform breakdown:

• linux1804-64-asan: 2
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-08-10&endday=2020-08-16&tree=all

Comment 7

[Intermittent Failures Robot]

2 failures in 4100 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1
• autoland: 1

Platform breakdown:

• linux1804-64-asan: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-08-17&endday=2020-08-23&tree=all

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2
• mozilla-beta: 1

Platform breakdown:

• linux1804-64-asan: 2
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-08-24&endday=2020-08-30&tree=all

Comment 9

[Intermittent Failures Robot]

4 failures in 2984 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1
• mozilla-central: 2
• autoland: 1

Platform breakdown:

• linux1804-64-asan: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-08-31&endday=2020-09-06&tree=all

Comment 10

[Intermittent Failures Robot]

1 failures in 3410 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-09-07&endday=2020-09-13&tree=all

Comment 11

[Intermittent Failures Robot]

2 failures in 3760 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform breakdown:

• linux1804-64-asan: 1
• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-09-14&endday=2020-09-20&tree=all

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 2
• mozilla-central: 1

Platform breakdown:

• linux1804-64: 2
• linux1804-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-09-21&endday=2020-09-27&tree=all

Comment 13

[Intermittent Failures Robot]

1 failures in 3694 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• linux1804-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1653640&startday=2020-10-12&endday=2020-10-18&tree=all

Comment 14

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.