Closed Bug 1625912 Opened 4 years ago Closed 4 years ago

Perma [tier2] raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-webaudio-chromium' timed out loading test page: http://127.0.0.1:58200/webaudio/index.html?raptor

Categories

(Testing :: Raptor, defect, P5)

Product:
Testing
Component:
Raptor
Version:
Version 3
Type:
defect

Tracking

(firefox-esr68 unaffected, firefox75 unaffected, firefox76 fixed, firefox77 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla77
Tracking Flags:
Tracking Status
firefox-esr68 --- unaffected
firefox75 --- unaffected
firefox76 --- fixed
firefox77 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, perf-alert)

Attachments

(2 files)

Bug 1625912 - Update webaudio-benchmark to revision d753e161. r?dmajor
47 bytes, text/x-phabricator-request
Details | Review
Bug 1625912 - Lower the duration of the rendered buffers in Web Audio benchmark. r?dmajor
47 bytes, text/x-phabricator-request
Details | Review

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

[task 2020-03-30T11:36:22.202Z] 11:36:22     INFO -  raptor-webext-desktop Info: starting chromium
[task 2020-03-30T11:36:22.202Z] 11:36:22     INFO -  Application command: /home/cltbld/tasks/task_1585568125/fetches/chrome-linux/chrome --user-data-dir=/tmp/tmpbkrneW.mozrunner --profile-directory=Default --no-first-run --use-mock-keychain --no-default-browser-check --load-extension=/home/cltbld/tasks/task_1585568125/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-03-30T11:36:22.549Z] 11:36:22     INFO -  raptor-control-server Info: received webext_status: raptor runner.js is loaded!
[task 2020-03-30T11:36:22.550Z] 11:36:22     INFO -  raptor-control-server Info: received webext_status: test name is: raptor-webaudio-chromium
[task 2020-03-30T11:36:22.552Z] 11:36:22     INFO -  raptor-control-server Info: received webext_status: test settings url is: http://127.0.0.1:40909/json/raptor-webaudio-chromium.json
[task 2020-03-30T11:36:22.555Z] 11:36:22     INFO -  raptor-control-server Info: received webext_status: starting raptorRunner
[task 2020-03-30T11:36:22.556Z] 11:36:22     INFO -  raptor-control-server Info: reading test settings from json/raptor-webaudio-chromium.json
[task 2020-03-30T11:36:22.558Z] 11:36:22     INFO -  raptor-control-server Info: sent test settings to webext runner
[task 2020-03-30T11:36:22.578Z] 11:36:22     INFO -  raptor-control-server Info: received webext_status: * pausing 1 seconds to let browser settle... *
[task 2020-03-30T11:36:23.584Z] 11:36:23     INFO -  raptor-control-server Info: received webext_status: running 5 pagecycles of http://127.0.0.1:58200/webaudio/index.html?raptor
[task 2020-03-30T11:36:23.600Z] 11:36:23     INFO -  raptor-control-server Info: received webext_status: opened new empty tab: 3
[task 2020-03-30T11:36:24.605Z] 11:36:24     INFO -  raptor-control-server Info: received webext_status: begin pagecycle 1
[task 2020-03-30T11:36:25.604Z] 11:36:25     INFO -  raptor-control-server Info: received webext_status: update tab: 3
[task 2020-03-30T11:36:25.611Z] 11:36:25     INFO -  raptor-control-server Info: received webext_status: test tab updated: 3
[task 2020-03-30T11:39:25.618Z] 11:39:25     INFO -  raptor-control-server Info: received webext_raptor-page-timeout: [u'raptor-webaudio-chromium', u'http://127.0.0.1:58200/webaudio/index.html?raptor']
[task 2020-03-30T11:39:25.674Z] 11:39:25     INFO -  raptor-control-server Info: received webext_screenshot
[task 2020-03-30T11:39:25.674Z] 11:39:25     INFO -  perftest-results-handler Info: received screenshot
[task 2020-03-30T11:39:25.674Z] 11:39:25     INFO -  raptor-control-server Info: received request to shutdown the browser
[task 2020-03-30T11:39:25.674Z] 11:39:25     INFO -  raptor-control-server Info: shutting down browser (pid: 3535)
[task 2020-03-30T11:39:25.682Z] 11:39:25     INFO -  raptor-control-server Info: received webext_status: Removed tab: 3
[task 2020-03-30T11:39:27.383Z] 11:39:27     INFO -  raptor-webext Info: removing webext /home/cltbld/tasks/task_1585568125/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-03-30T11:39:27.383Z] 11:39:27     INFO -  perftest-results-handler Info: summarizing raptor test results
[task 2020-03-30T11:39:27.383Z] 11:39:27     INFO -  perftest-output Error: no raptor test results found for raptor-webaudio-chromium
[task 2020-03-30T11:39:27.383Z] 11:39:27     INFO -  perftest-output Info: error: no raptor test results found, so no need to combine browser cycles
[task 2020-03-30T11:39:27.384Z] 11:39:27     INFO -  perftest-output Error: no summarized raptor results found for raptor-webaudio-chromium
[task 2020-03-30T11:39:27.384Z] 11:39:27     INFO -  perftest-output Info: screen captures can be found locally at: /home/cltbld/tasks/task_1585568125/build/screenshots.html
[task 2020-03-30T11:39:27.399Z] 11:39:27     INFO -  perftest-results-handler Critical: PERFHERDER_DATA was seen 0 times, expected 1.
[task 2020-03-30T11:39:27.400Z] 11:39:27     INFO -  raptor-control-server Info: shutting down control server
[task 2020-03-30T11:39:27.684Z] 11:39:27     INFO -  raptor-webext Info: finished
[task 2020-03-30T11:39:27.685Z] 11:39:27    ERROR -  raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-webaudio-chromium' timed out loading test page: http://127.0.0.1:58200/webaudio/index.html?raptor
[task 2020-03-30T11:39:27.739Z] 11:39:27    ERROR - Return code: 1
[task 2020-03-30T11:39:27.739Z] 11:39:27  WARNING - setting return code to 1
[task 2020-03-30T11:39:27.739Z] 11:39:27     INFO - Copying Raptor results to upload dir:
[task 2020-03-30T11:39:27.739Z] 11:39:27     INFO - /home/cltbld/tasks/task_1585568125/build/blobber_upload_dir/perfherder-data.json
[task 2020-03-30T11:39:27.740Z] 11:39:27     INFO - Copying raptor results from /home/cltbld/tasks/task_1585568125/build/raptor.json to /home/cltbld/tasks/task_1585568125/build/blobber_upload_dir/perfherder-data.json
[task 2020-03-30T11:39:27.740Z] 11:39:27 CRITICAL - Error copying results /home/cltbld/tasks/task_1585568125/build/raptor.json to upload dir /home/cltbld/tasks/task_1585568125/build/blobber_upload_dir/perfherder-data.json
[task 2020-03-30T11:39:27.740Z] 11:39:27     INFO - [Errno 2] No such file or directory: u'/home/cltbld/tasks/task_1585568125/build/raptor.json'
[task 2020-03-30T11:39:27.741Z] 11:39:27     INFO - /home/cltbld/tasks/task_1585568125/build/blobber_upload_dir/screenshots.html
[task 2020-03-30T11:39:27.741Z] 11:39:27     INFO - Copying raptor results from /home/cltbld/tasks/task_1585568125/build/screenshots.html to /home/cltbld/tasks/task_1585568125/build/blobber_upload_dir/screenshots.html
[task 2020-03-30T11:39:27.741Z] 11:39:27     INFO - Running post-action listener: _package_coverage_data
[task 2020-03-30T11:39:27.742Z] 11:39:27     INFO - Running post-action listener: _resource_record_post_action
[task 2020-03-30T11:39:27.742Z] 11:39:27     INFO - Running post-action listener: process_java_coverage_data
[task 2020-03-30T11:39:27.742Z] 11:39:27     INFO - Running post-action listener: stop_device
[task 2020-03-30T11:39:27.742Z] 11:39:27     INFO - [mozharness: 2020-03-30 11:39:27.742331Z] Finished run-tests step (success)
[task 2020-03-30T11:39:27.742Z] 11:39:27     INFO - Running post-run listener: _resource_record_post_run
[task 2020-03-30T11:39:27.792Z] 11:39:27     INFO - Total resource usage - Wall time: 193s; CPU: 13.0%; Read bytes: 7323648; Write bytes: 954192384; Read time: 640; Write time: 61984
[task 2020-03-30T11:39:27.792Z] 11:39:27     INFO - TinderboxPrint: CPU usage<br/>12.6%
[task 2020-03-30T11:39:27.792Z] 11:39:27     INFO - TinderboxPrint: I/O read bytes / time<br/>7,323,648 / 640
[task 2020-03-30T11:39:27.792Z] 11:39:27     INFO - TinderboxPrint: I/O write bytes / time<br/>954,192,384 / 61,984
[task 2020-03-30T11:39:27.792Z] 11:39:27     INFO - TinderboxPrint: CPU idle<br/>1,344.5 (87.2%)
[task 2020-03-30T11:39:27.792Z] 11:39:27     INFO - TinderboxPrint: CPU user<br/>192.5 (12.5%)
[task 2020-03-30T11:39:27.792Z] 11:39:27     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2020-03-30T11:39:27.792Z] 11:39:27     INFO - install - Wall time: 8s; CPU: 13.0%; Read bytes: 4096; Write bytes: 472138240; Read time: 148; Write time: 32908
[task 2020-03-30T11:39:27.795Z] 11:39:27     INFO - run-tests - Wall time: 186s; CPU: 13.0%; Read bytes: 6983680; Write bytes: 482054144; Read time: 360; Write time: 29076
[task 2020-03-30T11:39:27.843Z] 11:39:27  WARNING - returning nonzero exit status 1
[fetches 2020-03-30T11:39:27.859Z] removing /home/cltbld/tasks/task_1585568125/fetches
[fetches 2020-03-30T11:39:27.905Z] finished
[taskcluster 2020-03-30T11:39:27.913Z]    Exit Code: 1
[taskcluster 2020-03-30T11:39:27.913Z]    User Time: 3m45.5s
[taskcluster 2020-03-30T11:39:27.913Z]  Kernel Time: 4.576s
[taskcluster 2020-03-30T11:39:27.913Z]    Wall Time: 4m0.953659186s
[taskcluster 2020-03-30T11:39:27.913Z]       Result: FAILED
[taskcluster 2020-03-30T11:39:27.913Z] === Task Finished ===
[taskcluster 2020-03-30T11:39:27.913Z] Task Duration: 4m0.954338674s
[taskcluster 2020-03-30T11:39:28.117Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2021-03-30T10:32:16.011Z
[taskcluster 2020-03-30T11:39:28.377Z] 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 2021-03-30T10:32:16.011Z
[taskcluster 2020-03-30T11:39:28.584Z] Uploading artifact public/test_info/screenshots.html from file build/blobber_upload_dir/screenshots.html with content encoding "gzip", mime type "text/html; charset=utf-8" and expiry 2021-03-30T10:32:16.011Z
[taskcluster:error] exit status 1

Looks like Chrome is timing out because it's too slow. I'm making adjustments upstream and will update here.

Flags: needinfo?(padenot)
Assignee: nobody → padenot
Status: NEW → ASSIGNED
Attachment #9136764 - Attachment description: Bug 1625912 - Update webaudio-benchmark to revision 04379fdaaab66. r?dmajor → Bug 1625912 - Update webaudio-benchmark to revision d753e161. r?dmajor
Pushed by padenot@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e70a66b181f8
Update webaudio-benchmark to revision d753e161. r=dmajor

https://hg.mozilla.org/mozilla-central/rev/e70a66b181f8

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox76: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla76

== Change summary for alert #25527 (as of Wed, 01 Apr 2020 23:14:00 GMT) ==

Improvements:

14% raptor-webaudio-firefox linux64-shippable opt 176.83 -> 151.67
11% raptor-webaudio-firefox linux64-shippable-qr opt 176.17 -> 156.75
9% raptor-webaudio-firefox windows7-32-shippable opt 208.92 -> 190.42
9% raptor-webaudio-firefox windows10-64-shippable opt 186.33 -> 170.00
9% raptor-webaudio-firefox windows10-64-shippable-qr opt 185.00 -> 169.00
8% raptor-webaudio-firefox macosx1014-64-shippable opt 207.42 -> 191.42

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=25527

Keywords: perf-alert

== Change summary for alert #25525 (as of Wed, 01 Apr 2020 13:44:44 GMT) ==

Regressions:

0.48% installer size osx-shippable opt nightly 81,499,204.25 -> 81,889,536.25

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=25525

David, how would I go about reducing the duration here? It's still too much for chromium.

Flags: needinfo?(padenot) → needinfo?(dmajor)

The raptor test is here: https://searchfox.org/mozilla-central/source/testing/raptor/raptor/tests/benchmarks/raptor-webaudio.ini

I guess you could modify either the test_url or page_timeout.

Flags: needinfo?(dmajor)

== Change summary for alert #25528 (as of Wed, 01 Apr 2020 23:17:50 GMT) ==

Improvements:

3% displaylist_mutate windows7-32-shippable opt e10s stylo 1,425.54 -> 1,383.59
2% displaylist_mutate windows10-64-shippable opt e10s stylo 1,343.25 -> 1,312.38

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=25528

Given that this bug is marked as fixed, should we continue on bug 1626588 which was freshly filed?

Flags: needinfo?(padenot)
See Also: → 1626588
Status: RESOLVED → REOPENED
Flags: needinfo?(padenot)
Keywords: leave-open
Resolution: FIXED → ---

Let's try this, and watch the numbers. https://bugzilla.mozilla.org/show_bug.cgi?id=1625912#c11 tells me we might be over-training: this new patch divides by two the amount of work done during the benchmark.

Pushed by padenot@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/fa3adf030528
Lower the duration of the rendered buffers in Web Audio benchmark. r=dmajor
status-firefox76: fixed → ---
Target Milestone: mozilla76 → ---

Looks like that took care of it.

Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
status-firefox75: --- → unaffected
status-firefox76: --- → affected
status-firefox77: --- → fixed
status-firefox-esr68: --- → unaffected
Keywords: leave-open
Resolution: --- → FIXED
Target Milestone: --- → mozilla77
Regressions: 1630661
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: