Closed Bug 1769482 Opened 3 years ago Closed 3 years ago

Intermittent [tier 2] raptor-browsertime Critical: Browsertime process timed out after waiting 120/240 seconds for output

Categories

(Testing :: Raptor, defect, P5)

defect

Tracking

(firefox-esr91 unaffected, firefox100 unaffected, firefox101 unaffected, firefox102 wontfix, firefox103 fixed)

RESOLVED FIXED
103 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox100 --- unaffected
firefox101 --- unaffected
firefox102 --- wontfix
firefox103 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: alexandrui)

References

(Regression)

Details

(Keywords: intermittent-failure, perf-alert, regression, Whiteboard: [stockwell disable-recommended])

Attachments

(1 file)

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


[task 2022-05-16T04:49:02.809Z] 04:49:02     INFO -  raptor-perftest Info: starting test: cnn
[task 2022-05-16T04:49:02.810Z] 04:49:02     INFO -  raptor-browsertime Info: test: {'here': '/home/cltbld/tasks/task_165267645178850/build/tests/raptor/raptor/tests/tp6/desktop', 'alert_on': ['ContentfulSpeedIndex', 'FirstVisualChange', 'LastVisualChange', 'PerceptualSpeedIndex', 'SpeedIndex', 'fcp', 'loadtime'], 'alert_threshold': '2.0', 'apps': 'firefox, chrome, chromium', 'browser_cycles': 5, 'lower_is_better': True, 'owner': 'PerfTest Team', 'page_cycles': 2, 'page_timeout': 72000.0, 'playback': None, 'playback_pageset_manifest': 'mitm7-linux-firefox-{subtest}.manifest', 'playback_version': '7.0.4', 'type': 'pageload', 'unit': 'ms', 'use_live_sites': 'true', 'secondary_url': 'https://www.cnn.com/weather', 'test_url': 'https://www.cnn.com/2021/03/22/weather/climate-change-warm-waters-lake-michigan/index.html', 'name': 'cnn', 'manifest': '/home/cltbld/tasks/task_165267645178850/build/tests/raptor/raptor/tests/tp6/desktop/browsertime-tp6.ini', 'manifest_relpath': 'tests/tp6/desktop/browsertime-tp6.ini', 'path': '/home/cltbld/tasks/task_165267645178850/build/tests/raptor/raptor/tests/tp6/desktop/cnn', 'relpath': 'tests/tp6/desktop/cnn', 'ancestor_manifest': 'raptor.ini', 'expected': 'pass', 'cold': True, 'expected_browser_cycles': 5, 'browser_cycle': 1, 'measure': ['fnbpaint', 'fcp', 'dcf', 'loadtime', 'ContentfulSpeedIndex', 'PerceptualSpeedIndex', 'SpeedIndex', 'FirstVisualChange', 'LastVisualChange']}
[task 2022-05-16T04:49:02.811Z] 04:49:02     INFO -  raptor-browsertime-desktop Info: binary_path: /home/cltbld/tasks/task_165267645178850/build/application/firefox/firefox
[task 2022-05-16T04:49:02.811Z] 04:49:02     INFO -  raptor-browsertime Info: Using Firefox Window Recorder for videos
[task 2022-05-16T04:49:02.811Z] 04:49:02     INFO -  raptor-browsertime Info: timeout (s): 72000
[task 2022-05-16T04:49:02.811Z] 04:49:02     INFO -  raptor-browsertime Info: browsertime cwd: /home/cltbld/tasks/task_165267645178850/build
[task 2022-05-16T04:49:02.812Z] 04:49:02     INFO -  raptor-browsertime Info: browsertime cmd: /home/cltbld/tasks/task_165267645178850/fetches/node/bin/node /home/cltbld/tasks/task_165267645178850/fetches/browsertime/node_modules/browsertime/bin/browsertime.js --firefox.geckodriverPath /home/cltbld/tasks/task_165267645178850/fetches/geckodriver /home/cltbld/tasks/task_165267645178850/build/tests/raptor/raptor/browsertime/../../browsertime/browsertime_pageload.js --firefox.noDefaultPrefs --browsertime.page_cycle_delay 5000 --skipHar --pageLoadStrategy none --webdriverPageload true --firefox.disableBrowsertimeExtension true --pageCompleteCheckStartWait 5000 --pageCompleteCheckPollTimeout 1000 --timeouts.pageLoad 72000 --timeouts.script 144000 --browsertime.page_cycles 2 --pageCompleteWaitTime 5000 --browsertime.url https://www.cnn.com/2021/03/22/weather/climate-change-warm-waters-lake-michigan/index.html --browsertime.post_startup_delay 1000 --iterations 5 --browsertime.secondary_url https://www.cnn.com/weather --browsertime.commands  --viewPort 1280x1024 --browser firefox --firefox.binaryPath /home/cltbld/tasks/task_165267645178850/build/application/firefox/firefox --firefox.profileTemplate /tmp/tmprrz_jn2o/profile --resultDir /home/cltbld/tasks/task_165267645178850/build/blobber_upload_dir/browsertime-results/cnn --video true --visualMetrics true --visualMetricsContentful true --visualMetricsPerceptual true --visualMetricsPortable true --videoParams.keepOriginalVideo true --firefox.windowRecorder true
[task 2022-05-16T04:49:02.812Z] 04:49:02     INFO -  raptor-browsertime Info: browsertime_ffmpeg: /home/cltbld/tasks/task_165267645178850/fetches/ffmpeg-4.1.4-i686-static/ffmpeg
[task 2022-05-16T04:49:02.812Z] 04:49:02     INFO -  raptor-browsertime Info: PATH: b'/home/cltbld/tasks/task_165267645178850/fetches/ffmpeg-4.1.4-i686-static:/home/cltbld/tasks/task_165267645178850/build/venv/bin:/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/bin'
[task 2022-05-16T04:49:03.184Z] 04:49:03     INFO -  raptor-browsertime Info: Running tests using Firefox - 5 iteration(s)
[task 2022-05-16T04:49:03.185Z] 04:49:03     INFO -  raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2022-05-16T04:49:05.378Z] 04:49:05     INFO -  raptor-browsertime Info: Starting a browsertime pageload
[task 2022-05-16T04:49:05.378Z] 04:49:05     INFO -  raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2022-05-16T04:49:06.380Z] 04:49:06     INFO -  raptor-browsertime Info: Navigating to about:blank, count: 0
[task 2022-05-16T04:49:06.381Z] 04:49:06     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 1
[task 2022-05-16T04:49:12.435Z] 04:49:12     INFO -  raptor-browsertime Info: Navigating to primary url:https://www.cnn.com/2021/03/22/weather/climate-change-warm-waters-lake-michigan/index.html
[task 2022-05-16T04:49:12.436Z] 04:49:12     INFO -  raptor-browsertime Info: Cycle 0, waiting for 5000 ms
[task 2022-05-16T04:49:17.436Z] 04:49:17     INFO -  raptor-browsertime Info: Cycle 0, starting the measure
[task 2022-05-16T04:49:17.437Z] 04:49:17     INFO -  raptor-browsertime Info: Testing url https://www.cnn.com/2021/03/22/weather/climate-change-warm-waters-lake-michigan/index.html iteration 1
[task 2022-05-16T04:49:17.439Z] 04:49:17     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2022-05-16T04:53:18.010Z] 04:53:18 CRITICAL -  raptor-browsertime Critical: Browsertime process timed out after waiting 240 seconds for output
[task 2022-05-16T04:53:18.011Z] 04:53:18     INFO -  raptor-perftest Info: Removing temporary directory: /tmp/tmprrz_jn2o
[task 2022-05-16T04:53:18.027Z] 04:53:18    ERROR -  Traceback (most recent call last):
[task 2022-05-16T04:53:18.027Z] 04:53:18     INFO -    File "/home/cltbld/tasks/task_165267645178850/build/tests/raptor/raptor/raptor.py", line 215, in <module>
[task 2022-05-16T04:53:18.027Z] 04:53:18     INFO -      main()
[task 2022-05-16T04:53:18.027Z] 04:53:18     INFO -    File "/home/cltbld/tasks/task_165267645178850/build/tests/raptor/raptor/raptor.py", line 161, in main
[task 2022-05-16T04:53:18.027Z] 04:53:18     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-05-16T04:53:18.028Z] 04:53:18     INFO -    File "/home/cltbld/tasks/task_165267645178850/build/tests/raptor/raptor/perftest.py", line 462, in run_tests
[task 2022-05-16T04:53:18.028Z] 04:53:18     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2022-05-16T04:53:18.028Z] 04:53:18     INFO -    File "/home/cltbld/tasks/task_165267645178850/build/tests/raptor/raptor/browsertime/base.py", line 592, in run_test
[task 2022-05-16T04:53:18.028Z] 04:53:18     INFO -      f"Browsertime process timed out after waiting {output_timeout} seconds "
[task 2022-05-16T04:53:18.028Z] 04:53:18     INFO -  Exception: Browsertime process timed out after waiting 240 seconds for output
[task 2022-05-16T04:53:18.089Z] 04:53:18    ERROR - Return code: 1
[task 2022-05-16T04:53:18.089Z] 04:53:18  WARNING - setting return code to 1

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

