1659116 - Perma [tier 2] raptor-main Critical: [chromium] TEST-UNEXPECTED-FAIL: test 'raptor-webaudio-chromium' timed out loading test page: waiting for pending metrics

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  u'JSGC_DISABLE_POISONING': u'1',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'LANG': 'en_US.UTF-8',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'LC_ALL': 'en_US.UTF-8',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'LOGNAME': 'cltbld',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  u'MINIDUMP_SAVE_PATH': u'/Users/cltbld/tasks/task_1597405869/build/blobber_upload_dir',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  u'MINIDUMP_STACKWALK': '/Users/cltbld/tasks/task_1597405869/fetches/minidump_stackwalk/minidump_stackwalk',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'MOZ_AUTOMATION': '1',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'MOZ_FETCHES': '[{"artifact": "public/build/fix-stacks.tar.xz", "extract": true, "task": "BjKIfev6S7OCm21T9Dwi-g"}, {"artifact": "public/build/minidump_stackwalk.tar.xz", "extract": true, "task": "fe4Hqs8XSdu4LgSyh7vrxw"}, {"artifact": "public/chromium-mac.tar.bz2", "extract": true, "task": "JAr25Mx9TWSyPgmz1JFoJQ"}]',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'MOZ_FETCHES_DIR': '/Users/cltbld/tasks/task_1597405869/fetches',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'MOZ_NODE_PATH': '/usr/local/bin/node',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'MOZ_SCM_LEVEL': '3',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  u'MOZ_UPLOAD_DIR': u'/Users/cltbld/tasks/task_1597405869/build/blobber_upload_dir',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'PATH': '/Users/cltbld/tasks/task_1597405869/build/venv/bin:/usr/local/bin:/usr/bin:/bin:/usr/sbin:/sbin',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'PWD': '/Users/cltbld',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  u'PYTHONPATH': u'/Users/cltbld/tasks/task_1597405869/build/tests/raptor',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  u'RUST_BACKTRACE': u'full',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'SCCACHE_DISABLE': '1',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  u'SCRIPTSPATH': '/Users/cltbld/tasks/task_1597405869/mozharness',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'SHELL': '/bin/bash',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'SHLVL': '1',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'SSH_AUTH_SOCK': '/private/tmp/com.apple.launchd.BSTUtVfEKn/Listeners',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'TASKCLUSTER_ROOT_URL': 'https://firefox-ci-tc.services.mozilla.com',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'TASK_ID': 'RNP_SoykSPmny5ZtGzVH9g',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'TMPDIR': '/var/folders/s8/w8hy03qn63393k8_ykc09f_8000017/T/',
[task 2020-08-14T12:05:26.937Z] 12:05:26     INFO -  'USER': 'cltbld',
[task 2020-08-14T12:05:26.938Z] 12:05:26     INFO -  'VIRTUAL_ENV': '/Users/cltbld/tasks/task_1597405869/build/venv',
[task 2020-08-14T12:05:26.938Z] 12:05:26     INFO -  'XPC_FLAGS': '0x0',
[task 2020-08-14T12:05:26.938Z] 12:05:26     INFO -  'XPC_SERVICE_NAME': '0',
[task 2020-08-14T12:05:26.938Z] 12:05:26     INFO -  '_': '/usr/local/bin/generic-worker',
[task 2020-08-14T12:05:26.938Z] 12:05:26     INFO -  '__CF_USER_TEXT_ENCODING': '0x27:0:0',
[task 2020-08-14T12:05:26.938Z] 12:05:26     INFO -  '__PYVENV_LAUNCHER__': '/usr/local/bin/python3'}
[task 2020-08-14T12:05:26.938Z] 12:05:26     INFO - Calling ['/Users/cltbld/tasks/task_1597405869/build/venv/bin/python', u'/Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/raptor.py', u'--binary', u'/Users/cltbld/tasks/task_1597405869/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium', u'--symbolsPath', u'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Pvnq95wNSsascHVrSP3ltg/artifacts/public/build/target.crashreporter-symbols.zip', u'--app', 'chromium', u'--conditioned-profile-scenario', u'settled', u'--host', u'127.0.0.1', u'--test', 'raptor-webaudio', u'--log-tbpl-level=debug'] with output_timeout 3600
[task 2020-08-14T12:05:27.339Z] 12:05:27     INFO -  raptor-main Info: Python version: 2.7.16 (v2.7.16:413a49145e, Mar  2 2019, 14:32:10)
[task 2020-08-14T12:05:27.339Z] 12:05:27     INFO -  [GCC 4.2.1 Compatible Apple LLVM 6.0 (clang-600.0.57)]
[task 2020-08-14T12:05:27.340Z] 12:05:27     INFO -  raptor-main Info: raptor-start
[task 2020-08-14T12:05:27.340Z] 12:05:27     INFO -  raptor-main Info: received command line arguments: Namespace(activity=None, app='chromium', binary='/Users/cltbld/tasks/task_1597405869/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium', browser_cycles=None, browsertime=False, browsertime_browsertimejs=None, browsertime_chromedriver=None, browsertime_ffmpeg=None, browsertime_geckodriver=None, browsertime_no_ffwindowrecorder=False, browsertime_node=None, browsertime_video=False, chimera=False, cold=False, conditioned_profile_scenario='settled', cpu_test=False, debug_mode=False, device_name=None, disable_perf_tuning=False, e10s=True, enable_fission=False, enable_webrender=False, extra_prefs={}, gecko_profile=False, gecko_profile_entries=None, gecko_profile_interval=None, gecko_profile_threads=None, host='127.0.0.1', installerpath=None, intent=None, is_release_build=False, live_sites=False, log_errorsummary=None, log_grouped=None, log_html=None, log_mach=None, log_mach_buffer=None, log_mach_level=None, log_mach_screenshot=None, log_mach_verbose=None, log_raw=None, log_raw_level=None, log_tbpl=None, log_tbpl_buffer=None, log_tbpl_compact=None, log_tbpl_level='debug', log_unittest=None, log_xunit=None, memory_test=False, no_conditioned_profile=False, noinstall=False, obj_path=None, page_cycles=None, page_timeout=None, post_startup_delay=30000, power_test=False, project='mozilla-central', run_local=False, symbols_path='https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Pvnq95wNSsascHVrSP3ltg/artifacts/public/build/target.crashreporter-symbols.zip', test='raptor-webaudio', test_url_params=None, verbose=False)
[task 2020-08-14T12:05:27.340Z] 12:05:27     INFO -  raptor-manifest Info: /Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/raptor.ini
[task 2020-08-14T12:05:27.371Z] 12:05:27     INFO -  raptor-manifest Info: configuring settings for test raptor-webaudio-chromium
[task 2020-08-14T12:05:27.376Z] 12:05:27     INFO -  raptor-main Info: raptor tests scheduled to run:
[task 2020-08-14T12:05:27.377Z] 12:05:27     INFO -  raptor-main Info: raptor-webaudio-chromium
[task 2020-08-14T12:05:27.377Z] 12:05:27     INFO -  raptor-perftest Info: Using a conditioned profile.
[task 2020-08-14T12:05:27.377Z] 12:05:27     INFO -  raptor-perftest Warning: [chromium] Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: /Users/cltbld/tasks/task_1597405869/fetches/chrome-mac/Chromium.app/Contents/MacOS
[task 2020-08-14T12:05:27.377Z] 12:05:27     INFO -  raptor-perftest Info: Attempting to get version through fallback method...
[task 2020-08-14T12:05:27.483Z] 12:05:27     INFO -  Chromium 86.0.4234.0
[task 2020-08-14T12:05:27.618Z] 12:05:27     INFO -  raptor-perftest Info: Browser name: chromium
[task 2020-08-14T12:05:27.618Z] 12:05:27     INFO -  raptor-perftest Info: Browser version: 86.0.4234.0
[task 2020-08-14T12:05:27.618Z] 12:05:27     INFO -  raptor-perftest Warning: [chromium] Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: /Users/cltbld/tasks/task_1597405869/fetches/chrome-mac/Chromium.app/Contents/MacOS
[task 2020-08-14T12:05:27.618Z] 12:05:27     INFO -  raptor-perftest Info: Attempting to get version through fallback method...
[task 2020-08-14T12:05:27.682Z] 12:05:27     INFO -  Chromium 86.0.4234.0
[task 2020-08-14T12:05:27.768Z] 12:05:27     INFO -  raptor-perftest Info: Browser name: chromium
[task 2020-08-14T12:05:27.768Z] 12:05:27     INFO -  raptor-perftest Info: Browser version: 86.0.4234.0
[task 2020-08-14T12:05:27.768Z] 12:05:27     INFO -  raptor-perftest Info: Post startup delay set to 1000 ms
[task 2020-08-14T12:05:27.769Z] 12:05:27     INFO -  raptor-perftest Info: main raptor init, config is: {'verbose': False, 'e10s': True, 'app': 'chromium', 'symbols_path': 'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Pvnq95wNSsascHVrSP3ltg/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'run_local': False, 'chimera': False, 'cold': False, 'gecko_profile_interval': None, 'binary': '/Users/cltbld/tasks/task_1597405869/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium', 'enable_control_server_wait': False, 'no_conditioned_profile': False, 'platform': 'mac', 'conditioned_profile_scenario': 'settled', 'extra_prefs': {}, 'gecko_profile': False, 'gecko_profile_entries': None, 'disable_perf_tuning': False, 'host': '127.0.0.1', 'enable_fission': False, 'memory_test': False, 'enable_webrender': False, 'obj_path': None, 'live_sites': False, 'device_name': None, 'project': 'mozilla-central', 'cpu_test': False, 'is_release_build': False, 'using_condprof': True, 'processor': 'x86_64'}
[task 2020-08-14T12:05:27.769Z] 12:05:27     INFO -  raptor-perftest Info: Merging profile: /Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/profile_data/base
[task 2020-08-14T12:05:27.769Z] 12:05:27     INFO -  raptor-perftest Info: Merging profile: /Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/profile_data/common
[task 2020-08-14T12:05:27.769Z] 12:05:27     INFO -  raptor-perftest Info: Merging profile: /Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/profile_data/perf
[task 2020-08-14T12:05:27.778Z] 12:05:27     INFO -  raptor-perftest Info: Merging profile: /Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/profile_data/raptor
[task 2020-08-14T12:05:27.778Z] 12:05:27     INFO -  raptor-perftest Info: Local browser profile: /var/folders/s8/w8hy03qn63393k8_ykc09f_8000017/T/tmpcP6kBE.mozrunner/Default
[task 2020-08-14T12:05:27.778Z] 12:05:27     INFO -  raptor-perftest Warning: [chromium] Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: /Users/cltbld/tasks/task_1597405869/fetches/chrome-mac/Chromium.app/Contents/MacOS
[task 2020-08-14T12:05:27.778Z] 12:05:27     INFO -  raptor-perftest Info: Attempting to get version through fallback method...
[task 2020-08-14T12:05:27.850Z] 12:05:27     INFO -  Chromium 86.0.4234.0
[task 2020-08-14T12:05:27.868Z] 12:05:27     INFO -  raptor-perftest Info: Browser name: chromium
[task 2020-08-14T12:05:27.868Z] 12:05:27     INFO -  raptor-perftest Info: Browser version: 86.0.4234.0
[task 2020-08-14T12:05:27.873Z] 12:05:27     INFO -  raptor-control-server Info: raptor control server running on port 50002...
[task 2020-08-14T12:05:27.873Z] 12:05:27     INFO -  raptor-webext-desktop Info: creating browser runner using mozrunner
[task 2020-08-14T12:05:27.873Z] 12:05:27     INFO -  raptor-perftest Info: starting test: raptor-webaudio-chromium
[task 2020-08-14T12:05:27.873Z] 12:05:27     INFO -  raptor-webext Info: starting web extension test: raptor-webaudio-chromium
[task 2020-08-14T12:05:27.873Z] 12:05:27     INFO -  raptor-webext Info: test settings: {'expected_browser_cycles': 1, u'alert_threshold': u'2.0', 'browser_cycles': 1, 'here': u'/Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/tests/benchmarks', 'path': u'/Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/tests/benchmarks/raptor-webaudio-chromium', 'manifest_relpath': u'tests/benchmarks/raptor-webaudio.ini', 'cold': False, u'unit': u'score', 'name': u'raptor-webaudio-chromium', u'lower_is_better': True, u'page_cycles': u'5', u'apps': u'chromium', u'test_url': u'http://<host>:<port>/webaudio/index.html?raptor', 'manifest': u'/Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/tests/benchmarks/raptor-webaudio.ini', 'ancestor_manifest': 'raptor.ini', u'page_timeout': u'360000', 'browser_cycle': 1, 'expected': 'pass', u'type': u'benchmark', 'relpath': u'tests/benchmarks/raptor-webaudio-chromium'}
[task 2020-08-14T12:05:27.874Z] 12:05:27     INFO -  raptor-webext Info: web extension config: {'subtest_alert_on': None, 'verbose': False, 'e10s': True, 'app': 'chromium', 'symbols_path': 'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Pvnq95wNSsascHVrSP3ltg/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'run_local': False, 'chimera': False, 'cold': False, 'gecko_profile_interval': None, 'binary': '/Users/cltbld/tasks/task_1597405869/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium', 'local_profile_dir': '/var/folders/s8/w8hy03qn63393k8_ykc09f_8000017/T/tmpcP6kBE.mozrunner/Default', 'enable_control_server_wait': False, 'no_conditioned_profile': False, 'platform': 'mac', 'conditioned_profile_scenario': 'settled', 'extra_prefs': {}, 'gecko_profile': False, 'gecko_profile_entries': None, 'disable_perf_tuning': False, 'host': '127.0.0.1', 'enable_fission': False, 'memory_test': False, 'enable_webrender': False, 'obj_path': None, 'live_sites': False, 'device_name': None, 'project': 'mozilla-central', 'cpu_test': False, 'is_release_build': False, 'using_condprof': True, 'processor': 'x86_64'}
[task 2020-08-14T12:05:27.874Z] 12:05:27     INFO -  raptor-benchmark Info: bench_dir contains:
[task 2020-08-14T12:05:27.874Z] 12:05:27     INFO -  raptor-benchmark Info: ['six-speed', 'SunSpider', 'ARES-6', 'Speedometer', 'resources', 'StyleBench', 'MotionMark', 'wasm-godot', 'webaudio']
[task 2020-08-14T12:05:27.874Z] 12:05:27     INFO -  raptor-benchmark Info: writing wptserve headers file
[task 2020-08-14T12:05:27.874Z] 12:05:27     INFO -  raptor-benchmark Info: wrote wpt headers file: /Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/tests/webkit/PerformanceTests/__dir__.headers
[task 2020-08-14T12:05:27.874Z] 12:05:27     INFO -  raptor-benchmark Info: starting webserver on '127.0.0.1:50003'
[task 2020-08-14T12:05:27.875Z] 12:05:27     INFO -  raptor-benchmark Info: serving benchmarks from here: /Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/tests/webkit/PerformanceTests
[task 2020-08-14T12:05:27.875Z] 12:05:27     INFO -  raptor-gen-test-config Info: writing test settings into background js, so webext can get it
[task 2020-08-14T12:05:27.875Z] 12:05:27     INFO -  raptor-gen-test-config Info: finished writing test config to /Users/cltbld/tasks/task_1597405869/build/tests/raptor/webext/raptor/auto_gen_test_config.js
[task 2020-08-14T12:05:27.875Z] 12:05:27     INFO -  raptor-webext Info: installing webext /Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-08-14T12:05:27.875Z] 12:05:27     INFO -  raptor-webext-desktop Info: starting chromium
[task 2020-08-14T12:05:27.883Z] 12:05:27     INFO -  Application command: /Users/cltbld/tasks/task_1597405869/fetches/chrome-mac/Chromium.app/Contents/MacOS/Chromium --allow-downgrade --user-data-dir=/var/folders/s8/w8hy03qn63393k8_ykc09f_8000017/T/tmpcP6kBE.mozrunner --profile-directory=Default --no-first-run --use-mock-keychain --no-default-browser-check --load-extension=/Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-08-14T12:05:30.004Z] 12:05:30     INFO -  raptor-control-server Info: received webext_loaded: raptor runner.js is loaded!
[task 2020-08-14T12:05:30.004Z] 12:05:30     INFO -  raptor-control-server Info: received webext_status: testing on Chrome 86.0.4234.0
[task 2020-08-14T12:05:30.004Z] 12:05:30     INFO -  raptor-control-server Info: received webext_status: test name is: raptor-webaudio-chromium
[task 2020-08-14T12:05:30.004Z] 12:05:30     INFO -  raptor-control-server Info: received webext_status: test settings url is: http://127.0.0.1:50002/json/raptor-webaudio-chromium.json
[task 2020-08-14T12:05:30.004Z] 12:05:30     INFO -  raptor-control-server Info: received webext_status: starting raptorRunner
[task 2020-08-14T12:05:30.016Z] 12:05:30     INFO -  raptor-control-server Info: reading test settings from json/raptor-webaudio-chromium.json
[task 2020-08-14T12:05:30.026Z] 12:05:30     INFO -  raptor-control-server Info: sent test settings to webext runner
[task 2020-08-14T12:05:30.051Z] 12:05:30     INFO -  raptor-control-server Info: received webext_status: * pausing 1 seconds to let browser settle... *
[task 2020-08-14T12:05:31.144Z] 12:05:31     INFO -  raptor-control-server Info: received webext_status: opening new tab
[task 2020-08-14T12:05:31.179Z] 12:05:31     INFO -  raptor-control-server Info: received webext_status: opened new empty tab: 3
[task 2020-08-14T12:05:31.191Z] 12:05:31     INFO -  raptor-control-server Info: received webext_status: found active tab with id 3
[task 2020-08-14T12:05:31.198Z] 12:05:31     INFO -  raptor-control-server Info: received webext_status: running 5 pagecycles of http://127.0.0.1:50003/webaudio/index.html?raptor
[task 2020-08-14T12:05:32.206Z] 12:05:32     INFO -  raptor-control-server Info: received webext_status: begin page cycle 1
[task 2020-08-14T12:05:32.211Z] 12:05:32     INFO -  raptor-control-server Info: received webext_status: update tab 3 for http://127.0.0.1:50003/webaudio/index.html?raptor
[task 2020-08-14T12:05:32.214Z] 12:05:32     INFO -  raptor-control-server Info: received webext_status: tab 3 updated
[task 2020-08-14T12:11:32.294Z] 12:11:32     INFO -  raptor-control-server Info: received webext_raptor-page-timeout: [u'raptor-webaudio-chromium', u'http://127.0.0.1:50003/webaudio/index.html?raptor', 1]
[task 2020-08-14T12:11:32.300Z] 12:11:32     INFO -  raptor-control-server Info: received webext_screenshot
[task 2020-08-14T12:11:32.300Z] 12:11:32     INFO -  perftest-results-handler Info: received screenshot
[task 2020-08-14T12:11:32.305Z] 12:11:32     INFO -  raptor-control-server Info: received webext_status: closing Tab: 3
[task 2020-08-14T12:11:32.325Z] 12:11:32     INFO -  raptor-control-server Info: received webext_status: closed tab: 3
[task 2020-08-14T12:11:32.340Z] 12:11:32     INFO -  raptor-control-server Info: received request to shutdown the browser
[task 2020-08-14T12:11:32.340Z] 12:11:32     INFO -  raptor-control-server Info: shutting down browser (pid: 1098)
[task 2020-08-14T12:11:34.704Z] 12:11:34     INFO -  raptor-webext Info: removing webext /Users/cltbld/tasks/task_1597405869/build/tests/raptor/raptor/webextension/../../webext/raptor
[task 2020-08-14T12:11:34.704Z] 12:11:34     INFO -  perftest-results-handler Info: summarizing raptor test results
[task 2020-08-14T12:11:34.704Z] 12:11:34     INFO -  perftest-output Error: [chromium] no raptor test results found for raptor-webaudio-chromium
[task 2020-08-14T12:11:34.704Z] 12:11:34     INFO -  perftest-output Info: error: no raptor test results found, so no need to combine browser cycles
[task 2020-08-14T12:11:34.704Z] 12:11:34     INFO -  perftest-output Error: [chromium] no summarized raptor results found for raptor-webaudio-chromium
[task 2020-08-14T12:11:34.705Z] 12:11:34     INFO -  perftest-output Info: screen captures can be found locally at: /Users/cltbld/tasks/task_1597405869/build/screenshots.html
[task 2020-08-14T12:11:34.705Z] 12:11:34     INFO -  perftest-results-handler Critical: [chromium] PERFHERDER_DATA was seen 0 times, expected 1.
[task 2020-08-14T12:11:34.705Z] 12:11:34     INFO -  raptor-control-server Info: shutting down control server
[task 2020-08-14T12:11:35.202Z] 12:11:35     INFO -  raptor-webext Info: finished
[task 2020-08-14T12:11:35.202Z] 12:11:35    ERROR -  raptor-main Critical: [chromium] TEST-UNEXPECTED-FAIL: test 'raptor-webaudio-chromium' timed out loading test page: waiting for pending metrics
[task 2020-08-14T12:11:35.337Z] 12:11:35    ERROR - Return code: 1
[task 2020-08-14T12:11:35.337Z] 12:11:35  WARNING - setting return code to 1
[task 2020-08-14T12:11:35.337Z] 12:11:35     INFO - Copying Raptor results to upload dir:
[task 2020-08-14T12:11:35.338Z] 12:11:35     INFO - /Users/cltbld/tasks/task_1597405869/build/blobber_upload_dir/perfherder-data.json
[task 2020-08-14T12:11:35.338Z] 12:11:35     INFO - Copying raptor results from /Users/cltbld/tasks/task_1597405869/build/raptor.json to /Users/cltbld/tasks/task_1597405869/build/blobber_upload_dir/perfherder-data.json
[task 2020-08-14T12:11:35.338Z] 12:11:35 CRITICAL - Error copying results /Users/cltbld/tasks/task_1597405869/build/raptor.json to upload dir /Users/cltbld/tasks/task_1597405869/build/blobber_upload_dir/perfherder-data.json
[task 2020-08-14T12:11:35.338Z] 12:11:35     INFO - [Errno 2] No such file or directory: u'/Users/cltbld/tasks/task_1597405869/build/raptor.json'
[task 2020-08-14T12:11:35.338Z] 12:11:35     INFO - /Users/cltbld/tasks/task_1597405869/build/blobber_upload_dir/screenshots.html
[task 2020-08-14T12:11:35.338Z] 12:11:35     INFO - Copying raptor results from /Users/cltbld/tasks/task_1597405869/build/screenshots.html to /Users/cltbld/tasks/task_1597405869/build/blobber_upload_dir/screenshots.html
[task 2020-08-14T12:11:35.339Z] 12:11:35     INFO - Running post-action listener: _package_coverage_data
[task 2020-08-14T12:11:35.339Z] 12:11:35     INFO - Running post-action listener: _resource_record_post_action
[task 2020-08-14T12:11:35.339Z] 12:11:35     INFO - Running post-action listener: process_java_coverage_data
[task 2020-08-14T12:11:35.339Z] 12:11:35     INFO - Running post-action listener: stop_device
[task 2020-08-14T12:11:35.339Z] 12:11:35     INFO - [mozharness: 2020-08-14 12:11:35.339590Z] Finished run-tests step (success)
[task 2020-08-14T12:11:35.339Z] 12:11:35     INFO - Running post-run listener: _resource_record_post_run
[task 2020-08-14T12:11:35.423Z] 12:11:35     INFO - Total resource usage - Wall time: 384s; CPU: 9.0%; Read bytes: 145797120; Write bytes: 338235392; Read time: 2728; Write time: 1257
[task 2020-08-14T12:11:35.423Z] 12:11:35     INFO - TinderboxPrint: CPU usage<br/>8.6%
[task 2020-08-14T12:11:35.423Z] 12:11:35     INFO - TinderboxPrint: I/O read bytes / time<br/>145,797,120 / 2,728
[task 2020-08-14T12:11:35.423Z] 12:11:35     INFO - TinderboxPrint: I/O write bytes / time<br/>338,235,392 / 1,257
[task 2020-08-14T12:11:35.423Z] 12:11:35     INFO - TinderboxPrint: CPU idle<br/>1,404.3 (91.5%)
[task 2020-08-14T12:11:35.423Z] 12:11:35     INFO - TinderboxPrint: CPU user<br/>118.1 (7.7%)
[task 2020-08-14T12:11:35.423Z] 12:11:35     INFO - TinderboxPrint: Swap in / out<br/>323,694,592 / 0
[task 2020-08-14T12:11:35.423Z] 12:11:35     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-14T12:11:35.424Z] 12:11:35     INFO - install - Wall time: 17s; CPU: 37.0%; Read bytes: 221345280; Write bytes: 213921792; Read time: 13196; Write time: 423
[task 2020-08-14T12:11:35.426Z] 12:11:35     INFO - run-tests - Wall time: 368s; CPU: 7.0%; Read bytes: 137367552; Write bytes: 117878784; Read time: 2664; Write time: 815
[task 2020-08-14T12:11:35.493Z] 12:11:35  WARNING - returning nonzero exit status 1
[fetches 2020-08-14T12:11:35.510Z] removing /Users/cltbld/tasks/task_1597405869/fetches
[fetches 2020-08-14T12:11:35.541Z] finished
[taskcluster 2020-08-14T12:11:35.551Z]    Exit Code: 1
[taskcluster 2020-08-14T12:11:35.551Z]    User Time: 2m29.74956s
[taskcluster 2020-08-14T12:11:35.551Z]  Kernel Time: 16.857978s
[taskcluster 2020-08-14T12:11:35.551Z]    Wall Time: 8m23.027612696s
[taskcluster 2020-08-14T12:11:35.551Z]       Result: FAILED
[taskcluster 2020-08-14T12:11:35.551Z] === Task Finished ===
[taskcluster 2020-08-14T12:11:35.551Z] Task Duration: 8m23.031249445s
[taskcluster 2020-08-14T12:11:35.653Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2021-08-14T12:03:07.520Z
[taskcluster 2020-08-14T12:11:35.893Z] 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-14T12:03:07.520Z
[taskcluster 2020-08-14T12:11:36.345Z] Uploading artifact public/test_info/screenshots.html from file build/blobber_upload_dir/screenshots.html with content encoding "gzip", mime type "text/html; charset=utf-8" and expiry 2021-08-14T12:03:07.520Z
[taskcluster:error] exit status 1

Comment 1

[Alexandru Michis [:malexandru]]

This looks to have started appearing since the merge to nightly on August 12th:

• OS X 10.14 Shippable opt:
  https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&resultStatus=pending%2Crunning%2Csuccess%2Ctestfailed%2Cbusted%2Cexception&searchStr=os%2Cx%2C10.14%2Cshippable%2Copt%2Craptor%2Cperformance%2Ctests%2Con%2Cgoogle%2Cchromium%2Ctest-macosx1014-64-shippable%2Fopt-raptor-webaudio-chromium-e10s%2Cwa&fromchange=08471023c834ba75bb85d0e92e3d24bf1324b883&tochange=605c404fbd80c67e1127ac054b8bec6742bd748f&selectedTaskRun=b8EKCA6iQCWoZTFcQWanLA.0

• Windows 10 x64 Shippable opt:
  https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&group_state=expanded&searchStr=windows%2C10%2Cx64%2Cshippable%2Copt%2Craptor%2Cperformance%2Ctests%2Con%2Cgoogle%2Cchromium%2Ctest-windows10-64-shippable%2Fopt-raptor-webaudio-chromium-e10s%2Cwa&fromchange=08471023c834ba75bb85d0e92e3d24bf1324b883&tochange=605c404fbd80c67e1127ac054b8bec6742bd748f&selectedTaskRun=clIIB0hwSAqt6EHXXJh1GQ.0

Greg, could you please take a look?

Comment 2

[Intermittent Failures Robot]

15 failures in 662 pushes (0.023 failures/push) were associated with this bug yesterday.

Repository breakdown:

• mozilla-central: 15

Platform breakdown:

• linux64-shippable: 4
• windows10-64-shippable: 3
• windows7-32-shippable: 4
• macosx1014-64-shippable: 4

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

Comment 3

[Intermittent Failures Robot]

28 failures in 3601 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

This is the #24 most frequent failure this week.

Repository breakdown:

• mozilla-central: 28

Platform breakdown:

• linux64-shippable: 4
• windows10-64-shippable: 8
• windows7-32-shippable: 4
• macosx1014-64-shippable: 12

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

Comment 4

[Intermittent Failures Robot]

18 failures in 4100 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 12
• autoland: 6

Platform breakdown:

• windows7-32-shippable: 5
• macosx1014-64-shippable: 3
• windows10-64-shippable: 7
• linux64-shippable: 3

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

Comment 5

[Greg Mierzwinski [:sparky]]

:alexandrui will look into this.

Comment 6

[Intermittent Failures Robot]

12 failures in 4046 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 12

Platform breakdown:

• windows10-64-shippable: 3
• linux64-shippable: 3
• macosx1014-64-shippable: 3
• windows7-32-shippable: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659116&startday=2020-08-24&endday=2020-08-30&tree=all

Comment 7

[Alexandru Ionescu (needinfo me) [:alexandrui]]

Bebe will continue my investigation to bisect or whatever is needed as I will be in PTO starting tomorrow until Sept 11th.

Comment 8

[Intermittent Failures Robot]

8 failures in 2984 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 8

Platform breakdown:

• linux64-shippable: 2
• macosx1014-64-shippable: 2
• windows7-32-shippable: 2
• windows10-64-shippable: 2

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

Comment 9

[Intermittent Failures Robot]

12 failures in 3410 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 12

Platform breakdown:

• linux64-shippable: 3
• macosx1014-64-shippable: 3
• windows10-64-shippable: 3
• windows7-32-shippable: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659116&startday=2020-09-07&endday=2020-09-13&tree=all

Comment 10

[Greg Mierzwinski [:sparky]]

I'm not sure why perftest-triage was added here, :bebe/:alexandrui should be investigating this failure.

Comment 11

[Intermittent Failures Robot]

12 failures in 3760 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 12

Platform breakdown:

• macosx1014-64-shippable: 3
• windows10-64-shippable: 3
• linux64-shippable: 3
• windows7-32-shippable: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659116&startday=2020-09-14&endday=2020-09-20&tree=all

Comment 12

[Florin Strugariu [:Bebe]]

Ran the test on cromium localy and it shows this error in the console:

webaudio-bench.js:36 The AudioContext was not allowed to start. It must be resumed (or created) after a user gesture on the page. https://goo.gl/7K7WLu
(anonymous) @ webaudio-bench.js:36

:dave do you know who can help us review the webaudio code?

Comment 13

[Florin Strugariu [:Bebe]]

Tested this on Chrome also and got the same error. :sparky do we have failures with chrome also?

Comment 14

[Greg Mierzwinski [:sparky]]

It's only on chromium, see the intermittent bot post.

Comment 15

[Florin Strugariu [:Bebe]]

OK tested this locally on chrome and chromium and the test faills on my end on both test cases.

Also did some hacking on the benchmark and from my findings the Granular synthesis sub test is hanging in both browsers.
https://searchfox.org/mozilla-central/source/third_party/webkit/PerformanceTests/webaudio/benchmarks.js#265

Looks like the test was recently touched by: Bug 1624987 - Too much webaudio data in PGO profiles

Paul can you take a look over the test please?

Comment 16

[Intermittent Failures Robot]

8 failures in 4019 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 8

Platform breakdown:

• windows7-32-shippable: 2
• macosx1014-64-shippable: 2
• linux64-shippable: 2
• windows10-64-shippable: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1659116&startday=2020-09-21&endday=2020-09-27&tree=all

Comment 17

[Dave Hunt [:davehunt] [he/him] ⌚BST]

(In reply to Florin Strugariu [:Bebe] (needinfo me) from comment #12)

:dave do you know who can help us review the webaudio code?

I would suggest either :padenot (already needinfo'd) or :bryce.

Comment 18

[Paul Adenot (:padenot)]

Yeah I can lower this.

Comment 19

[Paul Adenot (:padenot)]

Attachment: Bug 1659116 - Update webaudio-benchmarks to e09b852. r?dmajor

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/788dc9ddde5c
Update webaudio-benchmarks to e09b852. r=dmajor DONTBUILD

Comment 21

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/788dc9ddde5c

Comment 22

[Florin Strugariu [:Bebe]]

== Change summary for alert #27100 (as of Wed, 30 Sep 2020 09:46:11 GMT) ==

Improvements:

20% raptor-webaudio-firefox windows10-64-shippable opt 107.00 -> 85.25
20% raptor-webaudio-firefox windows10-64-shippable-qr opt webrender 105.62 -> 84.42
19% raptor-webaudio-firefox macosx1014-64-shippable opt 158.75 -> 128.75
19% raptor-webaudio-firefox windows10-64-shippable-qr opt webrender 104.08 -> 84.42
19% raptor-webaudio-firefox windows7-32-shippable opt 123.17 -> 99.92
15% raptor-webaudio-firefox linux64-shippable opt 118.92 -> 101.08
15% raptor-webaudio-firefox linux64-shippable-qr opt webrender 123.83 -> 105.83

For up to date results, see: https://treeherder.mozilla.org/perf.html#/alerts?id=27100

Comment 23

[Paul Adenot (:padenot)]

This ^ is because the test changed.