1526088 - Intermittent raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-pinterest-firefox' timed out loading test page: https://pinterest.com/

Status: RESOLVED INCOMPLETE

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

#[markdown(off)]
Filed by: rmaries [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=226982102&repo=mozilla-central

https://queue.taskcluster.net/v1/task/Krv1Kc7yQomqrz-iXZgE9g/runs/0/artifacts/public/logs/live_backing.log

15:04:39 INFO - raptor-output PERFHERDER_DATA: {"framework": {"name": "raptor"}, "suites": [{"extraOptions": [], "name": "raptor-tp6-google-mail-firefox", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 996.51, "subtests": [{"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 286.0, "replicates": [161, 241, 274, 237, 297, 306, 290, 276, 288, 295, 269, 261, 286, 437, 268, 295, 283, 286, 263, 257, 287, 322, 267, 320, 291], "unit": "ms"}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 279.5, "shouldAlert": true, "replicates": [150, 264, 266, 259, 293, 301, 278, 267, 281, 290, 264, 283, 280, 425, 264, 318, 279, 278, 259, 251, 282, 318, 263, 310, 283], "unit": "ms"}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 279.5, "replicates": [150, 264, 266, 259, 293, 301, 278, 267, 281, 290, 264, 283, 280, 425, 264, 318, 279, 278, 259, 251, 282, 318, 263, 310, 283], "unit": "ms"}, {"name": "ttfi", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 7640.5, "replicates": [9740, 10267, 8560, 12556, 8835, 7598, 7673, 7610, 7730, 7333, 7636, 7645, 7509, 7564, 7523, 11499, 13995, 7561, 7345, 11893, 7463, 12911, 7455, 7749, 7584], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 5722.5, "shouldAlert": true, "replicates": [6784, 6095, 5712, 6645, 6844, 5461, 5984, 5071, 5812, 5450, 5893, 5859, 5733, 5755, 5969, 5554, 5276, 5089, 5428, 5745, 5372, 5021, 5779, 5487, 4932], "unit": "ms"}], "type": "pageload", "unit": "ms"}]}
15:04:39 INFO - raptor-output results can also be found locally at: /Users/cltbld/tasks/task_1549580007/build/raptor.json
15:04:39 INFO - raptor-control-server shutting down control server
15:04:39 INFO - raptor-main finished
15:04:39 INFO - raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-pinterest-firefox' timed out loading test page: https://pinterest.com/
15:04:39 ERROR - Return code: 1
15:04:39 WARNING - setting return code to 1
15:04:39 INFO - Validating PERFHERDER_DATA against /Users/cltbld/tasks/task_1549580007/mozharness/external_tools/performance-artifact-schema.json
15:04:39 INFO - copying raptor results to upload dir:
15:04:39 INFO - /Users/cltbld/tasks/task_1549580007/build/blobber_upload_dir/perfherder-data.json
15:04:39 INFO - copying raptor results from /Users/cltbld/tasks/task_1549580007/build/raptor.json to /Users/cltbld/tasks/task_1549580007/build/blobber_upload_dir/perfherder-data.json
15:04:39 INFO - Running pre test command check_screen_resolution with 'bash -c screenresolution get && screenresolution list && system_profiler SPDisplaysDataType'
15:04:39 INFO - Running command: ('bash', '-c', 'screenresolution get && screenresolution list && system_profiler SPDisplaysDataType') in /Users/cltbld/tasks/task_1549580007/build
15:04:39 INFO - Copy/paste: bash -c "screenresolution get && screenresolution list && system_profiler SPDisplaysDataType"
15:04:39 INFO - 2019-02-07 15:04:39.589 screenresolution[629:7622] starting screenresolution argv=screenresolution get
15:04:39 INFO - 2019-02-07 15:04:39.592 screenresolution[629:7622] Display 0: 1600x1200x32@60
15:04:39 INFO - 2019-02-07 15:04:39.598 screenresolution[630:7626] starting screenresolution argv=screenresolution list
15:04:39 INFO - Available Modes on Display 0
15:04:39 INFO - 1600x1200x32@60 1152x870x32@75 1280x1024x32@75
15:04:39 INFO - 1024x768x32@75 1024x768x32@70 1024x768x32@60
15:04:39 INFO - 800x600x32@75 800x600x32@60 640x480x32@75
15:04:39 INFO - 640x480x32@60 1280x1024x32@60 1280x960x32@60
15:04:39 INFO - 1280x960x32@75 1344x1008x32@60 Graphics/Displays:
15:04:39 INFO - Intel Iris:
15:04:39 INFO - Chipset Model: Intel Iris
15:04:39 INFO - Type: GPU
15:04:39 INFO - Bus: Built-In
15:04:39 INFO - VRAM (Dynamic, Max): 1536 MB
15:04:39 INFO - Vendor: Intel (0x8086)
15:04:39 INFO - Device ID: 0x0a2e
15:04:39 INFO - Revision ID: 0x0009
15:04:39 INFO - Displays:
15:04:39 INFO - Display:
15:04:39 INFO - Resolution: 1600 x 1200 @ 60 Hz
15:04:39 INFO - Pixel Depth: 32-Bit Color (ARGB8888)
15:04:39 INFO - Display Serial Number: 1600x1200 60
15:04:39 INFO - Main Display: Yes
15:04:39 INFO - Mirror: Off
15:04:39 INFO - Online: Yes
15:04:39 INFO - Rotation: Supported
15:04:39 INFO - Return code: 0
15:04:39 INFO - Running post-action listener: _package_coverage_data
15:04:39 INFO - Running post-action listener: _resource_record_post_action
15:04:39 INFO - Running post-action listener: process_java_coverage_data
15:04:39 INFO - Running post-action listener: stop_device
15:04:39 INFO - [mozharness: 2019-02-07 23:04:39.835330Z] Finished run-tests step (success)
15:04:39 INFO - Running post-run listener: _resource_record_post_run
15:04:39 INFO - Total resource usage - Wall time: 603s; CPU: 50.0%; Read bytes: 113568768; Write bytes: 842762752; Read time: 733; Write time: 3306
15:04:39 INFO - TinderboxPrint: CPU usage<br/>49.5%
15:04:39 INFO - TinderboxPrint: I/O read bytes / time<br/>113,568,768 / 733
15:04:39 INFO - TinderboxPrint: I/O write bytes / time<br/>842,762,752 / 3,306
15:04:39 INFO - TinderboxPrint: CPU idle<br/>1,218.2 (50.5%)
15:04:39 INFO - TinderboxPrint: CPU system<br/>551.5 (22.9%)
15:04:39 INFO - TinderboxPrint: CPU user<br/>643.3 (26.7%)
15:04:39 INFO - TinderboxPrint: Swap in / out<br/>373,379,072 / 0
15:04:39 INFO - install - Wall time: 25s; CPU: 54.0%; Read bytes: 257468416; Write bytes: 257852928; Read time: 20212; Write time: 539
15:04:39 INFO - run-tests - Wall time: 578s; CPU: 49.0%; Read bytes: 111164416; Write bytes: 583738368; Read time: 712; Write time: 2761
15:04:40 WARNING - returning nonzero exit status 1
[taskcluster 2019-02-07T23:04:40.151Z] Exit Code: 1
[taskcluster 2019-02-07T23:04:40.151Z] User Time: 5m48.314829s
[taskcluster 2019-02-07T23:04:40.151Z] Kernel Time: 59.12929s
[taskcluster 2019-02-07T23:04:40.151Z] Wall Time: 11m9.57796897s
[taskcluster 2019-02-07T23:04:40.151Z] Result: FAILED
[taskcluster 2019-02-07T23:04:40.151Z] === Task Finished ===
[taskcluster 2019-02-07T23:04:40.151Z] Task Duration: 11m9.578195935s
[taskcluster 2019-02-07T23:04:40.762Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2020-02-07T21:46:47.203Z
[taskcluster 2019-02-07T23:04:41.219Z] Uploading artifact public/logs/raptor_critical.log from file logs/raptor_critical.log with content encoding "gzip", mime type "text/plain" and expiry 2020-02-07T21:46:47.203Z
[taskcluster 2019-02-07T23:04:42.657Z] Uploading artifact public/logs/raptor_error.log from file logs/raptor_error.log with content encoding "gzip", mime type "text/plain" and expiry 2020-02-07T21:46:47.203Z
[taskcluster 2019-02-07T23:04:43.018Z] Uploading artifact public/logs/raptor_fatal.log from file logs/raptor_fatal.log with content encoding "gzip", mime type "text/plain" and expiry 2020-02-07T21:46:47.203Z
[taskcluster 2019-02-07T23:04:43.380Z] Uploading artifact public/logs/raptor_info.log from file logs/raptor_info.log with content encoding "gzip", mime type "text/plain" and expiry 2020-02-07T21:46:47.203Z
[taskcluster 2019-02-07T23:04:43.811Z] Uploading artifact public/logs/raptor_raw.log from file logs/raptor_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2020-02-07T21:46:47.203Z
[taskcluster 2019-02-07T23:04:44.333Z] Uploading artifact public/logs/raptor_warning.log from file logs/raptor_warning.log with content encoding "gzip", mime type "text/plain" and expiry 2020-02-07T21:46:47.203Z
[taskcluster 2019-02-07T23:04:44.696Z] Uploading artifact public/test_info/perfherder-data.json from file build/blobber_upload_dir/perfherder-data.json with content encoding "gzip", mime type "application/json" and expiry 2020-02-07T21:46:47.203Z
[taskcluster 2019-02-07T23:04:45.070Z] 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 2020-02-07T21:46:47.203Z
[taskcluster:error] exit status 1

Comment 1

[Intermittent Failures Robot]

1 failures in 2658 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• osx-10-10: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1526088&startday=2019-02-04&endday=2019-02-10&tree=all

Comment 2

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 3

[Cristina Coroiu [:ccoroiu]]

Recent failure log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=236934451&repo=mozilla-central&lineNumber=1038

16:23:54 INFO - raptor-control-server received webext_status: __raptor_shutdownBrowser
16:23:54 INFO - raptor-control-server shutting down browser (pid: 4795)
16:23:54 INFO - 127.0.0.1 - - [29/Mar/2019 16:23:54] "POST / HTTP/1.1" 200 -
16:23:54 INFO - raptor-control-server received webext_status: Removed tab 1
16:24:10 INFO - mozproxy Stopping mitmproxy playback, killing process 4787
16:24:10 INFO - mozproxy Successfully killed the mitmproxy playback process
16:24:10 INFO - mozproxy Turning off the browser proxy
16:24:10 INFO - mozproxy writing: /home/cltbld/tasks/task_1553876279/build/application/firefox/distribution/policies.json
16:24:10 INFO - raptor-main removing webext /home/cltbld/tasks/task_1553876279/build/tests/raptor/raptor/../webext/raptor
16:24:10 INFO - results-handler summarizing raptor test results
16:24:10 INFO - raptor-output ignoring the first dcf value due to initial pageload noise
16:24:10 INFO - raptor-output ignoring the first fcp value due to initial pageload noise
16:24:10 INFO - raptor-output turning on subtest alerting for measurement type: fcp
16:24:10 INFO - raptor-output ignoring the first fnbpaint value due to initial pageload noise
16:24:10 INFO - raptor-output ignoring the first loadtime value due to initial pageload noise
16:24:10 INFO - raptor-output turning on subtest alerting for measurement type: loadtime
16:24:10 INFO - raptor-output PERFHERDER_DATA: {"framework": {"name": "raptor"}, "suites": [{"extraOptions": [], "name": "raptor-tp6-google-mail-firefox", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 221.69, "subtests": [{"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 149.5, "replicates": [170, 146, 175, 127, 145, 127, 219, 137, 149, 150, 134, 146, 123, 154, 171, 131, 170, 152, 192, 168, 136, 145, 176, 159, 155], "unit": "ms"}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 165.5, "shouldAlert": true, "replicates": [183, 149, 192, 142, 157, 141, 234, 165, 165, 168, 149, 159, 157, 168, 184, 141, 201, 168, 219, 178, 171, 158, 191, 166, 163], "unit": "ms"}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 150.0, "replicates": [169, 145, 174, 126, 144, 127, 218, 150, 148, 150, 133, 144, 147, 153, 170, 130, 183, 150, 202, 167, 160, 144, 175, 158, 155], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 649.0, "shouldAlert": true, "replicates": [2914, 2481, 2469, 2503, 606, 2137, 676, 642, 2127, 593, 2164, 2125, 592, 2202, 691, 602, 683, 631, 652, 643, 645, 622, 635, 613, 646], "unit": "ms"}], "type": "pageload", "unit": "ms"}]}
16:24:10 INFO - raptor-output results can also be found locally at: /home/cltbld/tasks/task_1553876279/build/raptor.json
16:24:10 INFO - raptor-control-server shutting down control server
16:24:10 INFO - raptor-main finished
16:24:10 INFO - raptor-main TEST-UNEXPECTED-FAIL: test 'raptor-tp6-pinterest-firefox' timed out loading test page: https://pinterest.com/ pending metrics: fcp, fnb paint, dcf, load time
16:24:10 ERROR - Return code: 1
16:24:10 WARNING - setting return code to 1
16:24:10 INFO - Validating PERFHERDER_DATA against /home/cltbld/tasks/task_1553876279/mozharness/external_tools/performance-artifact-schema.json
16:24:10 INFO - copying raptor results to upload dir:
16:24:10 INFO - /home/cltbld/tasks/task_1553876279/build/blobber_upload_dir/perfherder-data.json
16:24:10 INFO - copying raptor results from /home/cltbld/tasks/task_1553876279/build/raptor.json to /home/cltbld/tasks/task_1553876279/build/blobber_upload_dir/perfherder-data.json
16:24:10 INFO - Running post-action listener: _package_coverage_data
16:24:10 INFO - Running post-action listener: _resource_record_post_action
16:24:10 INFO - Running post-action listener: process_java_coverage_data
16:24:10 INFO - Running post-action listener: stop_device

Comment 4

[Intermittent Failures Robot]

1 failures in 3910 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1526088&startday=2019-03-25&endday=2019-03-31&tree=all

Comment 5

[Intermittent Failures Robot]

1 failures in 3025 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1526088&startday=2019-04-08&endday=2019-04-14&tree=all

Comment 6

[Intermittent Failures Robot]

2 failures in 2673 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform breakdown:

• windows10-aarch64: 1
• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1526088&startday=2019-04-15&endday=2019-04-21&tree=all

Comment 7

[Intermittent Failures Robot]

1 failures in 3031 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-aarch64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1526088&startday=2019-04-22&endday=2019-04-28&tree=all

Comment 8

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 9

[Intermittent Failures Robot]

1 failures in 5197 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1526088&startday=2019-06-03&endday=2019-06-09&tree=all

Comment 10

[Raul Gurzau (:RaulG)]

new failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=251262748&repo=mozilla-central&lineNumber=1259

Comment 11

[Intermittent Failures Robot]

1 failures in 4753 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1526088&startday=2019-06-10&endday=2019-06-16&tree=all

Comment 12

[Intermittent Failures Robot]

1 failures in 2581 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• linux64-shippable-qr: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1526088&startday=2019-06-17&endday=2019-06-23&tree=all