Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=263358964&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/V8LZwh9gSlu8tA-EDzMq-Q/runs/0/artifacts/public/logs/live_backing.log
[task 2019-08-24T23:14:22.997Z] 23:14:22 INFO - raptor-control-server Info: received gecko profile filename: raptor-webaudio-firefox_pagecycle_3.profile
[task 2019-08-24T23:14:22.997Z] 23:14:22 INFO - raptor-control-server Info: moved gecko profile to /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpb21QJI/raptor-webaudio-firefox_pagecycle_3.profile
[task 2019-08-24T23:14:22.997Z] 23:14:22 INFO - raptor-control-server Info: received webext_status: stopping gecko profiling
[task 2019-08-24T23:14:22.997Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] Verifying results:"
[task 2019-08-24T23:14:22.997Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] [object Object]"
[task 2019-08-24T23:14:22.998Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] have 3 results for webaudio, as expected"
[task 2019-08-24T23:14:22.998Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] posting to control server"
[task 2019-08-24T23:14:22.998Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] [object Object]"
[task 2019-08-24T23:14:22.998Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] closed tab 2"
[task 2019-08-24T23:14:22.998Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] benchmark test finished"
[task 2019-08-24T23:14:22.998Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] stopping gecko profiling"
[task 2019-08-24T23:14:22.998Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] posting to control server"
[task 2019-08-24T23:14:22.998Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] stopping gecko profiling"
[task 2019-08-24T23:14:22.999Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] posting to control server"
[task 2019-08-24T23:14:22.999Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] "
[task 2019-08-24T23:14:22.999Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] post success"
[task 2019-08-24T23:14:23.000Z] 23:14:22 INFO - PID 1446 | console.log: "[raptor-runnerjs] post success"
[task 2019-08-24T23:14:23.000Z] 23:14:23 INFO - PID 1446 | console.log: "[raptor-runnerjs] Removed tab: 2"
[task 2019-08-24T23:14:23.000Z] 23:14:23 INFO - PID 1446 | console.log: "[raptor-runnerjs] posting to control server"
[task 2019-08-24T23:14:23.000Z] 23:14:23 INFO - PID 1446 | console.log: "[raptor-runnerjs] Removed tab: 2"
[task 2019-08-24T23:14:23.001Z] 23:14:23 INFO - raptor-control-server Info: received webext_results: {u'expected_browser_cycles': 1, u'subtest_unit': u'score', u'name': u'raptor-webaudio-firefox', u'extra_options': [u'gecko_profile'], u'lower_is_better': True, u'measurements': {u'webaudio': [[u'[{"name":"Empty testcase","duration":22,"buffer":{}},{"name":"Simple gain test without resampling","duration":75,"buffer":{}},{"name":"Simple gain test without resampling (Stereo)","duration":75,"buffer":{}},{"name":"Simple gain test without resampling (Stereo and positional)","duration":98,"buffer":{}},{"name":"Simple gain test","duration":61,"buffer":{}},{"name":"Simple gain test (Stereo)","duration":77,"buffer":{}},{"name":"Simple gain test (Stereo and positional)","duration":92,"buffer":{}},{"name":"Upmix without resampling (Mono -> Stereo)","duration":77,"buffer":{}},{"name":"Downmix without resampling (Mono -> Stereo)","duration":62,"buffer":{}},{"name":"Simple mixing (same buffer)","duration":999,"buffer":{}},{"name":"Simple mixing (different buffers)","duration":955,"buffer":{}},{"name":"Simple mixing with gains","duration":422,"buffer":{}},{"name":"Convolution reverb","duration":1107,"buffer":{}},{"name":"Granular synthesis","duration":4633,"buffer":{}},{"name":"Synth","duration":92,"buffer":{}},{"name":"Substractive synth","duration":81,"buffer":{}},{"name":"Stereo Panning","duration":79,"buffer":{}},{"name":"Stereo Panning with Automation","duration":222,"buffer":{}},{"name":"Periodic Wave with Automation","duration":235,"buffer":{}},{"name":"Geometric Mean","duration":166,"buffer":{}}]'], [u'[{"name":"Empty testcase","duration":17,"buffer":{}},{"name":"Simple gain test without resampling","duration":79,"buffer":{}},{"name":"Simple gain test without resampling (Stereo)","duration":77,"buffer":{}},{"name":"Simple gain test without resampling (Stereo and positional)","duration":92,"buffer":{}},{"name":"Simple gain test","duration":61,"buffer":{}},{"name":"Simple gain test (Stereo)","duration":77,"buffer":{}},{"name":"Simple gain test (Stereo and positional)","duration":90,"buffer":{}},{"name":"Upmix without resampling (Mono -> Stereo)","duration":76,"buffer":{}},{"name":"Downmix without resampling (Mono -> Stereo)","duration":63,"buffer":{}},{"name":"Simple mixing (same buffer)","duration":1004,"buffer":{}},{"name":"Simple mixing (different buffers)","duration":967,"buffer":{}},{"name":"Simple mixing with gains","duration":453,"buffer":{}},{"name":"Convolution reverb","duration":1143,"buffer":{}},{"name":"Granular synthesis","duration":5188,"buffer":{}},{"name":"Synth","duration":93,"buffer":{}},{"name":"Substractive synth","duration":81,"buffer":{}},{"name":"Stereo Panning","duration":79,"buffer":{}},{"name":"Stereo Panning with Automation","duration":218,"buffer":{}},{"name":"Periodic Wave with Automation","duration":225,"buffer":{}},{"name":"Geometric Mean","duration":166,"buffer":{}}]'], [u'[{"name":"Empty testcase","duration":19,"buffer":{}},{"name":"Simple gain test without resampling","duration":77,"buffer":{}},{"name":"Simple gain test without resampling (Stereo)","duration":75,"buffer":{}},{"name":"Simple gain test without resampling (Stereo and positional)","duration":90,"buffer":{}},{"name":"Simple gain test","duration":65,"buffer":{}},{"name":"Simple gain test (Stereo)","duration":81,"buffer":{}},{"name":"Simple gain test (Stereo and positional)","duration":89,"buffer":{}},{"name":"Upmix without resampling (Mono -> Stereo)","duration":76,"buffer":{}},{"name":"Downmix without resampling (Mono -> Stereo)","duration":63,"buffer":{}},{"name":"Simple mixing (same buffer)","duration":995,"buffer":{}},{"name":"Simple mixing (different buffers)","duration":975,"buffer":{}},{"name":"Simple mixing with gains","duration":433,"buffer":{}},{"name":"Convolution reverb","duration":1135,"buffer":{}},{"name":"Granular synthesis","duration":4585,"buffer":{}},{"name":"Synth","duration":93,"buffer":{}},{"name":"Substractive synth","duration":82,"buffer":{}},{"name":"Stereo Panning","duration":79,"buffer":{}},{"name":"Stereo Panning with Automation","duration":215,"buffer":{}},{"name":"Periodic Wave with Automation","duration":221,"buffer":{}},{"name":"Geometric Mean","duration":165,"buffer":{}}]']]}, u'browser_cycle': u'1', u'subtest_lower_is_better': True, u'cold': False, u'browser': u'Firefox 70.0a1 20190824215209', u'type': u'benchmark', u'page': u'http://127.0.0.1:50002/webaudio/index.html?raptor', u'unit': u'score', u'alert_threshold': 2}
[task 2019-08-24T23:14:23.001Z] 23:14:23 INFO - raptor-results-handler Info: received results in RaptorResultsHandler.add
[task 2019-08-24T23:14:23.029Z] 23:14:23 INFO - raptor-control-server Info: received webext_status: stopping gecko profiling
[task 2019-08-24T23:14:23.029Z] 23:14:23 INFO - raptor-control-server Info: received request to shutdown the browser
[task 2019-08-24T23:14:23.029Z] 23:14:23 INFO - raptor-control-server Info: shutting down browser (pid: 1446)
[task 2019-08-24T23:14:23.029Z] 23:14:23 INFO - raptor-control-server Info: received webext_status: Removed tab: 2
[task 2019-08-24T23:14:23.046Z] 23:14:23 INFO - PID 1446 | console.log: "[raptor-runnerjs] post success"
[task 2019-08-24T23:14:23.046Z] 23:14:23 INFO - PID 1446 | console.log: "[raptor-runnerjs] post success"
[task 2019-08-24T23:14:23.046Z] 23:14:23 INFO - PID 1446 | console.log: "[raptor-runnerjs] post success"
[task 2019-08-24T23:14:23.046Z] 23:14:23 INFO - PID 1446 | console.log: "[raptor-runnerjs] post success"
[task 2019-08-24T23:14:50.930Z] 23:14:50 INFO - Sat Aug 24 23:14:24 2019 MainThread Retrieving symbol zip from https://queue.taskcluster.net/v1/task/Hny0N4mmS6uWRQwpsrVITw/artifacts/public/build/target.crashreporter-symbols.zip...
[task 2019-08-24T23:14:50.930Z] 23:14:50 INFO - Sat Aug 24 23:14:28 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/firefox/8C006BE024DE35C5BAD24495BCC4E8940/firefox.sym
[task 2019-08-24T23:14:50.930Z] 23:14:50 INFO - Sat Aug 24 23:14:28 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/libmozglue.dylib/87E47BE0658B309C83E73FEE0A9A6B680/libmozglue.dylib.sym
[task 2019-08-24T23:14:50.930Z] 23:14:50 INFO - Sat Aug 24 23:14:28 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/liblgpllibs.dylib/6B873CE95BF238BEBD01EA74E7C2DBFC0/liblgpllibs.dylib.sym
[task 2019-08-24T23:14:50.930Z] 23:14:50 INFO - Sat Aug 24 23:14:28 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/libnss3.dylib/9D28C1BE7DDC30CEBC79FEF49A7FC73D0/libnss3.dylib.sym
...
[task 2019-08-24T23:14:50.933Z] 23:14:50 INFO - Sat Aug 24 23:14:48 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/CoreImage/96FA4D1BAC88305C8F4DD7D44657B7330/CoreImage.sym
[task 2019-08-24T23:14:50.933Z] 23:14:50 INFO - Sat Aug 24 23:14:48 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/CoreUI/105F61F3D0AE332BA4858615187BB4090/CoreUI.sym
[task 2019-08-24T23:14:50.933Z] 23:14:50 INFO - raptor-gecko-profile Info: Adding profile profile_raptor-webaudio-firefox/raptor-webaudio-firefox_pagecycle_2.profile to archive /Users/cltbld/tasks/task_1566688051/build/blobber_upload_dir/profile_raptor-webaudio-firefox.zip
[task 2019-08-24T23:14:52.406Z] 23:14:52 INFO - Sat Aug 24 23:14:51 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/libobjc-trampolines.dylib/5795A0483940380190CE33D1B1AF81F40/libobjc-trampolines.dylib.sym
[task 2019-08-24T23:14:52.406Z] 23:14:52 INFO - Sat Aug 24 23:14:51 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/AppleIntelHD5000GraphicsMTLDriver/CED88DF5113F3E629CB478847108335E0/AppleIntelHD5000GraphicsMTLDriver.sym
...
[task 2019-08-24T23:14:53.173Z] 23:14:53 INFO - Sat Aug 24 23:14:53 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/libresolv.9.dylib/893142A5F1533437A22D407EE542B5C50/libresolv.9.dylib.sym
[task 2019-08-24T23:14:53.173Z] 23:14:53 INFO - Sat Aug 24 23:14:53 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/libsasl2.2.dylib/1098761467633B5D9F2891D121BB49240/libsasl2.2.dylib.sym
[task 2019-08-24T23:14:53.813Z] 23:14:53 INFO - Sat Aug 24 23:14:53 2019 MainThread Parfatal error: /Library/Developer/CommandLineTools/usr/bin/lipo: can't figure out the architecture type of: /System/Library/Frameworks/Metal.framework/Versions/A/Metal
[task 2019-08-24T23:14:53.823Z] 23:14:53 INFO - sing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/libspindump.dylib/A584E4038C9538419C16E22664A5A63F0/libspindump.dylib.sym
[task 2019-08-24T23:14:53.823Z] 23:14:53 INFO - Sat Aug 24 23:14:53 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/libsqlite3.dylib/55CE34C400C03844B7ED80FA7F0AF03F0/libsqlite3.dylib.sym
[task 2019-08-24T23:14:53.823Z] 23:14:53 INFO - Sat Aug 24 23:14:53 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/libutil.dylib/CE9B18C966ED32D49D2901F8FCB467B00/libutil.dylib.sym
...
[task 2019-08-24T23:14:53.825Z] 23:14:53 INFO - Sat Aug 24 23:14:53 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/libunwind.dylib/24A97A67F0173CFCB0D06BD0224B13360/libunwind.dylib.sym
[task 2019-08-24T23:14:53.825Z] 23:14:53 INFO - Sat Aug 24 23:14:53 2019 MainThread Parsing SYM file at /var/folders/k5/_gdfgk8908s4w94l3h786f58000017/T/tmpChevEg/libxpc.dylib/9A0FFA79082F3293BF4963976B073B740/libxpc.dylib.sym
[task 2019-08-24T23:14:53.825Z] 23:14:53 INFO - raptor-control-server Info: shutting down control server
[task 2019-08-24T23:14:54.160Z] 23:14:54 INFO - raptor-main Info: finished
[task 2019-08-24T23:14:54.160Z] 23:14:54 ERROR - Traceback (most recent call last):
[task 2019-08-24T23:14:54.160Z] 23:14:54 INFO - File "/Users/cltbld/tasks/task_1566688051/build/tests/raptor/raptor/raptor.py", line 1270, in <module>
[task 2019-08-24T23:14:54.160Z] 23:14:54 INFO - main()
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - File "/Users/cltbld/tasks/task_1566688051/build/tests/raptor/raptor/raptor.py", line 1238, in main
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - success = raptor.run_tests(raptor_test_list, raptor_test_names)
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - File "/Users/cltbld/tasks/task_1566688051/build/tests/raptor/raptor/raptor.py", line 204, in run_tests
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - self.run_test_teardown(test)
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - File "/Users/cltbld/tasks/task_1566688051/build/tests/raptor/raptor/raptor.py", line 673, in run_test_teardown
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - super(RaptorDesktop, self).run_test_teardown(test)
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - File "/Users/cltbld/tasks/task_1566688051/build/tests/raptor/raptor/raptor.py", line 326, in run_test_teardown
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - super(Raptor, self).run_test_teardown(test)
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - File "/Users/cltbld/tasks/task_1566688051/build/tests/raptor/raptor/raptor.py", line 219, in run_test_teardown
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - self.gecko_profiler.symbolicate()
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - File "/Users/cltbld/tasks/task_1566688051/build/tests/raptor/raptor/gecko_profile.py", line 178, in symbolicate
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - profile_path)
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - File "/Users/cltbld/tasks/task_1566688051/build/tests/raptor/raptor/gecko_profile.py", line 113, in _save_gecko_profile
[task 2019-08-24T23:14:54.161Z] 23:14:54 INFO - exc_info=True)
[task 2019-08-24T23:14:54.162Z] 23:14:54 ERROR - TypeError: critical() got an unexpected keyword argument 'exc_info'
[task 2019-08-24T23:14:54.567Z] 23:14:54 ERROR - Return code: 1
[task 2019-08-24T23:14:54.567Z] 23:14:54 WARNING - setting return code to 1
[task 2019-08-24T23:14:54.567Z] 23:14:54 INFO - copying raptor results to upload dir:
[task 2019-08-24T23:14:54.567Z] 23:14:54 INFO - /Users/cltbld/tasks/task_1566688051/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-24T23:14:54.567Z] 23:14:54 INFO - copying raptor results from /Users/cltbld/tasks/task_1566688051/build/raptor.json to /Users/cltbld/tasks/task_1566688051/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-24T23:14:54.567Z] 23:14:54 CRITICAL - Error copying results /Users/cltbld/tasks/task_1566688051/build/raptor.json to upload dir /Users/cltbld/tasks/task_1566688051/build/blobber_upload_dir/perfherder-data.json
[task 2019-08-24T23:14:54.567Z] 23:14:54 INFO - [Errno 2] No such file or directory: u'/Users/cltbld/tasks/task_1566688051/build/raptor.json'
[task 2019-08-24T23:14:54.568Z] 23:14:54 INFO - Running post-action listener: _package_coverage_data
[task 2019-08-24T23:14:54.568Z] 23:14:54 INFO - Running post-action listener: _resource_record_post_action
[task 2019-08-24T23:14:54.568Z] 23:14:54 INFO - Running post-action listener: process_java_coverage_data
[task 2019-08-24T23:14:54.568Z] 23:14:54 INFO - Running post-action listener: stop_device
[task 2019-08-24T23:14:54.568Z] 23:14:54 INFO - [mozharness: 2019-08-24 23:14:54.568556Z] Finished run-tests step (success)
[task 2019-08-24T23:14:54.568Z] 23:14:54 INFO - Running post-run listener: _resource_record_post_run
[task 2019-08-24T23:14:54.630Z] 23:14:54 INFO - Total resource usage - Wall time: 122s; CPU: 25.0%; Read bytes: 376123392; Write bytes: 667795456; Read time: 3001; Write time: 2926
[task 2019-08-24T23:14:54.630Z] 23:14:54 INFO - TinderboxPrint: CPU usage<br/>24.8%
[task 2019-08-24T23:14:54.630Z] 23:14:54 INFO - TinderboxPrint: I/O read bytes / time<br/>376,123,392 / 3,001
[task 2019-08-24T23:14:54.630Z] 23:14:54 INFO - TinderboxPrint: I/O write bytes / time<br/>667,795,456 / 2,926
[task 2019-08-24T23:14:54.630Z] 23:14:54 INFO - TinderboxPrint: CPU idle<br/>365.5 (74.9%)
[task 2019-08-24T23:14:54.630Z] 23:14:54 INFO - TinderboxPrint: CPU system<br/>23.7 (4.9%)
[task 2019-08-24T23:14:54.630Z] 23:14:54 INFO - TinderboxPrint: CPU user<br/>98.6 (20.2%)
[task 2019-08-24T23:14:54.630Z] 23:14:54 INFO - TinderboxPrint: Swap in / out<br/>623,104,000 / 0
[task 2019-08-24T23:14:54.630Z] 23:14:54 INFO - install - Wall time: 18s; CPU: 39.0%; Read bytes: 253842944; Write bytes: 242413568; Read time: 14153; Write time: 388
[task 2019-08-24T23:14:54.631Z] 23:14:54 INFO - run-tests - Wall time: 105s; CPU: 22.0%; Read bytes: 368955392; Write bytes: 404357120; Read time: 2936; Write time: 2488
[task 2019-08-24T23:14:54.654Z] 23:14:54 WARNING - returning nonzero exit status 1
[taskcluster 2019-08-24T23:14:54.708Z] Exit Code: 1
[taskcluster 2019-08-24T23:14:54.708Z] User Time: 1m36.3111s
[taskcluster 2019-08-24T23:14:54.708Z] Kernel Time: 30.462631s
[taskcluster 2019-08-24T23:14:54.708Z] Wall Time: 2m58.466976088s
[taskcluster 2019-08-24T23:14:54.708Z] Result: FAILED
Description
•