:sparky, since you are the author of the regressor, bug 1767797, could you take a look?
For more information, please visit auto_nag documentation.

Flags: needinfo?(gmierz2)
Has Regression Range: --- → yes

The patch only changed the failure signature (so it didn't exactly cause the regression) but I'll monitor it.

Flags: needinfo?(gmierz2)

Failing with 120 seconds for output on beta after the merge: https://treeherder.mozilla.org/logviewer?job_id=379649835&repo=mozilla-beta

Summary: Intermittent [tier 2] raptor-browsertime Critical: Browsertime process timed out after waiting 240 seconds for output → Intermittent [tier 2] raptor-browsertime Critical: Browsertime process timed out after waiting 120/240 seconds for output

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

There are 35 total failures in the last 7 days on

[task 2022-06-04T12:02:56.580Z] 12:02:56     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2022-06-04T12:03:03.765Z] 12:03:03     INFO -  raptor-browsertime Info: https://imgur.com/gallery/m5tYJL6 has been tested before within the same run, it will get an extra query parameter named browsertime_run. Make sure to use alias to keep track of the URLs
[task 2022-06-04T12:03:03.767Z] 12:03:03     INFO -  raptor-browsertime Info: Stop firefox window recorder.
[task 2022-06-04T12:03:39.446Z] 12:03:39     INFO -  raptor-browsertime Info: Browsertime pageload ended.
[task 2022-06-04T12:03:42.009Z] 12:03:42     INFO -  raptor-browsertime Info: Get visual metrics from the video
[task 2022-06-04T12:03:48.631Z] 12:03:48     INFO -  raptor-browsertime Info: Get visual metrics from the video
[task 2022-06-04T12:03:53.740Z] 12:03:53     INFO -  raptor-browsertime Info: https://imgur.com/gallery/m5tYJL6 TTFB: 9ms DOMContentLoaded: 393ms firstPaint: 173ms FCP: 572ms Load: 1.60s
[task 2022-06-04T12:03:53.740Z] 12:03:53     INFO -  raptor-browsertime Info: VisualMetrics: FirstVisualChange: 640ms SpeedIndex: 733ms PerceptualSpeedIndex: 770ms ContentfulSpeedIndex: 922ms VisualComplete85: 960ms LastVisualChange: 6.92s
[task 2022-06-04T12:03:53.741Z] 12:03:53     INFO -  raptor-browsertime Info: https://imgur.com/gallery/m5tYJL6?browsertime_run=2 DOMContentLoaded: 259ms firstPaint: 72ms FCP: 388ms Load: 448ms
[task 2022-06-04T12:03:53.741Z] 12:03:53     INFO -  raptor-browsertime Info: VisualMetrics: FirstVisualChange: 320ms SpeedIndex: 390ms PerceptualSpeedIndex: 383ms ContentfulSpeedIndex: 460ms VisualComplete85: 520ms LastVisualChange: 3.36s
[task 2022-06-04T12:03:53.743Z] 12:03:53     INFO -  raptor-browsertime Info: Skip setting default preferences for Firefox
[task 2022-06-04T12:03:56.822Z] 12:03:56     INFO -  raptor-browsertime Info: Starting a browsertime pageload
[task 2022-06-04T12:03:56.823Z] 12:03:56     INFO -  raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2022-06-04T12:03:57.965Z] 12:03:57     INFO -  raptor-browsertime Info: Navigating to about:blank, count: 0
[task 2022-06-04T12:03:57.965Z] 12:03:57     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 5
[task 2022-06-04T12:04:03.064Z] 12:04:03     INFO -  raptor-browsertime Info: Navigating to primary url:https://imgur.com/gallery/m5tYJL6
[task 2022-06-04T12:04:03.064Z] 12:04:03     INFO -  raptor-browsertime Info: Cycle 0, waiting for 1000 ms
[task 2022-06-04T12:04:04.181Z] 12:04:04     INFO -  raptor-browsertime Info: Cycle 0, starting the measure
[task 2022-06-04T12:04:04.182Z] 12:04:04     INFO -  raptor-browsertime Info: Testing url https://imgur.com/gallery/m5tYJL6 iteration 5
[task 2022-06-04T12:04:04.182Z] 12:04:04     INFO -  raptor-browsertime Info: Start firefox window recorder.
[task 2022-06-04T12:05:02.400Z] 12:05:02     INFO -  raptor-browsertime Info: Stop firefox window recorder.
[task 2022-06-04T12:07:02.479Z] 12:07:02 CRITICAL -  raptor-browsertime Critical: Browsertime process timed out after waiting 120 seconds for output
[task 2022-06-04T12:07:02.480Z] 12:07:02     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2022-06-04T12:07:02.480Z] 12:07:02     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2022-06-04T12:07:02.480Z] 12:07:02     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 967
[task 2022-06-04T12:07:02.829Z] 12:07:02     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2022-06-04T12:07:02.829Z] 12:07:02     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2022-06-04T12:07:02.829Z] 12:07:02     INFO -  raptor-mitmproxy Info: writing: /opt/worker/tasks/task_165434360381716/build/application/Firefox Nightly.app/Contents/Resources/distribution/policies.json
[task 2022-06-04T12:07:02.831Z] 12:07:02     INFO -  raptor-perftest Info: Removing temporary directory: /var/folders/gp/cjhz6dpx30jfxz1n_z6r2kqc000014/T/tmp1yy0bryb
[task 2022-06-04T12:07:02.854Z] 12:07:02    ERROR -  Traceback (most recent call last):
[task 2022-06-04T12:07:02.854Z] 12:07:02     INFO -    File "/opt/worker/tasks/task_165434360381716/build/tests/raptor/raptor/raptor.py", line 203, in <module>
[task 2022-06-04T12:07:02.854Z] 12:07:02     INFO -      main()
[task 2022-06-04T12:07:02.855Z] 12:07:02     INFO -    File "/opt/worker/tasks/task_165434360381716/build/tests/raptor/raptor/raptor.py", line 149, in main
[task 2022-06-04T12:07:02.855Z] 12:07:02     INFO -      success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2022-06-04T12:07:02.855Z] 12:07:02     INFO -    File "/opt/worker/tasks/task_165434360381716/build/tests/raptor/raptor/perftest.py", line 459, in run_tests
[task 2022-06-04T12:07:02.855Z] 12:07:02     INFO -      self.run_test(test, timeout=int(test.get("page_timeout")))
[task 2022-06-04T12:07:02.856Z] 12:07:02     INFO -    File "/opt/worker/tasks/task_165434360381716/build/tests/raptor/raptor/browsertime/base.py", line 592, in run_test
[task 2022-06-04T12:07:02.856Z] 12:07:02     INFO -      f"Browsertime process timed out after waiting {output_timeout} seconds "
[task 2022-06-04T12:07:02.856Z] 12:07:02     INFO -  Exception: Browsertime process timed out after waiting 120 seconds for output
[task 2022-06-04T12:07:02.996Z] 12:07:02    ERROR - Return code: 1

