1582655 - Intermittent tools/profiler/tests/browser/browser_test_feature_preferencereads.js | Found a tab after previous test timed out: http://example.com/browser/tools/profiler/tests/browser/fixed_height.html -

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=267592398&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/fLGMTdb9TUmSzBSwhRPQXw/runs/0/artifacts/public/logs/live_backing.log

---

[task 2019-09-20T06:27:30.701Z] 06:27:30 INFO - TEST-START | tools/profiler/tests/browser/browser_test_feature_preferencereads.js
[task 2019-09-20T06:27:30.883Z] 06:27:30 INFO - GECKO(5129) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpT0aEwM.mozrunner/runtests_leaks_tab_pid5373.log
[task 2019-09-20T06:27:30.883Z] 06:27:30 INFO - GECKO(5129) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-09-20T06:27:31.125Z] 06:27:31 INFO - GECKO(5129) | [2019-09-20T06:27:31Z WARN audio_thread_priority::rt_linux] Could not make thread real-time.
[task 2019-09-20T06:27:31.125Z] 06:27:31 INFO - GECKO(5129) | [2019-09-20T06:27:31Z WARN audioipc_client] Could not promote audio threads to real-time during initialization.
[task 2019-09-20T06:27:31.141Z] 06:27:31 INFO - GECKO(5129) | ++DOCSHELL 0x7f2a6bcb5800 == 1 [pid = 5357] [id = {a78770ae-145d-4b88-97b3-d4c3102b558d}]
[task 2019-09-20T06:27:31.289Z] 06:27:31 INFO - GECKO(5129) | ++DOMWINDOW == 1 (0x7f2a6cbc3f20) [pid = 5357] [serial = 1] [outer = (nil)]
[task 2019-09-20T06:27:31.306Z] 06:27:31 INFO - GECKO(5129) | ++DOMWINDOW == 2 (0x7f2a6bb05400) [pid = 5357] [serial = 2] [outer = 0x7f2a6cbc3f20]
[task 2019-09-20T06:27:33.943Z] 06:27:33 INFO - GECKO(5129) | --DOMWINDOW == 2 (0x7f1ac63c6c00) [pid = 5284] [serial = 3] [outer = (nil)] [url = http://example.com/browser/tools/profiler/tests/browser/do_work_500ms.html]
[task 2019-09-20T06:27:33.963Z] 06:27:33 INFO - GECKO(5129) | --DOCSHELL 0x7f1ac595e000 == 0 [pid = 5284] [id = {c0cbf0d7-b1b6-4405-9305-2afeffbff3fd}] [url = http://example.com/browser/tools/profiler/tests/browser/do_work_500ms.html]
[task 2019-09-20T06:27:36.296Z] 06:27:36 INFO - GECKO(5129) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-09-20T06:27:36.493Z] 06:27:36 INFO - GECKO(5129) | [2019-09-20T06:27:36Z WARN audio_thread_priority::rt_linux] Could not make thread real-time.
[task 2019-09-20T06:27:36.493Z] 06:27:36 INFO - GECKO(5129) | [2019-09-20T06:27:36Z WARN audioipc_client] Could not promote audio threads to real-time during initialization.
[task 2019-09-20T06:27:36.509Z] 06:27:36 INFO - GECKO(5129) | ++DOCSHELL 0x7f44e835e000 == 1 [pid = 5373] [id = {7ab591c8-3d73-4f05-973b-3e6fe7838d8e}]
[task 2019-09-20T06:27:36.610Z] 06:27:36 INFO - GECKO(5129) | ++DOMWINDOW == 1 (0x7f44f9efdf20) [pid = 5373] [serial = 1] [outer = (nil)]
[task 2019-09-20T06:27:36.611Z] 06:27:36 INFO - GECKO(5129) | ++DOMWINDOW == 2 (0x7f44e82d9400) [pid = 5373] [serial = 2] [outer = 0x7f44f9efdf20]
[task 2019-09-20T06:27:36.908Z] 06:27:36 INFO - GECKO(5129) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpT0aEwM.mozrunner/runtests_leaks_tab_pid5407.log
[task 2019-09-20T06:27:37.105Z] 06:27:37 INFO - GECKO(5129) | ++DOMWINDOW == 3 (0x7f44e8dcb400) [pid = 5373] [serial = 3] [outer = 0x7f44f9efdf20]
[task 2019-09-20T06:27:46.294Z] 06:27:46 INFO - GECKO(5129) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-09-20T06:27:46.887Z] 06:27:46 INFO - GECKO(5129) | [2019-09-20T06:27:46Z WARN audio_thread_priority::rt_linux] Could not make thread real-time.
[task 2019-09-20T06:27:46.888Z] 06:27:46 INFO - GECKO(5129) | [2019-09-20T06:27:46Z WARN audioipc_client] Could not promote audio threads to real-time during initialization.
[task 2019-09-20T06:27:48.313Z] 06:27:48 INFO - GECKO(5129) | --DOCSHELL 0x7f69e5db2000 == 0 [pid = 5255] [id = {845b2af2-99ec-4720-8a6e-825783b9b455}] [url = about:blank]
[task 2019-09-20T06:27:48.509Z] 06:27:48 INFO - GECKO(5129) | --DOCSHELL 0x7f760ec5c800 == 0 [pid = 5316] [id = {04ad5197-0d29-49ae-9803-f9167757795d}] [url = about:blank]
[task 2019-09-20T06:27:49.121Z] 06:27:49 INFO - GECKO(5129) | --DOMWINDOW == 1 (0x7f1ac5902f20) [pid = 5284] [serial = 1] [outer = (nil)] [url = http://example.com/browser/tools/profiler/tests/browser/do_work_500ms.html]
[task 2019-09-20T06:28:01.264Z] 06:28:01 INFO - GECKO(5129) | --DOMWINDOW == 0 (0x7f1ac63c5000) [pid = 5284] [serial = 4] [outer = (nil)] [url = http://example.com/browser/tools/profiler/tests/browser/do_work_500ms.html]
[task 2019-09-20T06:28:05.940Z] 06:28:05 INFO - GECKO(5129) | --DOMWINDOW == 1 (0x7f69e5dc3f20) [pid = 5255] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2019-09-20T06:28:06.036Z] 06:28:06 INFO - GECKO(5129) | --DOMWINDOW == 1 (0x7f76383b6f20) [pid = 5316] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2019-09-20T06:28:07.502Z] 06:28:07 INFO - GECKO(5129) | --DOMWINDOW == 2 (0x7f44e82d9400) [pid = 5373] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-09-20T06:28:32.707Z] 06:28:32 INFO - GECKO(5129) | --DOMWINDOW == 0 (0x7f760f74ec00) [pid = 5316] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-09-20T06:28:36.284Z] 06:28:36 INFO - GECKO(5129) | --DOMWINDOW == 0 (0x7f69e5d23400) [pid = 5255] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-09-20T06:29:01.227Z] 06:29:01 INFO - TEST-INFO | started process screentopng
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - TEST-INFO | screentopng: exit 0
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - Buffered messages logged at 06:27:30
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - Entering test bound test_profile_feature_preferencereads
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - TEST-PASS | tools/profiler/tests/browser/browser_test_feature_preferencereads.js | The profiler is not currently active - true == true -
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - Buffered messages finished
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_preferencereads.js | Test timed out -
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - GECKO(5129) | MEMORY STAT | vsize 3244MB | residentFast 527MB | heapAllocated 265MB
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - TEST-OK | tools/profiler/tests/browser/browser_test_feature_preferencereads.js | took 90843ms
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - TEST-UNEXPECTED-FAIL | tools/profiler/tests/browser/browser_test_feature_preferencereads.js | Found a tab after previous test timed out: http://example.com/browser/tools/profiler/tests/browser/fixed_height.html -
[task 2019-09-20T06:29:04.987Z] 06:29:04 INFO - checking window state

