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

[task 2020-08-06T17:59:11.133Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-runnerjs] results pending..."
[task 2020-08-06T17:59:11.382Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-runnerjs] results pending..."
[task 2020-08-06T17:59:11.498Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-benchmarkjs] raptor benchmark received message"
[task 2020-08-06T17:59:11.498Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-benchmarkjs] raptor-benchmark,wasm-godot,[object Object],[object Object],[object Object],[object Object],[object Object]"
[task 2020-08-06T17:59:11.498Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-benchmarkjs] sending result back to runner: wasm-godot [object Object],[object Object],[object Object],[object Object],[object Object]"
[task 2020-08-06T17:59:11.514Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-runnerjs] received message from http://localhost:40339/wasm-godot/index.html"
[task 2020-08-06T17:59:11.514Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-runnerjs] result: wasm-godot [object Object],[object Object],[object Object],[object Object],[object Object]"
[task 2020-08-06T17:59:11.514Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-runnerjs] received results from benchmark"
[task 2020-08-06T17:59:11.514Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-benchmarkjs] Response: confirmed wasm-godot"
[task 2020-08-06T17:59:11.636Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-runnerjs] cancelled raptor alarm raptor-page-timeout"
[task 2020-08-06T17:59:11.636Z] 17:59:11     INFO -  raptor-control-server Info: received webext_status: results received
[task 2020-08-06T17:59:11.637Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-runnerjs] Verifying results:"
[task 2020-08-06T17:59:11.637Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-runnerjs] [object Object]"
[task 2020-08-06T17:59:11.637Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-runnerjs] have 5 results for wasm-godot, as expected"
[task 2020-08-06T17:59:11.641Z] 17:59:11     INFO -  raptor-control-server Info: received webext_results: {u'expected_browser_cycles': 1, u'subtest_unit': u'ms', u'name': u'raptor-wasm-godot-cranelift-firefox', u'lower_is_better': True, u'measurements': {u'wasm-godot': [[[{u'name': u'wasm-instantiate', u'time': 30490.16}, {u'name': u'engine-instantiate', u'time': 438.7999999999993}, {u'name': u'first-frame', u'time': None}, {u'name': u'first-interactive', u'time': 30949}, {u'name': u'cpuTime', u'time': 30938.44}]], [[{u'name': u'wasm-instantiate', u'time': 29249.54}, {u'name': u'engine-instantiate', u'time': 39.63999999999942}, {u'name': u'first-frame', u'time': None}, {u'name': u'first-interactive', u'time': 29312.78}, {u'name': u'cpuTime', u'time': 29298.159999999996}]], [[{u'name': u'wasm-instantiate', u'time': 29873.14}, {u'name': u'engine-instantiate', u'time': 38.340000000000146}, {u'name': u'first-frame', u'time': None}, {u'name': u'first-interactive', u'time': 29928}, {u'name': u'cpuTime', u'time': 29920.36}]], [[{u'name': u'wasm-instantiate', u'time': 29215.199999999997}, {u'name': u'engine-instantiate', u'time': 40.280000000002474}, {u'name': u'first-frame', u'time': None}, {u'name': u'first-interactive', u'time': 29275.82}, {u'name': u'cpuTime', u'time': 29264.52}]], [[{u'name': u'wasm-instantiate', u'time': 29196.04}, {u'name': u'engine-instantiate', u'time': 41.159999999999854}, {u'name': u'first-frame', u'time': None}, {u'name': u'first-interactive', u'time': 29253.399999999998}, {u'name': u'cpuTime', u'time': 29246.42}]]]}, u'browser_cycle': u'1', u'subtest_lower_is_better': True, u'cold': False, u'browser': u'Firefox 81.0a1 20200806154430', u'type': u'benchmark', u'page': u'http://localhost:40339/wasm-godot/index.html', u'unit': u'ms', u'alert_threshold': 2}
[task 2020-08-06T17:59:11.641Z] 17:59:11     INFO -  perftest-results-handler Info: received results in RaptorResultsHandler.add
[task 2020-08-06T17:59:11.649Z] 17:59:11     INFO -  raptor-control-server Info: received webext_status: closing Tab: 7
[task 2020-08-06T17:59:11.670Z] 17:59:11     INFO -  raptor-control-server Info: received webext_status: closed tab: 7
[task 2020-08-06T17:59:11.674Z] 17:59:11     INFO -  PID 3531 | console.info: "[raptor-runnerjs] benchmark test finished"
[task 2020-08-06T17:59:11.674Z] 17:59:11     INFO -  raptor-control-server Info: received request to shutdown the browser
[task 2020-08-06T17:59:11.674Z] 17:59:11     INFO -  raptor-control-server Info: shutting down browser (pid: 3531)
[task 2020-08-06T17:59:11.677Z] 17:59:11     INFO -  raptor-control-server Info: received webext_status: ended page cycle 6
[task 2020-08-06T17:59:11.678Z] 17:59:11     INFO -  raptor-control-server Info: received webext_status: ended page cycle 6
[task 2020-08-06T17:59:11.682Z] 17:59:11     INFO -  raptor-control-server Info: received webext_status: ended page cycle 6
[task 2020-08-06T17:59:11.683Z] 17:59:11     INFO -  raptor-control-server Info: received webext_status: ended page cycle 6
[task 2020-08-06T17:59:11.687Z] 17:59:11     INFO -  raptor-control-server Info: received webext_status: ended page cycle 6
[task 2020-08-06T17:59:13.885Z] 17:59:13     INFO -  raptor-webext Info: removing webext /home/cltbld/tasks/task_1596736537/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-08-06T17:59:13.885Z] 17:59:13     INFO -  perftest-results-handler Info: summarizing raptor test results
[task 2020-08-06T17:59:13.886Z] 17:59:13     INFO -  [[[{u'name': u'wasm-instantiate', u'time': 30490.16}, {u'name': u'engine-instantiate', u'time': 438.7999999999993}, {u'name': u'first-frame', u'time': None}, {u'name': u'first-interactive', u'time': 30949}, {u'name': u'cpuTime', u'time': 30938.44}]], [[{u'name': u'wasm-instantiate', u'time': 29249.54}, {u'name': u'engine-instantiate', u'time': 39.63999999999942}, {u'name': u'first-frame', u'time': None}, {u'name': u'first-interactive', u'time': 29312.78}, {u'name': u'cpuTime', u'time': 29298.159999999996}]], [[{u'name': u'wasm-instantiate', u'time': 29873.14}, {u'name': u'engine-instantiate', u'time': 38.340000000000146}, {u'name': u'first-frame', u'time': None}, {u'name': u'first-interactive', u'time': 29928}, {u'name': u'cpuTime', u'time': 29920.36}]], [[{u'name': u'wasm-instantiate', u'time': 29215.199999999997}, {u'name': u'engine-instantiate', u'time': 40.280000000002474}, {u'name': u'first-frame', u'time': None}, {u'name': u'first-interactive', u'time': 29275.82}, {u'name': u'cpuTime', u'time': 29264.52}]], [[{u'name': u'wasm-instantiate', u'time': 29196.04}, {u'name': u'engine-instantiate', u'time': 41.159999999999854}, {u'name': u'first-frame', u'time': None}, {u'name': u'first-interactive', u'time': 29253.399999999998}, {u'name': u'cpuTime', u'time': 29246.42}]]]
[task 2020-08-06T17:59:13.886Z] 17:59:13     INFO -  perftest-output Info: PERFHERDER_DATA: {"framework": {"name": "raptor"}, "application": {"version": "81.0a1", "name": "firefox"}, "suites": [{"value": 29312.78, "extraOptions": [], "name": "raptor-wasm-godot-cranelift-firefox", "tags": ["benchmark", "warm"], "lowerIsBetter": true, "subtests": [{"name": "cpuTime", "lowerIsBetter": true, "alertThreshold": 2.0, "replicates": [30938.44, 29298.159999999996, 29920.36, 29264.52, 29246.42], "value": 29298.159999999996, "unit": "ms"}, {"name": "engine-instantiate", "lowerIsBetter": true, "alertThreshold": 2.0, "replicates": [438.7999999999993, 39.63999999999942, 38.340000000000146, 40.280000000002474, 41.159999999999854], "value": 40.280000000002474, "unit": "ms"}, {"name": "first-frame", "lowerIsBetter": true, "alertThreshold": 2.0, "replicates": [null, null, null, null, null], "value": null, "unit": "ms"}, {"name": "first-interactive", "lowerIsBetter": true, "alertThreshold": 2.0, "replicates": [30949, 29312.78, 29928, 29275.82, 29253.399999999998], "value": 29312.78, "unit": "ms"}, {"name": "wasm-instantiate", "lowerIsBetter": true, "alertThreshold": 2.0, "replicates": [30490.16, 29249.54, 29873.14, 29215.199999999997, 29196.04], "value": 29249.54, "unit": "ms"}], "type": "benchmark", "alertThreshold": 2.0, "unit": "ms"}]}
[task 2020-08-06T17:59:13.886Z] 17:59:13     INFO -  perftest-output Info: results can also be found locally at: /home/cltbld/tasks/task_1596736537/build/raptor.json
[task 2020-08-06T17:59:13.894Z] 17:59:13     INFO -  perftest-results-handler Info: Validating PERFHERDER_DATA against /home/cltbld/tasks/task_1596736537/mozharness/external_tools/performance-artifact-schema.json
[task 2020-08-06T17:59:13.894Z] 17:59:13     INFO -  perftest-results-handler Critical: Error while validating PERFHERDER_DATA
[task 2020-08-06T17:59:13.894Z] 17:59:13     INFO -  perftest-results-handler Info: None is not of type u'number'
[task 2020-08-06T17:59:13.895Z] 17:59:13     INFO -  Failed validating u'type' in schema[u'properties'][u'suites'][u'items'][u'properties'][u'subtests'][u'items'][u'properties'][u'value']:
[task 2020-08-06T17:59:13.895Z] 17:59:13     INFO -      {u'description': u'Summary value for subtest',
[task 2020-08-06T17:59:13.895Z] 17:59:13     INFO -       u'maximum': 1000000000000.0,
[task 2020-08-06T17:59:13.895Z] 17:59:13     INFO -       u'minimum': -1000000000000.0,
[task 2020-08-06T17:59:13.895Z] 17:59:13     INFO -       u'title': u'Subtest value',
[task 2020-08-06T17:59:13.895Z] 17:59:13     INFO -       u'type': u'number'}
[task 2020-08-06T17:59:13.895Z] 17:59:13     INFO -  On instance[u'suites'][0][u'subtests'][2][u'value']:
[task 2020-08-06T17:59:13.895Z] 17:59:13     INFO -      None
[task 2020-08-06T17:59:13.896Z] 17:59:13     INFO -  raptor-perftest Info: Removing temporary directory: /tmp/tmpKVk7KK
[task 2020-08-06T17:59:13.936Z] 17:59:13     INFO -  raptor-perftest Info: Removing temporary directory: /tmp/tmpnOe4Yf
[task 2020-08-06T17:59:13.972Z] 17:59:13     INFO -  raptor-control-server Info: shutting down control server
[task 2020-08-06T17:59:14.189Z] 17:59:14     INFO -  raptor-webext Info: finished
[task 2020-08-06T17:59:14.190Z] 17:59:14    ERROR -  raptor-main Critical: TEST-UNEXPECTED-FAIL: no raptor test results were found for raptor-wasm-godot-cranelift-firefox
[task 2020-08-06T17:59:14.242Z] 17:59:14    ERROR - Return code: 1
[task 2020-08-06T17:59:14.242Z] 17:59:14  WARNING - setting return code to 1
[task 2020-08-06T17:59:14.242Z] 17:59:14     INFO - Copying Raptor results to upload dir:
[task 2020-08-06T17:59:14.242Z] 17:59:14     INFO - /home/cltbld/tasks/task_1596736537/build/blobber_upload_dir/perfherder-data.json
[task 2020-08-06T17:59:14.242Z] 17:59:14     INFO - Copying raptor results from /home/cltbld/tasks/task_1596736537/build/raptor.json to /home/cltbld/tasks/task_1596736537/build/blobber_upload_dir/perfherder-data.json
[task 2020-08-06T17:59:14.244Z] 17:59:14     INFO - Running post-action listener: _package_coverage_data
[task 2020-08-06T17:59:14.244Z] 17:59:14     INFO - Running post-action listener: _resource_record_post_action
[task 2020-08-06T17:59:14.244Z] 17:59:14     INFO - Running post-action listener: process_java_coverage_data
[task 2020-08-06T17:59:14.244Z] 17:59:14     INFO - Running post-action listener: stop_device
[task 2020-08-06T17:59:14.244Z] 17:59:14     INFO - [mozharness: 2020-08-06 17:59:14.244673Z] Finished run-tests step (success)
[task 2020-08-06T17:59:14.244Z] 17:59:14     INFO - Running post-run listener: _resource_record_post_run
[task 2020-08-06T17:59:14.290Z] 17:59:14     INFO - Total resource usage - Wall time: 170s; CPU: 71.0%; Read bytes: 62472192; Write bytes: 806007296; Read time: 732; Write time: 126524
[task 2020-08-06T17:59:14.290Z] 17:59:14     INFO - TinderboxPrint: CPU usage<br/>71.2%
[task 2020-08-06T17:59:14.290Z] 17:59:14     INFO - TinderboxPrint: I/O read bytes / time<br/>62,472,192 / 732
[task 2020-08-06T17:59:14.290Z] 17:59:14     INFO - TinderboxPrint: I/O write bytes / time<br/>806,007,296 / 126,524
[task 2020-08-06T17:59:14.291Z] 17:59:14     INFO - TinderboxPrint: CPU idle<br/>387.2 (28.6%)
[task 2020-08-06T17:59:14.291Z] 17:59:14     INFO - TinderboxPrint: CPU system<br/>157.7 (11.7%)
[task 2020-08-06T17:59:14.291Z] 17:59:14     INFO - TinderboxPrint: CPU user<br/>805.5 (59.6%)
[task 2020-08-06T17:59:14.291Z] 17:59:14     INFO - TinderboxPrint: Swap in / out<br/>0 / 0
[task 2020-08-06T17:59:14.291Z] 17:59:14     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 2020-08-06T17:59:14.291Z] 17:59:14     INFO - install - Wall time: 8s; CPU: 13.0%; Read bytes: 12288; Write bytes: 335167488; Read time: 164; Write time: 22904
[task 2020-08-06T17:59:14.293Z] 17:59:14     INFO - run-tests - Wall time: 162s; CPU: 75.0%; Read bytes: 60354560; Write bytes: 470839808; Read time: 560; Write time: 103620
[task 2020-08-06T17:59:14.334Z] 17:59:14  WARNING - returning nonzero exit status 1
[fetches 2020-08-06T17:59:14.342Z] removing /home/cltbld/tasks/task_1596736537/fetches
[fetches 2020-08-06T17:59:14.344Z] finished
[taskcluster 2020-08-06T17:59:14.354Z]    Exit Code: 1
[taskcluster 2020-08-06T17:59:14.354Z]    User Time: 10m40.16s
[taskcluster 2020-08-06T17:59:14.354Z]  Kernel Time: 2m1.212s
[taskcluster 2020-08-06T17:59:14.354Z]    Wall Time: 3m21.449870536s
[taskcluster 2020-08-06T17:59:14.354Z]       Result: FAILED
[taskcluster 2020-08-06T17:59:14.354Z] === Task Finished ===
[taskcluster 2020-08-06T17:59:14.354Z] Task Duration: 3m21.450715784s
[taskcluster 2020-08-06T17:59:14.489Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2021-08-06T17:55:45.480Z
[taskcluster 2020-08-06T17:59:14.996Z] 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 2021-08-06T17:55:45.480Z
[taskcluster 2020-08-06T17:59:15.193Z] 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-08-06T17:55:45.480Z
[taskcluster:error] exit status 1