Closed Bug 1605567 Opened 5 years ago Closed 5 years ago

Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-tp6m-amazon-geckoview' timed out loading test page: waiting for pending metrics

Categories

(Testing :: Raptor, defect, P5)

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

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

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

...
[task 2019-12-21T11:55:09.074Z] 11:55:07 INFO - raptor-control-server Info: received webext_status: test tab updated: 0
[task 2019-12-21T11:55:09.074Z] 11:55:09 INFO - raptor-control-server Info: received webext_results: {u'expected_browser_cycles': 1, u'subtest_unit': u'ms', u'name': u'raptor-tp6m-youtube-geckoview', u'lower_is_better': True, u'measurements': {u'dcf': [1320, 944, 1052, 1186, 489, 853, 710, 985, 870, 1374, 874, 2140, 513, 869, 873], u'fcp': [1359, 971, 957, 1052, 785, 882, 743, 909, 785, 1402, 768, 2046, 800, 900, 769], u'fnbpaint': [429, 278, 288, 306, 295, 307, 287, 287, 297, 294, 292, 328, 303, 286, 292], u'loadtime': [1501, 968, 1062, 1258, 774, 920, 742, 1007, 895, 1397, 883, 2150, 803, 892, 882]}, u'browser_cycle': u'1', u'subtest_lower_is_better': True, u'cold': False, u'browser': u'Fennec 73.0a1 20191221094532', u'type': u'pageload', u'page': u'https://m.youtube.com', u'unit': u'ms', u'alert_threshold': 2}
[task 2019-12-21T11:55:09.074Z] 11:55:09 INFO - raptor-control-server Info: received webext_status: results received
[task 2019-12-21T11:55:12.586Z] 11:55:09 INFO - perftest-results-handler Info: received results in RaptorResultsHandler.add
[task 2019-12-21T11:55:12.586Z] 11:55:09 INFO - raptor-control-server Info: received request to shutdown the browser
[task 2019-12-21T11:55:12.586Z] 11:55:09 INFO - raptor-control-server Info: shutting down android app org.mozilla.geckoview_example
[task 2019-12-21T11:55:12.586Z] 11:55:10 INFO - adb shell_output: adb -s ZY322HN8G4 wait-for-device shell am force-stop org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-21T11:55:12.586Z] 11:55:10 INFO - raptor-main Info: removing reverse socket connections
[task 2019-12-21T11:55:12.586Z] 11:55:10 INFO - adb command_output: adb -s ZY322HN8G4 wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
[task 2019-12-21T11:55:12.586Z] 11:55:11 INFO - adb shell_bool: adb -s ZY322HN8G4 wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-21T11:55:12.586Z] 11:55:11 INFO - adb shell_output: adb -s ZY322HN8G4 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-21T11:55:12.586Z] 11:55:11 INFO - adb shell_bool: adb -s ZY322HN8G4 wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-21T11:55:12.586Z] 11:55:11 INFO - adb command_output: adb -s ZY322HN8G4 wait-for-device pull /sdcard/raptor/profile/minidumps /tmp/tmpIKw5bq/minidumps, timeout: None, timedout: None, exitcode: 0, output: /sdcard/raptor/profile/minidumps/: 0 files pulled.
[task 2019-12-21T11:55:12.586Z] 11:55:11 INFO - raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 1816
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - raptor-main Info: removing webext /builds/task_1576928724/workspace/build/tests/raptor/raptor/../webext/raptor
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-results-handler Info: summarizing raptor test results
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first dcf value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first fcp value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: turning on subtest alerting for measurement type: fcp
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first fnbpaint value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first loadtime value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: turning on subtest alerting for measurement type: loadtime
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first dcf value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first fcp value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: turning on subtest alerting for measurement type: fcp
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first fnbpaint value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first loadtime value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: turning on subtest alerting for measurement type: loadtime
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first dcf value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first fcp value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: turning on subtest alerting for measurement type: fcp
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first fnbpaint value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: ignoring the first loadtime value due to initial pageload noise
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: turning on subtest alerting for measurement type: loadtime
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: screen captures can be found locally at: /builds/task_1576928724/workspace/build/screenshots.html
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: PERFHERDER_DATA: {"framework": {"name": "raptor"}, "application": {"name": "geckoview"}, "suites": [{"value": 887.94, "extraOptions": [], "name": "raptor-tp6m-facebook-geckoview", "tags": ["pageload", "warm"], "lowerIsBetter": true, "subtests": [{"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 692.5, "replicates": [1271, 745, 661, 694, 665, 642, 749, 738, 691, 662, 1308, 729, 711, 622, 619], "unit": "ms"}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 728.5, "shouldAlert": true, "replicates": [1393, 816, 701, 735, 710, 677, 783, 774, 722, 696, 1342, 813, 824, 721, 655], "unit": "ms"}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 710.0, "replicates": [1305, 766, 682, 716, 690, 658, 763, 756, 704, 677, 1322, 793, 781, 677, 636], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 1735.0, "shouldAlert": true, "replicates": [2430, 1783, 1639, 1732, 1520, 1486, 2033, 2606, 1714, 1498, 2138, 2989, 3963, 1738, 1467], "unit": "ms"}], "type": "pageload", "alertThreshold": 2.0, "unit": "ms"}, {"value": 256.9, "extraOptions": [], "name": "raptor-tp6m-google-geckoview", "tags": ["pageload", "warm"], "lowerIsBetter": true, "subtests": [{"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 228.5, "replicates": [420, 228, 226, 229, 236, 226, 237, 247, 227, 226, 228, 241, 225, 235, 240], "unit": "ms"}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 299.5, "shouldAlert": true, "replicates": [566, 337, 305, 301, 309, 298, 255, 263, 303, 270, 305, 257, 296, 314, 260], "unit": "ms"}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 263.0, "replicates": [439, 261, 269, 263, 279, 265, 223, 233, 271, 239, 269, 227, 263, 282, 226], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 242.0, "shouldAlert": true, "replicates": [1317, 236, 235, 237, 248, 238, 245, 253, 238, 261, 239, 248, 238, 247, 248], "unit": "ms"}], "type": "pageload", "alertThreshold": 2.0, "unit": "ms"}, {"value": 674.61, "extraOptions": [], "name": "raptor-tp6m-youtube-geckoview", "tags": ["pageload", "warm"], "lowerIsBetter": true, "subtests": [{"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 873.5, "replicates": [1320, 944, 1052, 1186, 489, 853, 710, 985, 870, 1374, 874, 2140, 513, 869, 873], "unit": "ms"}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 891.0, "shouldAlert": true, "replicates": [1359, 971, 957, 1052, 785, 882, 743, 909, 785, 1402, 768, 2046, 800, 900, 769], "unit": "ms"}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 293.0, "replicates": [429, 278, 288, 306, 295, 307, 287, 287, 297, 294, 292, 328, 303, 286, 292], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 907.5, "shouldAlert": true, "replicates": [1501, 968, 1062, 1258, 774, 920, 742, 1007, 895, 1397, 883, 2150, 803, 892, 882], "unit": "ms"}], "type": "pageload", "alertThreshold": 2.0, "unit": "ms"}]}
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-output Info: results can also be found locally at: /builds/task_1576928724/workspace/build/raptor.json
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - perftest-results-handler Info: Validating PERFHERDER_DATA against /builds/task_1576928724/workspace/mozharness/external_tools/performance-artifact-schema.json
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - raptor-main Info: removing test folder for raptor: /sdcard/raptor
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - adb shell_output: adb -s ZY322HN8G4 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - adb shell_output: adb -s ZY322HN8G4 wait-for-device shell rm -r /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - adb shell_output: adb -s ZY322HN8G4 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - adb shell_bool: adb -s ZY322HN8G4 wait-for-device shell test -e /sdcard/raptor, timeout: None, root: False, timedout: None, exitcode: 1, output:
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - raptor-control-server Info: shutting down control server
[task 2019-12-21T11:55:12.586Z] 11:55:12 INFO - raptor-main Info: finished
[task 2019-12-21T11:55:12.586Z] 11:55:12 ERROR - raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-tp6m-amazon-geckoview' timed out loading test page: https://www.amazon.com pending metrics: fcp, fnb paint, dcf
[task 2019-12-21T11:55:32.464Z] 11:55:12 ERROR - Return code: 1
[task 2019-12-21T11:55:32.465Z] 11:55:12 WARNING - setting return code to 1
[task 2019-12-21T11:55:32.465Z] 11:55:12 INFO - Killing logcat pid 585.

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=299395052&repo=mozilla-central&lineNumber=2826

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-tp6m-amazon-geckoview' timed out loading test page: https://www.amazon.com pending metrics: fcp, fnb paint, dcf → Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-tp6m-amazon-geckoview' timed out loading test page: waiting for pending metris
Summary: Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-tp6m-amazon-geckoview' timed out loading test page: waiting for pending metris → Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-tp6m-amazon-geckoview' timed out loading test page: waiting for pending metrics

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

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.