Comment 1

[Andreea Pavel [:apavel]]

This showed up first as a perma-failure here (Bug 1563063) : https://treeherder.mozilla.org/#/jobs?repo=autoland&selectedJob=267487279&searchStr=linux%2Cx64%2Cdebug%2Cmochitests%2Ctest-linux64%2Fdebug-mochitest-browser-chrome-e10s&fromchange=6b93a83735ed3ab3b57b46c1b768814b1a1af5d6&tochange=9602dbc76cd3a8d73e633b9337230287563a261a and after Bogdan backed out it turned green.

Showed up later as intermittent.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

It wasn't perma-failure

Comment 3

[Cosmin Sabou [:CosminS]]

Should be fixed by this backout: https://hg.mozilla.org/mozilla-central/rev/2a7cddefc1bbeee6bc41105b76814e4760a878df

Comment 4

[Olli Pettay [:smaug][[e-mail]]]

No. There were failures when bug 1563063 wasn't in. See https://bugzilla.mozilla.org/show_bug.cgi?id=1582655#c1

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

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

Platform breakdown:

• linux64: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1582655&startday=2019-09-16&endday=2019-09-22&tree=all

Comment 6

[Olli Pettay [:smaug][[e-mail]]]

FWIW, the test fails locally rather reliably on debug linux64 even without bug 1563063

Comment 7

[Olli Pettay [:smaug][[e-mail]]]

Attachment: Bug 1582655, try to make browser_test_feature_preferencereads.js less racy and let browser_test_feature_jsallocations.js to run a bit longer, r=whawkins

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/988fe150d3a2
try to make browser_test_feature_preferencereads.js less racy and let browser_test_feature_jsallocations.js to run a bit longer, r=whawkins

Comment 9

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/988fe150d3a2

Comment 10

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/9dd1edbf897e