Greg are you working on this?

Flags: needinfo?(gmierz2)
Whiteboard: [stockwell needswork:owner]

No I wasn't, thanks for the need info.

:alexandrui, can you look into this issue? I think we need to re-record imgur here.

(leaving ni? open for myself)

Flags: needinfo?(aionescu)

sparky, this is for live sites.
edit: comment 0 is about live sites, which was regressed by the doubling of the timeout which applies only for live sites. the recording is not affected by that, so the intermittent probably should be reassigned.

Flags: needinfo?(aionescu)

To be clear, are you going to attempt to re-record it?

Flags: needinfo?(gmierz2) → needinfo?(aionescu)
See Also: → 1768867

:alexandrui, do you have any updates on the backfill?

Flags: needinfo?(aionescu)

It shows that bug 1710421 caused the intermittent, but whimboo said that it's not the case. He helped me with the patch that would fix this.

Flags: needinfo?(aionescu)
Assignee: nobody → aionescu
Status: NEW → ASSIGNED
Pushed by aionescu@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/f4a4e8cf5be0 Fix imgur intermittent r=perftest-reviewers,sparky
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → 103 Branch

The patch landed in nightly and beta is affected.
:alexandrui, is this bug important enough to require an uplift?

  • If yes, please nominate the patch for beta approval.
  • If no, please set status-firefox102 to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(aionescu)
Flags: needinfo?(aionescu)
See Also: → 1774954

(In reply to Pulsebot from comment #24)

Pushed by aionescu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/f4a4e8cf5be0
Fix imgur intermittent r=perftest-reviewers,sparky

== Change summary for alert #34563 (as of Fri, 17 Jun 2022 23:20:29 GMT) ==

Regressions:

Ratio Test Platform Options Absolute values (old vs new)
5% imgur fcp windows10-64-shippable-qr cold fission webrender 687.79 -> 725.17

For up to date results, see: https://treeherder.mozilla.org/perfherder/alerts?id=34563

See Also: → 1784176
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: