Closed Bug 1622477 Opened 5 years ago Closed 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | tools/profiler/tests/xpcshell/test_active_configuration.js | Test timed out

Categories

(Core :: Gecko Profiler, defect, P5)

Product:
Core
Component:
Gecko Profiler
Type:
defect

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1781449

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug, Regression)

Details

(Keywords: intermittent-failure, regression)

Filed by: rmaries [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=293129771&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QQ5-yadFQY-Btx3w_FerwA/runs/0/artifacts/public/logs/live_backing.log

[task 2020-03-14T00:38:24.568Z] 00:38:24 INFO - TEST-START | tools/profiler/tests/xpcshell/test_active_configuration.js
[task 2020-03-14T00:43:24.567Z] 00:43:24 WARNING - TEST-UNEXPECTED-TIMEOUT | tools/profiler/tests/xpcshell/test_active_configuration.js | Test timed out
[task 2020-03-14T00:43:24.568Z] 00:43:24 INFO - TEST-INFO took 300000ms
[task 2020-03-14T00:43:24.568Z] 00:43:24 INFO - >>>>>>>
[task 2020-03-14T00:43:24.569Z] 00:43:24 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-03-14T00:43:24.570Z] 00:43:24 INFO - "Checking that the profiler can fetch the information about the active configuration that is being used to power the profiler."
[task 2020-03-14T00:43:24.570Z] 00:43:24 INFO - TEST-PASS | tools/profiler/tests/xpcshell/test_active_configuration.js | run_test - [run_test : 14] When the profile is off, there is no active configuration. - null == null
[task 2020-03-14T00:43:24.571Z] 00:43:24 INFO - "Start the profiler."
[task 2020-03-14T00:43:24.573Z] 00:43:24 INFO - "Generate the activeConfiguration."
[task 2020-03-14T00:43:24.573Z] 00:43:24 INFO - TEST-PASS | tools/profiler/tests/xpcshell/test_active_configuration.js | run_test - [run_test : 48] The active configuration matches configuration given. - {"features":["js","leaf","threads"],"threads":["GeckoMain"],"interval":1,"capacity":16384,"activeBrowsingContextID":123} deepEqual {"interval":1,"threads":["GeckoMain"],"features":["js","leaf","threads"],"activeBrowsingContextID":123,"capacity":16384}
[task 2020-03-14T00:43:24.573Z] 00:43:24 INFO - "Get the profile."
[task 2020-03-14T00:43:24.573Z] 00:43:24 INFO - TEST-PASS | tools/profiler/tests/xpcshell/test_active_configuration.js | run_test - [run_test : 56] The configuration also matches on the profile meta object. - {"features":["js","leaf","threads"],"threads":["GeckoMain"],"interval":1,"capacity":16384,"activeBrowsingContextID":123} deepEqual {"interval":1,"threads":["GeckoMain"],"features":["js","leaf","threads"],"activeBrowsingContextID":123,"capacity":16384}
[task 2020-03-14T00:43:24.574Z] 00:43:24 INFO - "Restart the profiler with a new configuration."
[task 2020-03-14T00:43:24.574Z] 00:43:24 INFO - "Generate the activeConfiguration."
[task 2020-03-14T00:43:24.574Z] 00:43:24 INFO - TEST-PASS | tools/profiler/tests/xpcshell/test_active_configuration.js | run_test - [run_test : 96] The active configuration matches the new configuration. - {"features":["threads"],"threads":["GeckoMain","DOM Worker"],"interval":0.5,"capacity":32768,"duration":20,"activeBrowsingContextID":111} deepEqual {"interval":0.5,"threads":["GeckoMain","DOM Worker"],"features":["threads"],"activeBrowsingContextID":111,"duration":20,"capacity":32768}
[task 2020-03-14T00:43:24.575Z] 00:43:24 INFO - "Get the profile."
[task 2020-03-14T00:43:24.575Z] 00:43:24 INFO - <<<<<<<
[task 2020-03-14T00:43:24.576Z] 00:43:24 INFO - xpcshell return code: None
[task 2020-03-14T00:43:24.576Z] 00:43:24 INFO - tools/profiler/tests/xpcshell/test_active_configuration.js | Process still running after test!
[task 2020-03-14T00:43:24.632Z] 00:43:24 INFO - INFO | Result summary:
[task 2020-03-14T00:43:24.633Z] 00:43:24 INFO - INFO | Passed: 396
[task 2020-03-14T00:43:24.633Z] 00:43:24 WARNING - INFO | Failed: 1
[task 2020-03-14T00:43:24.634Z] 00:43:24 WARNING - One or more unittests failed.
[task 2020-03-14T00:43:24.634Z] 00:43:24 INFO - INFO | Todo: 0
[task 2020-03-14T00:43:24.635Z] 00:43:24 INFO - INFO | Retried: 1
[task 2020-03-14T00:43:24.635Z] 00:43:24 INFO - SUITE-END | took 2384s

From the orange graph, it seems that it started around June 12.

This test exercises the raw API and doesn't do much by itself. From the logs, when it fails, it was waiting 5 minutes that just StartProfiler returns.

According to the clang doc:

ThreadSanitizer is a tool that detects data races. It consists of a compiler instrumentation module and a run-time library. Typical slowdown introduced by ThreadSanitizer is about 5x-15x. Typical memory overhead introduced by ThreadSanitizer is about 5x-10x.

Gerald, do you remember if we landed anything specific in this time frame?

Flags: needinfo?(gsquelart)

Most probably the same as bug 1635619, with possible cause bug 1626918.
Investigating...

Assignee: nobody → gsquelart
Flags: needinfo?(gsquelart)
Regressed by: 1626918
See Also: → 1635619
Has Regression Range: --- → yes

In the last 7 days there have been 23 occurrences, all on linux1804-64-tsan opt.

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

Bug 1653181 removed the spikes introduced by bug 1626918, but there are still a few hits like before, so I'm keeping this bug open.

Not actively working on this, and it's low frequency.

Assignee: gsquelart → nobody
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.