[raptor] Test tp6m-c-17 failed because of a time out, but is marked as successful on treeherder
Categories
(Testing :: Performance, defect, P1)
Tracking
(Not tracked)
People
(Reporter: marauder, Unassigned)
Details
10:48:19 INFO - raptor-main Info: begin browser cycle 13 of 15 for test raptor-tp6m-bing-geckoview-cold
10:48:19 INFO - raptor-main Info: starting test: raptor-tp6m-bing-geckoview-cold
10:48:19 INFO - raptor-main Info: starting raptor test: raptor-tp6m-bing-geckoview-cold
........
10:48:22 INFO - raptor-main Info: copying /tmp/tmpJzYVeZ/cert9.db to /tmp/tmp3Y6f6o.mozrunner/cert9.db
10:48:22 INFO - raptor-main Info: starting test: raptor-tp6m-bing-geckoview-cold
10:48:22 INFO - raptor-main Info: starting raptor test: raptor-tp6m-bing-geckoview-cold
........
10:51:21 CRITICAL - raptor-main Critical: Tests failed to finish! Application timed out.
10:51:21 ERROR - raptor-main Error: Test failed to finish. Application timed out after 170 seconds
10:51:21 INFO - raptor-main Info: removing reverse socket connections
........
10:51:22 INFO - perftest-output Info: combining results from browser cycle 12 for raptor-tp6m-bing-geckoview-cold
10:51:22 INFO - perftest-output Info: adding replicates for dcf
10:51:22 INFO - perftest-output Info: adding replicates for fcp
10:51:22 INFO - perftest-output Info: adding replicates for fnbpaint
10:51:22 INFO - perftest-output Info: adding replicates for loadtime
10:51:22 INFO - perftest-output Info: PERFHERDER_DATA: {"framework": {"name": "raptor"}, "application": {"name": "geckoview"}, "suites": [{"extraOptions": [], "name": "raptor-tp6m-bing-geckoview-cold", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 491.9, "subtests": [{"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 443.0, "replicates": [457, 425, 418, 441, 500, 471, 465, 457, 430, 441, 419, 445], "unit": "ms"}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 532.5, "shouldAlert": true, "replicates": [559, 518, 521, 529, 569, 532, 529, 525, 534, 545, 533, 544], "unit": "ms"}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 450.0, "replicates": [464, 436, 430, 449, 480, 451, 439, 432, 455, 453, 444, 470], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 551.5, "shouldAlert": true, "replicates": [561, 547, 535, 557, 570, 555, 548, 536, 545, 556, 548, 558], "unit": "ms"}], "type": "pageload", "unit": "ms"}]}
10:51:22 INFO - perftest-output Info: results can also be found locally at: /builds/task_1575627691/workspace/build/raptor.json
........
10:51:23 INFO - raptor-control-server Info: shutting down control server
10:51:23 INFO - raptor-main Info: finished
10:51:23 INFO - Return code: 0
|
||
Comment 1•6 years ago
•
|
||
Robert, is this possible to be because the finally of Perftest.run_tests() is calling run_test_teardown() > calling Perftest.check_for_crashes() > which is not implemented?
Also, shouldn't have run_tests been like below?
class RaptorAndroid(PerftestAndroid, Raptor):
...
def run_tests(self, tests, test_names):
...
return super(PerftestAndroid, self).run_tests(tests, test_names)
instead of
return super(RaptorAndroid, self).run_tests(tests, test_names)
|
|
||
Updated•6 years ago
|
|
|
||
Comment 3•6 years ago
|
||
Looking thorouly, I am not sure if there's a false positive or a true positive. I made a log comparison between the two tp6-c-17 from those two tasks (first is the failed, last is the passed) and a conclusion is:
the failed one prints the timeout message on the 13th browser cycle just after the test settings are sent to the webext and continues like nothing happened:
[task 2019-12-06T10:51:22.451Z] 10:48:36 INFO - raptor-control-server Info: sent test settings to webext runner
[task 2019-12-06T10:51:22.451Z] 10:51:21 INFO - adb shell_output: adb -s ZY322HN3J9 wait-for-device shell am force-stop org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-06T10:51:22.451Z] 10:51:21 CRITICAL - raptor-main Critical: Tests failed to finish! Application timed out.
[task 2019-12-06T10:51:22.451Z] 10:51:21 ERROR - raptor-main Error: Test failed to finish. Application timed out after 170 seconds
[task 2019-12-06T10:51:22.451Z] 10:51:21 INFO - raptor-main Info: removing reverse socket connections
[task 2019-12-06T10:51:22.451Z] 10:51:21 INFO - adb command_output: adb -s ZY322HN3J9 wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
[task 2019-12-06T10:51:22.451Z] 10:51:22 INFO - adb shell_bool: adb -s ZY322HN3J9 wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-06T10:51:22.451Z] 10:51:22 INFO - adb shell_output: adb -s ZY322HN3J9 wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-06T10:51:22.451Z] 10:51:22 INFO - adb shell_bool: adb -s ZY322HN3J9 wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-06T10:51:22.580Z] 10:51:22 INFO - adb command_output: adb -s ZY322HN3J9
The passed one looks like this (the arrows show the missing logs from the failed one):
[task 2019-12-06T07:31:37.874Z] 07:31:02 INFO - raptor-control-server Info: sent test settings to webext runner
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:02 INFO - raptor-control-server Info: received webext_status: * pausing 30 seconds to let browser settle... *
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:32 INFO - raptor-control-server Info: received webext_status: running 1 pagecycles of https://www.bing.com/
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:33 INFO - raptor-control-server Info: received webext_status: begin pagecycle 1
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:34 INFO - raptor-control-server Info: received webext_status: update tab: 0
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:34 INFO - raptor-control-server Info: received webext_status: test tab updated: 0
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:35 INFO - raptor-control-server Info: received webext_status: results received
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:35 INFO - raptor-control-server Info: received webext_results: {u'expected_browser_cycles': 15, u'subtest_unit': u'ms', u'name': u'raptor-tp6m-bing-geckoview-cold', u'lower_is_better': True, u'measurements': {u'dcf': [419], u'fcp': [547], u'fnbpaint': [444], u'loadtime': [530]}, u'browser_cycle': u'15', u'subtest_lower_is_better': True, u'cold': True, u'browser': u'Fennec 73.0a1 20191206052617', u'type': u'pageload', u'page': u'https://www.bing.com/', u'unit': u'ms', u'alert_threshold': 2}
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:35 INFO - perftest-results-handler Info: received results in RaptorResultsHandler.add
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:35 INFO - raptor-control-server Info: received request to shutdown the browser
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:35 INFO - raptor-control-server Info: shutting down android app org.mozilla.geckoview_example
>>>>>>>> [task 2019-12-06T07:31:37.874Z] 07:31:36 INFO - adb shell_output: adb -s ZY322FZT7B wait-for-device shell am force-stop org.mozilla.geckoview_example, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-06T07:31:37.874Z] 07:31:36 INFO - raptor-main Info: removing reverse socket connections
[task 2019-12-06T07:31:37.874Z] 07:31:36 INFO - adb command_output: adb -s ZY322FZT7B wait-for-device reverse --remove-all, timeout: None, timedout: None, exitcode: 0, output:
[task 2019-12-06T07:31:37.874Z] 07:31:37 INFO - adb shell_bool: adb -s ZY322FZT7B wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-06T07:31:37.874Z] 07:31:37 INFO - adb shell_output: adb -s ZY322FZT7B wait-for-device shell sync, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-06T07:31:37.874Z] 07:31:37 INFO - adb shell_bool: adb -s ZY322FZT7B wait-for-device shell test -d /sdcard/raptor/profile/minidumps, timeout: None, root: False, timedout: None, exitcode: 0, output:
[task 2019-12-06T07:31:37.874Z] 07:31:37 INFO - adb command_output: adb -s ZY322FZT7B wait-for-device pull /sdcard/raptor/profile/minidumps /tmp/tmpauNl7r/minidumps, timeout: None, timedout: None, exitcode: 0, output: /sdcard/raptor/profile/minidumps/: 0 files pulled.
[task 2019-12-06T07:31:38.058Z] 07:31:37 INFO - raptor-mitmproxy Info: Stopping mitmproxy playback, killing process 823
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - raptor-mitmproxy Info: Successfully killed the mitmproxy playback process
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - raptor-main Info: removing webext /builds/task_1575616268/workspace/build/tests/raptor/raptor/../webext/raptor
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - perftest-results-handler Info: summarizing raptor test results
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - perftest-output Info: turning on subtest alerting for measurement type: fcp
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - perftest-output Info: turning on subtest alerting for measurement type: loadtime
...
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - perftest-output Info: combining results from browser cycle 1 for raptor-tp6m-bing-geckoview-cold
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - perftest-output Info: created new combined result with intial cycle replicates
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - perftest-output Info: combining results from browser cycle 2 for raptor-tp6m-bing-geckoview-cold
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - perftest-output Info: adding replicates for dcf
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - perftest-output Info: adding replicates for fcp
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - perftest-output Info: adding replicates for fnbpaint
[task 2019-12-06T07:31:38.058Z] 07:31:38 INFO - perftest-output Info: adding replicates for loadtime
...
[task 2019-12-06T07:31:53.668Z] 07:31:38 INFO - perftest-output Info: PERFHERDER_DATA: {"framework": {"name": "raptor"}, "application": {"name": "geckoview"}, "suites": [{"extraOptions": [], "name": "raptor-tp6m-bing-geckoview-cold", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 483.04, "subtests": [{"name": "dcf", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 429, "replicates": [430, 429, 427, 467, 425, 434, 424, 433, 414, 416, 424, 458, 441, 487, 419], "unit": "ms"}, {"name": "fcp", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 533, "shouldAlert": true, "replicates": [533, 534, 542, 529, 533, 539, 529, 536, 474, 475, 513, 513, 562, 547, 547], "unit": "ms"}, {"name": "fnbpaint", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 445, "replicates": [443, 441, 452, 445, 451, 446, 449, 458, 392, 396, 431, 433, 467, 467, 444], "unit": "ms"}, {"name": "loadtime", "lowerIsBetter": true, "alertThreshold": 2.0, "value": 535, "shouldAlert": true, "replicates": [532, 542, 535, 544, 522, 548, 537, 546, 484, 468, 524, 533, 553, 556, 530], "unit": "ms"}], "type": "pageload", "unit": "ms"}]}
[task 2019-12-06T07:31:53.668Z] 07:31:38 INFO - perftest-output Info: results can also be found locally at: /builds/task_1575616268/workspace/build/raptor.json
|
||
Comment 4•6 years ago
|
||
The priority flag is not set for this bug.
:davehunt, could you have a look please?
For more information, please visit auto_nag documentation.
|
||
Updated•6 years ago
|
|
||
Comment 5•6 years ago
|
||
:alexandrui is this still under investigation? Is it still happening
|
|
||
Comment 6•6 years ago
|
||
I will look into it ASAP
|
|
||
Comment 7•6 years ago
|
||
Looks like this was a one time thing. Closing it.
Description
•