Open Bug 1778299 Opened 2 years ago Updated 5 hours ago

Intermittent raptor-browsertime Error: Browsertime failed to run | raptor-browsertime Critical: Benchmark timed out. Aborting...

Categories

(Testing :: Raptor, defect, P5)

defect

Tracking

(Not tracked)

REOPENED

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [retriggered])

Filed by: ccozmuta [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=383481949&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/bfWhiUJQTdu8-IZ0EyGmqg/runs/0/artifacts/public/logs/live_backing.log


[task 2022-07-06T10:51:05.227Z] 10:51:05     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:08.361Z] 10:51:08     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:11.508Z] 10:51:11     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:14.660Z] 10:51:14     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:17.690Z] 10:51:17     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:20.791Z] 10:51:20     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:23.924Z] 10:51:23     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:27.022Z] 10:51:27     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:30.041Z] 10:51:30     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:33.077Z] 10:51:33     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:36.141Z] 10:51:36     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:39.290Z] 10:51:39     INFO -  raptor-browsertime Info: Waiting 3000 ms for data from benchmark...
[task 2022-07-06T10:51:42.414Z] 10:51:42    ERROR -  raptor-browsertime Error: Browsertime failed to run
[task 2022-07-06T10:51:42.434Z] 10:51:42     INFO -  raptor-browsertime Info: Navigating to about:blank
[task 2022-07-06T10:51:42.434Z] 10:51:42     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 1
[task 2022-07-06T10:51:42.434Z] 10:51:42 CRITICAL -  raptor-browsertime Critical: Benchmark timed out. Aborting...
[task 2022-07-06T10:51:42.435Z] 10:51:42     INFO -  raptor-perftest Info: Removing temporary directory: /var/folders/4m/bf8cy0kn7sl30kyf58gkxz0m000014/T/tmp3pb7gqso
[task 2022-07-06T10:51:42.447Z] 10:51:42    ERROR -  Traceback (most recent call last):
[task 2022-07-06T10:51:42.447Z] 10:51:42     INFO -    File "/opt/worker/tasks/task_165710208507943/build/tests/raptor/raptor/raptor.py", line 203, in <module>
[task 2022-07-06T10:51:42.447Z] 10:51:42     INFO -      main()
[task 2022-07-06T10:51:42.448Z] 10:51:42     INFO -    File "/opt/worker/tasks/task_165710208507943/build/tests/raptor/raptor/raptor.py", line 149, in main
[task 2022-07-06T10:51:42.448Z] 10:51:42     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-07-06T10:51:42.448Z] 10:51:42     INFO -    File "/opt/worker/tasks/task_165710208507943/build/tests/raptor/raptor/perftest.py", line 460, in run_tests
[task 2022-07-06T10:51:42.448Z] 10:51:42     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2022-07-06T10:51:42.448Z] 10:51:42     INFO -    File "/opt/worker/tasks/task_165710208507943/build/tests/raptor/raptor/browsertime/base.py", line 714, in run_test
[task 2022-07-06T10:51:42.448Z] 10:51:42     INFO -      raise Exception(self.browsertime_failure)
[task 2022-07-06T10:51:42.448Z] 10:51:42     INFO -  Exception: Benchmark timed out. Aborting...
[task 2022-07-06T10:51:42.634Z] 10:51:42    ERROR - Return code: 1
[task 2022-07-06T10:51:42.634Z] 10:51:42  WARNING - setting return code to 1
[task 2022-07-06T10:51:42.634Z] 10:51:42     INFO - Copying Raptor results to upload dir:
[task 2022-07-06T10:51:42.634Z] 10:51:42     INFO - /opt/worker/tasks/task_165710208507943/build/blobber_upload_dir/perfherder-data.json
[task 2022-07-06T10:51:42.635Z] 10:51:42     INFO - Copying raptor results from /opt/worker/tasks/task_165710208507943/build/raptor.json to /opt/worker/tasks/task_165710208507943/build/blobber_upload_dir/perfherder-data.json
[task 2022-07-06T10:51:42.635Z] 10:51:42 CRITICAL - Error copying results /opt/worker/tasks/task_165710208507943/build/raptor.json to upload dir /opt/worker/tasks/task_165710208507943/build/blobber_upload_dir/perfherder-data.json
[task 2022-07-06T10:51:42.635Z] 10:51:42     INFO - [Errno 2] No such file or directory: '/opt/worker/tasks/task_165710208507943/build/raptor.json'
[task 2022-07-06T10:51:42.636Z] 10:51:42     INFO - Running post-action listener: _package_coverage_data
[task 2022-07-06T10:51:42.636Z] 10:51:42     INFO - Running post-action listener: _resource_record_post_action
[task 2022-07-06T10:51:42.636Z] 10:51:42     INFO - Running post-action listener: process_java_coverage_data
[task 2022-07-06T10:51:42.636Z] 10:51:42     INFO - Running post-action listener: stop_device
[task 2022-07-06T10:51:42.636Z] 10:51:42     INFO - [mozharness: 2022-07-06 10:51:42.636332Z] Finished run-tests step (success)
[task 2022-07-06T10:51:42.636Z] 10:51:42     INFO - Running post-run listener: _resource_record_post_run
[task 2022-07-06T10:51:42.842Z] 10:51:42     INFO - Total resource usage - Wall time: 2365s; CPU: 3%; Read bytes: 258822144; Write bytes: 1078575104; Read time: 2924; Write time: 3418
[task 2022-07-06T10:51:42.842Z] 10:51:42     INFO - TinderboxPrint: CPU usage<br/>2.8%
[task 2022-07-06T10:51:42.842Z] 10:51:42     INFO - TinderboxPrint: I/O read bytes / time<br/>258,822,144 / 2,924
[task 2022-07-06T10:51:42.842Z] 10:51:42     INFO - TinderboxPrint: I/O write bytes / time<br/>1,078,575,104 / 3,418
[task 2022-07-06T10:51:42.842Z] 10:51:42     INFO - TinderboxPrint: CPU idle<br/>27,197.1 (95.8%)
[task 2022-07-06T10:51:42.842Z] 10:51:42     INFO - TinderboxPrint: CPU system<br/>389.3 (1.4%)
[task 2022-07-06T10:51:42.842Z] 10:51:42     INFO - TinderboxPrint: CPU user<br/>793.4 (2.8%)
[task 2022-07-06T10:51:42.842Z] 10:51:42     INFO - TinderboxPrint: Swap in / out<br/>668,561,408 / 0
[task 2022-07-06T10:51:42.843Z] 10:51:42     INFO - install-chromium-distribution - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2022-07-06T10:51:42.844Z] 10:51:42     INFO - install - Wall time: 33s; CPU: 14%; Read bytes: 479868416; Write bytes: 437645312; Read time: 30471; Write time: 604
[task 2022-07-06T10:51:42.872Z] 10:51:42     INFO - run-tests - Wall time: 2332s; CPU: 3%; Read bytes: 216657920; Write bytes: 627212288; Read time: 2187; Write time: 2795
[task 2022-07-06T10:51:43.400Z] 10:51:43  WARNING - returning nonzero exit status 1
[taskcluster 2022-07-06T10:51:43.440Z]    Exit Code: 1
[taskcluster 2022-07-06T10:51:43.440Z]    User Time: 1m20.683757s
[taskcluster 2022-07-06T10:51:43.440Z]  Kernel Time: 20.231654s
[taskcluster 2022-07-06T10:51:43.440Z]    Wall Time: 40m41.806417s
[taskcluster 2022-07-06T10:51:43.440Z]       Result: FAILED
[taskcluster 2022-07-06T10:51:43.440Z] === Task Finished ===
[taskcluster 2022-07-06T10:51:43.440Z] Task Duration: 40m41.809702s
[taskcluster 2022-07-06T10:51:43.553Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2023-07-06T08:30:02.593Z
[taskcluster 2022-07-06T10:51:43.778Z] Uploading artifact public/test_info/resource-usage.json from file build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2023-07-06T08:30:02.593Z
[taskcluster 2022-07-06T10:51:45.365Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/bfWhiUJQTdu8-IZ0EyGmqg/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2023-07-06T08:30:02.593Z
[taskcluster:error] exit status 1
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → DUPLICATE
No longer blocks: 1788392
Status: RESOLVED → REOPENED
Resolution: DUPLICATE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Alex, could you have a look over the frequent speedometer failure here?
Failure log: https://treeherder.mozilla.org/logviewer?job_id=418708899&repo=autoland

Flags: needinfo?(afinder)

:aglavic, can you look into this issue? It looks like we might be able to backfill this task to see what patch caused the increase in frequency. It started on June 9th based on the orange factor graph.

Flags: needinfo?(afinder) → needinfo?(aglavic)

Yep I'll backfill the task :)

Assignee: nobody → aglavic
Whiteboard: [retriggered] → [retriggered][fxp]

Looks to be resolved
Started: https://bugzilla.mozilla.org/show_bug.cgi?id=1834302 June 9th
16123ae006bde0652837ee005684f287424cafe8
Stopped: https://bugzilla.mozilla.org/show_bug.cgi?id=1831548 June 15th
698d86db485b0752be9afd7cc39439fa3599bcf1

Flags: needinfo?(aglavic)

Closing as there have been no fails for over 3 weeks now

Assignee: aglavic → nobody
Status: REOPENED → RESOLVED
Closed: 2 years ago1 year ago
Resolution: --- → WORKSFORME

Did not mean to close the ticket

Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Whiteboard: [retriggered][fxp] → [retriggered]
Summary: Intermittent [Tier 2] raptor-browsertime Error: Browsertime failed to run | raptor-browsertime Critical: Benchmark timed out. Aborting... → Intermittent raptor-browsertime Error: Browsertime failed to run | raptor-browsertime Critical: Benchmark timed out. Aborting...
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

This is timing out permanently on windows shippable godot runs: https://treeherder.mozilla.org/jobs?repo=mozilla-central&group_state=expanded&searchStr=godot&fromchange=e39cc33d235644207d14479a4f952740cca9387d&selectedTaskRun=KEfBJ3ucQfCGxdKg1xGnZA.0
Greg, could you have a look or redirect to someone? Thanks.

Flags: needinfo?(gmierz2)

The failures have stopped now. I have a feeling it was caused by this bug because the tests are passing on the push with the backout: https://bugzilla.mozilla.org/show_bug.cgi?id=1860062

Flags: needinfo?(gmierz2)
Keywords: regression
Regressed by: 1860062

:cmartin, since you are the author of the regressor, bug 1860062, could you take a look?

For more information, please visit BugBot documentation.

Flags: needinfo?(cmartin)

This was been resolved with a backout.

Flags: needinfo?(cmartin)
Status: REOPENED → RESOLVED
Closed: 1 year ago1 year ago
Resolution: --- → FIXED

Set release status flags based on info from the regressing bug 1860062

Target Milestone: --- → 122 Branch

Re-opening this because the intermittent is still happening (the most recent failure here) and it was present before the spike in failures here that got Bug 1860062 backed out.

Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: 122 Branch → ---

Set release status flags based on info from the regressing bug 1860062

You need to log in before you can comment on or make changes to this bug.