1731189 - Perma [tier 2] raptor-main Critical: TEST-UNEXPECTED-FAIL: no raptor test results were found for process-switch

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

task 2021-09-17T05:42:51.744Z] 05:42:51     INFO -  raptor-mitmproxy Info: Verified mitmproxy CA certificate is installed in Firefox
[task 2021-09-17T05:42:51.745Z] 05:42:51     INFO -  raptor-browsertime Info: test: {'here': '/opt/worker/tasks/task_163185726043943/build/tests/raptor/raptor/tests/custom', 'alert_on': ['fcp', 'loadtime'], 'alert_threshold': '2.0', 'apps': 'firefox, chrome, chromium', 'browser_cycles': '25', 'lower_is_better': True, 'measure': ['fnbpaint', 'fcp', 'dcf', 'loadtime'], 'page_cycles': 2, 'page_timeout': '60000', 'playback': 'mitmproxy', 'playback_version': '5.1.1', 'type': 'pageload', 'unit': 'ms', 'use_live_sites': 'false', 'test_url': 'https://mozilla.seanfeng.dev/files/red.html,https://mozilla.pettay.fi/moztests/blue.html', 'test_script': 'process_switch.js', 'accept_zero_vismet': True, 'browsertime_args': '--pageCompleteWaitTime=1000 --pageCompleteCheckInactivity=true', 'playback_pageset_manifest': 'mitm5-linux-firefox-proc-switch.manifest', 'name': 'process-switch', 'manifest': '/opt/worker/tasks/task_163185726043943/build/tests/raptor/raptor/tests/custom/browsertime-process-switch.ini', 'manifest_relpath': 'tests/custom/browsertime-process-switch.ini', 'path': '/opt/worker/tasks/task_163185726043943/build/tests/raptor/raptor/tests/custom/process-switch', 'relpath': 'tests/custom/process-switch', 'ancestor_manifest': 'raptor.ini', 'expected': 'pass', 'cold': True, 'expected_browser_cycles': 25, 'browser_cycle': 1}
[task 2021-09-17T05:42:51.745Z] 05:42:51     INFO -  raptor-browsertime-desktop Info: binary_path: /opt/worker/tasks/task_163185726043943/build/application/Firefox Nightly.app/Contents/MacOS/firefox
[task 2021-09-17T05:42:51.745Z] 05:42:51     INFO -  raptor-browsertime Info: Using Firefox Window Recorder for videos
[task 2021-09-17T05:42:51.746Z] 05:42:51     INFO -  raptor-browsertime Info: timeout (s): 60000
[task 2021-09-17T05:42:51.746Z] 05:42:51     INFO -  raptor-browsertime Info: browsertime cwd: /opt/worker/tasks/task_163185726043943/build
[task 2021-09-17T05:42:51.747Z] 05:42:51     INFO -  raptor-browsertime Info: browsertime cmd: /opt/worker/tasks/task_163185726043943/fetches/node/bin/node /opt/worker/tasks/task_163185726043943/fetches/browsertime/node_modules/browsertime/bin/browsertime.js --firefox.geckodriverPath /opt/worker/tasks/task_163185726043943/fetches/geckodriver /opt/worker/tasks/task_163185726043943/build/tests/raptor/raptor/browsertime/../../browsertime/process_switch.js --viewPort 1024x768 --browser firefox --firefox.binaryPath /opt/worker/tasks/task_163185726043943/build/application/Firefox Nightly.app/Contents/MacOS/firefox --browsertime.page_cycles 2 --browsertime.url https://mozilla.seanfeng.dev/files/red.html,https://mozilla.pettay.fi/moztests/blue.html --browsertime.page_cycle_delay 1000 --browsertime.post_startup_delay 1000 --pageCompleteWaitTime 5000 --firefox.profileTemplate /var/folders/jc/d05gr1rn64b7fn434c51mr68000014/T/tmp9gy13tj6/profile --skipHar --pageLoadStrategy none --webdriverPageload true --firefox.disableBrowsertimeExtension true --pageCompleteCheckStartWait 5000 --pageCompleteCheckPollTimeout 1000 --timeouts.pageLoad 60000 --timeouts.script 120000 --resultDir /opt/worker/tasks/task_163185726043943/build/blobber_upload_dir/browsertime-results/process-switch --firefox.env MOZ_WEBRENDER=1 --firefox.env MOZ_ACCELERATED=1 --video true --visualMetrics false --firefox.windowRecorder true --pageCompleteWaitTime 1000 --pageCompleteCheckInactivity true -n 25
[task 2021-09-17T05:42:51.748Z] 05:42:51     INFO -  raptor-browsertime Info: browsertime_ffmpeg: /opt/worker/tasks/task_163185726043943/fetches/ffmpeg-4.1.1-macos64-static/bin/ffmpeg
[task 2021-09-17T05:42:51.748Z] 05:42:51     INFO -  raptor-browsertime Info: PATH: b'/opt/worker/tasks/task_163185726043943/fetches/ffmpeg-4.1.1-macos64-static/bin:/opt/worker/tasks/task_163185726043943/build/venv/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin'
[task 2021-09-17T05:42:52.309Z] 05:42:52     INFO -  raptor-browsertime Info: Running tests using Firefox - 25 iteration(s)
[task 2021-09-17T05:42:55.207Z] 05:42:55     INFO -  raptor-browsertime Info: Starting a process switch test
[task 2021-09-17T05:42:55.207Z] 05:42:55     INFO -  raptor-browsertime Info: Waiting for 1000 ms (post_startup_delay)
[task 2021-09-17T05:42:56.213Z] 05:42:56     INFO -  raptor-browsertime Info: Navigating to about:blank
[task 2021-09-17T05:42:56.213Z] 05:42:56     INFO -  raptor-browsertime Info: Navigating to url about:blank iteration 1
[task 2021-09-17T05:44:56.255Z] 05:44:56     INFO -  raptor-mitmproxy Info: MitmproxyDesktop stop!!
[task 2021-09-17T05:44:56.255Z] 05:44:56     INFO -  raptor-mitmproxy Info: Mitmproxy stop!!
[task 2021-09-17T05:44:56.255Z] 05:44:56     INFO -  raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 920
[task 2021-09-17T05:44:56.440Z] 05:44:56     INFO -  raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2021-09-17T05:44:56.440Z] 05:44:56     INFO -  raptor-mitmproxy Info: Turning off the browser proxy
[task 2021-09-17T05:44:56.441Z] 05:44:56     INFO -  raptor-mitmproxy Info: writing: /opt/worker/tasks/task_163185726043943/build/application/Firefox Nightly.app/Contents/Resources/distribution/policies.json
[task 2021-09-17T05:44:56.441Z] 05:44:56     INFO -  perftest-results-handler Info: retrieving browsertime test results
[task 2021-09-17T05:44:56.441Z] 05:44:56     INFO -  perftest-results-handler Critical: unable to find browsertime results at /opt/worker/tasks/task_163185726043943/build/blobber_upload_dir/browsertime-results/process-switch/browsertime.json
[task 2021-09-17T05:44:56.442Z] 05:44:56     INFO -  raptor-perftest Info: Removing temporary directory: /var/folders/jc/d05gr1rn64b7fn434c51mr68000014/T/tmp9gy13tj6
[task 2021-09-17T05:44:56.450Z] 05:44:56    ERROR -  raptor-main Critical: TEST-UNEXPECTED-FAIL: no raptor test results were found for process-switch
[task 2021-09-17T05:44:56.529Z] 05:44:56    ERROR - Return code: 1
[task 2021-09-17T05:44:56.529Z] 05:44:56  WARNING - setting return code to 1
[task 2021-09-17T05:44:56.529Z] 05:44:56     INFO - Copying Raptor results to upload dir:
[task 2021-09-17T05:44:56.530Z] 05:44:56     INFO - /opt/worker/tasks/task_163185726043943/build/blobber_upload_dir/perfherder-data.json
[task 2021-09-17T05:44:56.530Z] 05:44:56     INFO - Copying raptor results from /opt/worker/tasks/task_163185726043943/build/raptor.json to /opt/worker/tasks/task_163185726043943/build/blobber_upload_dir/perfherder-data.json
[task 2021-09-17T05:44:56.530Z] 05:44:56 CRITICAL - Error copying results /opt/worker/tasks/task_163185726043943/build/raptor.json to upload dir /opt/worker/tasks/task_163185726043943/build/blobber_upload_dir/perfherder-data.json
[task 2021-09-17T05:44:56.530Z] 05:44:56     INFO - [Errno 2] No such file or directory: '/opt/worker/tasks/task_163185726043943/build/raptor.json'
[task 2021-09-17T05:44:56.530Z] 05:44:56     INFO - Running post-action listener: _package_coverage_data
[task 2021-09-17T05:44:56.530Z] 05:44:56     INFO - Running post-action listener: _resource_record_post_action
[task 2021-09-17T05:44:56.531Z] 05:44:56     INFO - Running post-action listener: process_java_coverage_data
[task 2021-09-17T05:44:56.531Z] 05:44:56     INFO - Running post-action listener: stop_device
[task 2021-09-17T05:44:56.531Z] 05:44:56     INFO - [mozharness: 2021-09-17 05:44:56.531068Z] Finished run-tests step (success)
[task 2021-09-17T05:44:56.531Z] 05:44:56     INFO - Running post-run listener: _resource_record_post_run
[task 2021-09-17T05:44:56.605Z] 05:44:56     INFO - Total resource usage - Wall time: 192s; CPU: 5%; Read bytes: 116232192; Write bytes: 636076032; Read time: 897; Write time: 1369
[task 2021-09-17T05:44:56.605Z] 05:44:56     INFO - TinderboxPrint: CPU usage<br/>4.5%
[task 2021-09-17T05:44:56.605Z] 05:44:56     INFO - TinderboxPrint: I/O read bytes / time<br/>116,232,192 / 897
[task 2021-09-17T05:44:56.605Z] 05:44:56     INFO - TinderboxPrint: I/O write bytes / time<br/>636,076,032 / 1,369
[task 2021-09-17T05:44:56.605Z] 05:44:56     INFO - TinderboxPrint: CPU idle<br/>2,202.1 (95.5%)
[task 2021-09-17T05:44:56.605Z] 05:44:56     INFO - TinderboxPrint: CPU system<br/>33.3 (1.4%)
[task 2021-09-17T05:44:56.605Z] 05:44:56     INFO - TinderboxPrint: CPU user<br/>70.1 (3.0%)
[task 2021-09-17T05:44:56.605Z] 05:44:56     INFO - TinderboxPrint: Swap in / out<br/>691,355,648 / 0
[task 2021-09-17T05:44:56.605Z] 05:44:56     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 2021-09-17T05:44:56.606Z] 05:44:56     INFO - install - Wall time: 32s; CPU: 14%; Read bytes: 420865536; Write bytes: 430731264; Read time: 28192; Write time: 803
[task 2021-09-17T05:44:56.608Z] 05:44:56     INFO - run-tests - Wall time: 161s; CPU: 3%; Read bytes: 110075904; Write bytes: 184074240; Read time: 792; Write time: 527
[task 2021-09-17T05:44:56.654Z] 05:44:56  WARNING - returning nonzero exit status 1
[taskcluster 2021-09-17T05:44:56.683Z]    Exit Code: 1
[taskcluster 2021-09-17T05:44:56.683Z]    User Time: 56.077016s
[taskcluster 2021-09-17T05:44:56.683Z]  Kernel Time: 11.471905s
[taskcluster 2021-09-17T05:44:56.683Z]    Wall Time: 3m54.201989s
[taskcluster 2021-09-17T05:44:56.683Z]       Result: FAILED
[taskcluster 2021-09-17T05:44:56.683Z] === Task Finished ===
[taskcluster 2021-09-17T05:44:56.683Z] Task Duration: 3m54.206141s
[taskcluster 2021-09-17T05:44:56.812Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2022-09-17T03:41:46.097Z
[taskcluster 2021-09-17T05:44:57.025Z] Uploading artifact public/test_info/mitmproxy.log from file build/blobber_upload_dir/mitmproxy.log with content encoding "gzip", mime type "text/plain" and expiry 2022-09-17T03:41:46.097Z
[taskcluster 2021-09-17T05:44:57.170Z] 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 2022-09-17T03:41:46.097Z
[taskcluster 2021-09-17T05:44:57.628Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XvFG5ddgR6OueYZm91GAXQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2022-09-17T03:41:46.097Z
[taskcluster:error] exit status 1

Comment 1

[Andreea Pavel [:apavel]]

Retriggers: https://treeherder.mozilla.org/jobs?repo=autoland&selectedTaskRun=MugIXEj9TmGIFl6cBGZSIQ.0&resultStatus=success%2Cpending%2Crunning%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&searchStr=windows%2C10%2Cx64%2Cwebrender%2Cshippable%2Copt%2Cbrowsertime%2Cperformance%2Ctests%2Con%2Cfirefox%2Ctest-windows10-64-shippable-qr%2Fopt-browsertime-custom-firefox-process-switch-e10s%2Cps&tochange=81f1e8a36a0cfdd957e62137f1f11d8ad515e8f8&fromchange=b5456abe453555e2e1570b1fd8dc059c65347322

Joel, can you please take a look?

Comment 2

[Intermittent Failures Robot]

45 failures in 825 pushes (0.055 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 31
• autoland: 14

Platform and build breakdown:

• macosx1014-64-shippable-qr: 13
  • opt: 13
• macosx1015-64-shippable-qr: 13
  • opt: 13
• linux1804-64-shippable-qr: 6
  • opt: 6
• windows10-64-shippable-qr: 6
  • opt: 6
• linux1804-64-qr: 1
  • opt: 1
• windows10-64-qr: 1
  • opt: 1
• windows10-32-qr: 1
  • opt: 1
• linux1804-64-clang-trunk-qr: 2
  • opt: 2
• windows10-32-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1731189&startday=2021-09-17&endday=2021-09-17&tree=all

Comment 3

[Intermittent Failures Robot]

17 failures in 87 pushes (0.195 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 17

Platform and build breakdown:

• linux1804-64-shippable-qr: 4
  • opt: 4
• windows10-64-shippable-qr: 4
  • opt: 4
• macosx1014-64-shippable-qr: 4
  • opt: 4
• macosx1015-64-shippable-qr: 4
  • opt: 4
• linux1804-64-clang-trunk-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1731189&startday=2021-09-18&endday=2021-09-18&tree=all

Comment 4

[Intermittent Failures Robot]

99 failures in 3375 pushes (0.029 failures/push) were associated with this bug in the last 7 days.

This is the #5 most frequent failure this week.

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 57
• autoland: 42

Platform and build breakdown:

• macosx1014-64-shippable-qr: 19
  • opt: 19
• macosx1015-64-shippable-qr: 19
  • opt: 19
• windows10-64-shippable-qr: 40
  • opt: 40
• linux1804-64-shippable-qr: 12
  • opt: 12
• linux1804-64-qr: 1
  • opt: 1
• windows10-64-qr: 1
  • opt: 1
• windows10-32-qr: 1
  • opt: 1
• linux1804-64-clang-trunk-qr: 4
  • opt: 4
• windows10-32-shippable-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1731189&startday=2021-09-13&endday=2021-09-19&tree=all

Comment 5

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 6

[Greg Mierzwinski [:sparky]]

Attachment: Bug 1731189 - Combine browsertime_script and browsertime_options into a single variable. r?#perftest

This patch changes how we check for existing options when we are replacing them with settings from a browsertime_args entry in a test manifest. Previously, we only checked browsertime_options but browsertime_script also had settings in it which resulted in duplicate arguments being passed. See bug 1731607 for future work around this issue.

Comment 7

[Joel Maher ( :jmaher ) (UTC -8)]

Attachment: Bug 1731189 - fix logic error in adding --pageCompleteWaitTime cli argument to raptor. r=#perftest-reviewers!

try push showing 3 different pageCompleteWaitTime uses:
https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=fx3p6eFgTcyThBomkfXCFw.0&revision=27ba4e231dc18e1f888c56d3fc3e7fa4689abd45

Comment 8

[Greg Mierzwinski [:sparky]]

:jmaher, you can abandon your patch. Sorry about that, I forgot to mention that I made a patch for this here: https://phabricator.services.mozilla.com/D126099

It was caused by a conflict in how our options are getting setup. I've also filed this bug for follow-up work on parsing browsertime arguments: https://bugzilla.mozilla.org/show_bug.cgi?id=1731607

Comment 9

[Joel Maher ( :jmaher ) (UTC -8)]

there will still be a case where we have >1 entry of --pageCompleteWaitTime; With the referenced cleanup of options that would make it a simpler check. is there something I might be missing?

Comment 10

[Intermittent Failures Robot]

34 failures in 638 pushes (0.053 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 34

Platform and build breakdown:

• linux1804-64-shippable-qr: 8
  • opt: 8
• windows10-64-shippable-qr: 8
  • opt: 8
• macosx1015-64-shippable-qr: 8
  • opt: 8
• macosx1014-64-shippable-qr: 8
  • opt: 8
• macosx1100-64-shippable-qr: 1
  • opt: 1
• linux1804-64-clang-trunk-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1731189&startday=2021-09-20&endday=2021-09-20&tree=all

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/07e90ae59d8c
Combine browsertime_script and browsertime_options into a single variable. r=perftest-reviewers,kimberlythegeek

Comment 12

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/07e90ae59d8c

Comment 13

[Intermittent Failures Robot]

24 failures in 671 pushes (0.036 failures/push) were associated with this bug yesterday.

** This test has failed more than 150 times in the last 21 days. It should be disabled until it can be fixed. **

Repository breakdown:

• mozilla-central: 24

Platform and build breakdown:

• windows10-64-shippable-qr: 6
  • opt: 6
• linux1804-64-shippable-qr: 6
  • opt: 6
• macosx1015-64-shippable-qr: 6
  • opt: 6
• macosx1014-64-shippable-qr: 6
  • opt: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1731189&startday=2021-09-21&endday=2021-09-21&tree=all

Comment 14

[Greg Mierzwinski [:sparky]]

(In reply to Joel Maher ( :jmaher ) (UTC -0800) from comment #9)

there will still be a case where we have >1 entry of --pageCompleteWaitTime; With the referenced cleanup of options that would make it a simpler check. is there something I might be missing?

No you're not missing anything we still have an issue there (for this and other flags), but :aglavic will start working on bug 1731607 shortly so it'll be resolved soon.

Comment 15

[Intermittent Failures Robot]

58 failures in 2873 pushes (0.02 failures/push) were associated with this bug in the last 7 days.

This is the #16 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 58

Platform and build breakdown:

• linux1804-64-shippable-qr: 14
  • opt: 14
• windows10-64-shippable-qr: 14
  • opt: 14
• macosx1015-64-shippable-qr: 14
  • opt: 14
• macosx1014-64-shippable-qr: 14
  • opt: 14
• macosx1100-64-shippable-qr: 1
  • opt: 1
• linux1804-64-clang-trunk-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1731189&startday=2021-09-20&endday=2021-09-26&tree=all