1772269 - Intermittent [Tier 2] raptor-browsertime Critical: Browsertime process timed out after waiting 120 seconds for output

Status: RESOLVED DUPLICATE of bug 1769482

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-06-02T04:22:36.596Z] 04:22:36     INFO -  raptor-browsertime Info: Get visual metrics from the video
[task 2022-06-02T04:22:42.952Z] 04:22:42     INFO -  raptor-browsertime Info: Get visual metrics from the video
[task 2022-06-02T04:22:46.522Z] 04:22:46     INFO -  raptor-browsertime Info: https://imgur.com/gallery/m5tYJL6 TTFB: 31ms DOMContentLoaded: 544ms firstPaint: 274ms FCP: 800ms Load: 1.76s
[task 2022-06-02T04:22:46.522Z] 04:22:46     INFO -  raptor-browsertime Info: VisualMetrics: FirstVisualChange: 720ms SpeedIndex: 874ms PerceptualSpeedIndex: 891ms ContentfulSpeedIndex: 1.07s VisualComplete85: 1.16s LastVisualChange: 6.92s
[task 2022-06-02T04:22:46.523Z] 04:22:46     INFO -  raptor-browsertime Info: https://imgur.com/gallery/m5tYJL6?browsertime_run=2 TTFB: -1ms DOMContentLoaded: 364ms firstPaint: 88ms FCP: 537ms Load: 622ms
[task 2022-06-02T04:22:46.523Z] 04:22:46     INFO -  raptor-browsertime Info: VisualMetrics: FirstVisualChange: 480ms SpeedIndex: 580ms PerceptualSpeedIndex: 569ms ContentfulSpeedIndex: 653ms VisualComplete85: 720ms LastVisualChange: 3.48s
[task 2022-06-02T04:22:46.526Z] 04:22:46     INFO -  raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2022-06-02T04:22:48.732Z] 04:22:48     INFO -  raptor-browsertime Info: Starting a browsertime pageload
[task 2022-06-02T04:22:48.732Z] 04:22:48     INFO -  raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2022-06-02T04:22:49.734Z] 04:22:49     INFO -  raptor-browsertime Info: Navigating to about:blank, count: 0
[task 2022-06-02T04:22:49.735Z] 04:22:49     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 20
[task 2022-06-02T04:22:54.825Z] 04:22:54     INFO -  raptor-browsertime Info: Navigating to primary url:https://imgur.com/gallery/m5tYJL6
[task 2022-06-02T04:22:54.826Z] 04:22:54     INFO -  raptor-browsertime Info: Cycle 0, waiting for 1000 ms
[task 2022-06-02T04:22:55.827Z] 04:22:55     INFO -  raptor-browsertime Info: Cycle 0, starting the measure
[task 2022-06-02T04:22:55.828Z] 04:22:55     INFO -  raptor-browsertime Info: Testing url https://imgur.com/gallery/m5tYJL6 iteration 20
[task 2022-06-02T04:22:55.829Z] 04:22:55     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2022-06-02T04:27:22.686Z] 04:27:22 CRITICAL -  raptor-browsertime Critical: Browsertime process timed out after waiting 120 seconds for output
[task 2022-06-02T04:27:22.686Z] 04:27:22     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2022-06-02T04:27:22.686Z] 04:27:22     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2022-06-02T04:27:22.686Z] 04:27:22     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2022-06-02T04:27:22.687Z] 04:27:22     INFO -  raptor-mitmproxy Info: writing: /home/cltbld/tasks/task_165414196172489/build/application/firefox/distribution/policies.json
[task 2022-06-02T04:27:22.687Z] 04:27:22     INFO -  raptor-perftest Info: Removing temporary directory: /tmp/tmp5vgz9a5q
[task 2022-06-02T04:27:22.714Z] 04:27:22    ERROR -  Traceback (most recent call last):
[task 2022-06-02T04:27:22.714Z] 04:27:22     INFO -    File "/home/cltbld/tasks/task_165414196172489/build/tests/raptor/raptor/raptor.py", line 215, in <module>
[task 2022-06-02T04:27:22.714Z] 04:27:22     INFO -      main()
[task 2022-06-02T04:27:22.714Z] 04:27:22     INFO -    File "/home/cltbld/tasks/task_165414196172489/build/tests/raptor/raptor/raptor.py", line 161, in main
[task 2022-06-02T04:27:22.715Z] 04:27:22     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-06-02T04:27:22.715Z] 04:27:22     INFO -    File "/home/cltbld/tasks/task_165414196172489/build/tests/raptor/raptor/perftest.py", line 462, in run_tests
[task 2022-06-02T04:27:22.715Z] 04:27:22     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2022-06-02T04:27:22.715Z] 04:27:22     INFO -    File "/home/cltbld/tasks/task_165414196172489/build/tests/raptor/raptor/browsertime/base.py", line 592, in run_test
[task 2022-06-02T04:27:22.715Z] 04:27:22     INFO -      f"Browsertime process timed out after waiting {output_timeout} seconds "
[task 2022-06-02T04:27:22.716Z] 04:27:22     INFO -  Exception: Browsertime process timed out after waiting 120 seconds for output
[task 2022-06-02T04:27:22.776Z] 04:27:22    ERROR - Return code: 1
[task 2022-06-02T04:27:22.776Z] 04:27:22  WARNING - setting return code to 1
[task 2022-06-02T04:27:22.776Z] 04:27:22     INFO - Copying Raptor results to upload dir:
[task 2022-06-02T04:27:22.776Z] 04:27:22     INFO - /home/cltbld/tasks/task_165414196172489/build/blobber_upload_dir/perfherder-data.json
[task 2022-06-02T04:27:22.776Z] 04:27:22     INFO - Copying raptor results from /home/cltbld/tasks/task_165414196172489/build/raptor.json to /home/cltbld/tasks/task_165414196172489/build/blobber_upload_dir/perfherder-data.json
[task 2022-06-02T04:27:22.777Z] 04:27:22 CRITICAL - Error copying results /home/cltbld/tasks/task_165414196172489/build/raptor.json to upload dir /home/cltbld/tasks/task_165414196172489/build/blobber_upload_dir/perfherder-data.json
[task 2022-06-02T04:27:22.777Z] 04:27:22     INFO - [Errno 2] No such file or directory: '/home/cltbld/tasks/task_165414196172489/build/raptor.json'
[task 2022-06-02T04:27:22.777Z] 04:27:22     INFO - Running post-action listener: _package_coverage_data
[task 2022-06-02T04:27:22.777Z] 04:27:22     INFO - Running post-action listener: _resource_record_post_action
[task 2022-06-02T04:27:22.778Z] 04:27:22     INFO - Running post-action listener: process_java_coverage_data
[task 2022-06-02T04:27:22.778Z] 04:27:22     INFO - Running post-action listener: stop_device
[task 2022-06-02T04:27:22.778Z] 04:27:22     INFO - [mozharness: 2022-06-02 04:27:22.778084Z] Finished run-tests step (success)
[task 2022-06-02T04:27:22.778Z] 04:27:22     INFO - Running post-run listener: _resource_record_post_run
[taskcluster 2022-06-02T04:27:22.809Z] [taskcluster-proxy] Successfully refreshed taskcluster-proxy credentials: task-client/SrHc8WXiRr-Su5yXn857LA/0/on/mdc1/t-linux64-ms-015/until/1654145242.769
[task 2022-06-02T04:27:22.929Z] 04:27:22     INFO - Total resource usage - Wall time: 2033s; CPU: 19%; Read bytes: 144636936192; Write bytes: 27440553984; Read time: 2275272; Write time: 1876888
[task 2022-06-02T04:27:22.930Z] 04:27:22     INFO - TinderboxPrint: CPU usage<br/>18.5%
[task 2022-06-02T04:27:22.930Z] 04:27:22     INFO - TinderboxPrint: I/O read bytes / time<br/>144,636,936,192 / 2,275,272
[task 2022-06-02T04:27:22.930Z] 04:27:22     INFO - TinderboxPrint: I/O write bytes / time<br/>27,440,553,984 / 1,876,888
[task 2022-06-02T04:27:22.930Z] 04:27:22     INFO - TinderboxPrint: CPU idle<br/>11,815.8 (72.8%)
[task 2022-06-02T04:27:22.930Z] 04:27:22     INFO - TinderboxPrint: CPU iowait<br/>363.5 (2.2%)
[task 2022-06-02T04:27:22.930Z] 04:27:22     INFO - TinderboxPrint: CPU nice<br/>218.8 (1.3%)
[task 2022-06-02T04:27:22.930Z] 04:27:22     INFO - TinderboxPrint: CPU system<br/>1,748.8 (10.8%)
[task 2022-06-02T04:27:22.930Z] 04:27:22     INFO - TinderboxPrint: CPU user<br/>2,050.0 (12.6%)
[task 2022-06-02T04:27:22.930Z] 04:27:22     INFO - TinderboxPrint: Swap in / out<br/>20,447,232 / 1,047,949,312
[task 2022-06-02T04:27:22.930Z] 04:27:22     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-06-02T04:27:22.931Z] 04:27:22     INFO - install - Wall time: 9s; CPU: 13%; Read bytes: 131072; Write bytes: 426196992; Read time: 32; Write time: 2252
[task 2022-06-02T04:27:22.949Z] 04:27:22     INFO - run-tests - Wall time: 2024s; CPU: 19%; Read bytes: 144632389632; Write bytes: 27011809280; Read time: 2275232; Write time: 1873928
[task 2022-06-02T04:27:23.303Z] 04:27:23  WARNING - returning nonzero exit status 1
[taskcluster 2022-06-02T04:27:23.337Z]    Exit Code: 1
[taskcluster 2022-06-02T04:27:23.337Z]    User Time: 37m34.752652s
[taskcluster 2022-06-02T04:27:23.337Z]  Kernel Time: 6m44.383166s
[taskcluster 2022-06-02T04:27:23.337Z]    Wall Time: 34m40.156263743s
[taskcluster 2022-06-02T04:27:23.337Z]       Result: FAILED
[taskcluster 2022-06-02T04:27:23.338Z] === Task Finished ===
[taskcluster 2022-06-02T04:27:23.338Z] Task Duration: 34m40.157770313s