Closed
Bug 1632385
Opened 6 years ago
Closed 6 years ago
Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-stylebench-chrome' timed out loading test page: waiting for pending metrics
Categories
(Testing :: Raptor, defect, P5)
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: malexandru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=298876384&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ME1p-t9BQ_CKlq5LdrUBiQ/runs/0/artifacts/public/logs/live_backing.log
[task 2020-04-22T17:32:20.048Z] 17:32:20 INFO - Calling ['C:\\Users\\task_1587571147\\build\\venv\\Scripts\\python', u'C:\\Users\\task_1587571147\\build\\tests\\raptor\\raptor\\raptor.py', u'--binary', u'C:\\Progra~2\\Google\\Chrome\\Application\\chrome.exe', u'--symbolsPath', u'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/PCub-YROSrCD5zCIdE-ANQ/artifacts/public/build/target.crashreporter-symbols.zip', u'--app', 'chrome', u'--conditioned-profile-scenario', u'settled', u'--host', u'127.0.0.1', u'--test', 'raptor-stylebench', u'--log-tbpl-level=debug'] with output_timeout 3600
[task 2020-04-22T17:32:20.359Z] 17:32:20 INFO - raptor-main Info: raptor-start
[task 2020-04-22T17:32:20.361Z] 17:32:20 INFO - raptor-main Info: received command line arguments: Namespace(activity=None, app='chrome', binary='C:\\Progra~2\\Google\\Chrome\\Application\\chrome.exe', browser_cycles=None, browsertime=False, browsertime_browsertimejs=None, browsertime_chromedriver=None, browsertime_ffmpeg=None, browsertime_geckodriver=None, browsertime_node=None, browsertime_video=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, 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/PCub-YROSrCD5zCIdE-ANQ/artifacts/public/build/target.crashreporter-symbols.zip', test='raptor-stylebench', test_url_params=None)
[task 2020-04-22T17:32:20.361Z] 17:32:20 INFO - raptor-manifest Info: C:\Users\task_1587571147\build\tests\raptor\raptor\raptor.ini
[task 2020-04-22T17:32:20.422Z] 17:32:20 INFO - raptor-manifest Info: configuring settings for test raptor-stylebench-chrome
[task 2020-04-22T17:32:20.422Z] 17:32:20 INFO - raptor-main Info: raptor tests scheduled to run:
[task 2020-04-22T17:32:20.422Z] 17:32:20 INFO - raptor-main Info: raptor-stylebench-chrome
[task 2020-04-22T17:32:20.422Z] 17:32:20 INFO - raptor-perftest Info: Using a conditioned profile.
[task 2020-04-22T17:32:20.423Z] 17:32:20 INFO - raptor-perftest Warning: Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: C:\Progra~2\Google\Chrome\Application
[task 2020-04-22T17:32:20.423Z] 17:32:20 INFO - raptor-perftest Info: Attempting to get version through fallback method...
[task 2020-04-22T17:32:20.503Z] 17:32:20 INFO - raptor-perftest Info: Browser name: chrome
[task 2020-04-22T17:32:20.503Z] 17:32:20 INFO - raptor-perftest Info: Browser version: 81.0.4044.113
[task 2020-04-22T17:32:20.503Z] 17:32:20 INFO - raptor-perftest Warning: Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: C:\Progra~2\Google\Chrome\Application
[task 2020-04-22T17:32:20.503Z] 17:32:20 INFO - raptor-perftest Info: Attempting to get version through fallback method...
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Info: Browser name: chrome
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Info: Browser version: 81.0.4044.113
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Info: Post startup delay set to 1000 ms
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Info: main raptor init, config is: {'e10s': True, 'app': 'chrome', 'symbols_path': 'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/PCub-YROSrCD5zCIdE-ANQ/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'run_local': False, 'gecko_profile_interval': None, 'binary': 'C:\\Progra~2\\Google\\Chrome\\Application\\chrome.exe', 'enable_control_server_wait': False, 'no_conditioned_profile': False, 'platform': 'win', '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, 'device_name': None, 'project': 'mozilla-central', 'cpu_test': False, 'is_release_build': False, 'using_condprof': True, 'processor': 'x86_64'}
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Info: Merging profile: C:\Users\task_1587571147\build\tests\raptor\raptor\profile_data\base
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Info: Merging profile: C:\Users\task_1587571147\build\tests\raptor\raptor\profile_data\common
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Info: Merging profile: C:\Users\task_1587571147\build\tests\raptor\raptor\profile_data\perf
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Info: Merging profile: C:\Users\task_1587571147\build\tests\raptor\raptor\profile_data\raptor
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Info: Local browser profile: c:\users\task_1587571147\appdata\local\temp\tmpjse4th.mozrunner\Default
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Warning: Failed to get browser meta data through mozversion: LocalAppNotFoundError-Application not found at: C:\Progra~2\Google\Chrome\Application
[task 2020-04-22T17:32:20.543Z] 17:32:20 INFO - raptor-perftest Info: Attempting to get version through fallback method...
[task 2020-04-22T17:32:20.582Z] 17:32:20 INFO - raptor-perftest Info: Browser name: chrome
[task 2020-04-22T17:32:20.582Z] 17:32:20 INFO - raptor-perftest Info: Browser version: 81.0.4044.113
[task 2020-04-22T17:32:20.583Z] 17:32:20 INFO - raptor-control-server Info: raptor control server running on port 49798...
[task 2020-04-22T17:32:20.583Z] 17:32:20 INFO - raptor-webext-desktop Info: creating browser runner using mozrunner
[task 2020-04-22T17:32:20.583Z] 17:32:20 INFO - raptor-perftest Info: starting test: raptor-stylebench-chrome
[task 2020-04-22T17:32:20.583Z] 17:32:20 INFO - raptor-webext Info: starting web extension test: raptor-stylebench-chrome
[task 2020-04-22T17:32:20.584Z] 17:32:20 INFO - raptor-webext Info: test settings: {'expected_browser_cycles': 1, u'alert_threshold': u'2.0', u'subtest_unit': u'ms', 'here': u'C:\\Users\\task_1587571147\\build\\tests\\raptor\\raptor\\tests\\benchmarks', 'path': u'C:\\Users\\task_1587571147\\build\\tests\\raptor\\raptor\\tests\\benchmarks\\raptor-stylebench-chrome', 'manifest_relpath': u'tests\\benchmarks\\raptor-stylebench.ini', 'cold': False, u'unit': u'score', 'name': u'raptor-stylebench-chrome', u'lower_is_better': False, u'page_cycles': u'5', u'subtest_lower_is_better': True, u'apps': u'chrome', u'test_url': u'http://<host>:<port>/StyleBench/index.html?raptor', 'manifest': u'C:\\Users\\task_1587571147\\build\\tests\\raptor\\raptor\\tests\\benchmarks\\raptor-stylebench.ini', 'ancestor_manifest': 'raptor.ini', u'page_timeout': u'120000', 'browser_cycle': 1, 'expected': 'pass', u'type': u'benchmark', 'relpath': u'tests\\benchmarks\\raptor-stylebench-chrome'}
[task 2020-04-22T17:32:20.584Z] 17:32:20 INFO - raptor-webext Info: web extension config: {'subtest_alert_on': None, 'e10s': True, 'app': 'chrome', 'symbols_path': 'https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/PCub-YROSrCD5zCIdE-ANQ/artifacts/public/build/target.crashreporter-symbols.zip', 'power_test': False, 'run_local': False, 'gecko_profile_interval': None, 'binary': 'C:\\Progra~2\\Google\\Chrome\\Application\\chrome.exe', 'local_profile_dir': 'c:\\users\\task_1587571147\\appdata\\local\\temp\\tmpjse4th.mozrunner\\Default', 'enable_control_server_wait': False, 'no_conditioned_profile': False, 'platform': 'win', '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, 'device_name': None, 'project': 'mozilla-central', 'cpu_test': False, 'is_release_build': False, 'using_condprof': True, 'processor': 'x86_64'}
[task 2020-04-22T17:32:20.584Z] 17:32:20 INFO - raptor-benchmark Info: bench_dir contains:
[task 2020-04-22T17:32:20.584Z] 17:32:20 INFO - raptor-benchmark Info: ['ARES-6', 'MotionMark', 'resources', 'six-speed', 'Speedometer', 'StyleBench', 'SunSpider', 'wasm-godot', 'webaudio']
[task 2020-04-22T17:32:20.584Z] 17:32:20 INFO - raptor-benchmark Info: writing wptserve headers file
[task 2020-04-22T17:32:20.585Z] 17:32:20 INFO - raptor-benchmark Info: wrote wpt headers file: C:\Users\task_1587571147\build\tests\raptor\raptor\tests\webkit\PerformanceTests\__dir__.headers
[task 2020-04-22T17:32:20.585Z] 17:32:20 INFO - raptor-benchmark Info: starting webserver on '127.0.0.1:49799'
[task 2020-04-22T17:32:20.586Z] 17:32:20 INFO - raptor-benchmark Info: serving benchmarks from here: C:\Users\task_1587571147\build\tests\raptor\raptor\tests\webkit\PerformanceTests
[task 2020-04-22T17:32:20.586Z] 17:32:20 INFO - raptor-gen-test-config Info: writing test settings into background js, so webext can get it
[task 2020-04-22T17:32:20.586Z] 17:32:20 INFO - raptor-gen-test-config Info: finished writing test config to C:\Users\task_1587571147\build\tests\raptor\webext\raptor\auto_gen_test_config.js
[task 2020-04-22T17:32:20.586Z] 17:32:20 INFO - raptor-webext Info: installing webext C:\Users\task_1587571147\build\tests\raptor\raptor\webextension\..\..\webext\raptor
[task 2020-04-22T17:32:20.586Z] 17:32:20 INFO - raptor-webext-desktop Info: starting chrome
[task 2020-04-22T17:32:20.586Z] 17:32:20 INFO - Application command: C:\Progra~2\Google\Chrome\Application\chrome.exe --allow-downgrade --user-data-dir=c:\users\task_1587571147\appdata\local\temp\tmpjse4th.mozrunner --profile-directory=Default --no-first-run --use-mock-keychain --no-default-browser-check --load-extension=C:\Users\task_1587571147\build\tests\raptor\raptor\webextension\..\..\webext\raptor
[task 2020-04-22T17:32:21.833Z] 17:32:21 INFO - raptor-control-server Info: received webext_loaded: raptor runner.js is loaded!
[task 2020-04-22T17:32:21.835Z] 17:32:21 INFO - raptor-control-server Info: received webext_status: test name is: raptor-stylebench-chrome
[task 2020-04-22T17:32:21.840Z] 17:32:21 INFO - raptor-control-server Info: received webext_status: test settings url is: http://127.0.0.1:49798/json/raptor-stylebench-chrome.json
[task 2020-04-22T17:32:21.842Z] 17:32:21 INFO - raptor-control-server Info: received webext_status: starting raptorRunner
[task 2020-04-22T17:32:21.847Z] 17:32:21 INFO - raptor-control-server Info: reading test settings from json/raptor-stylebench-chrome.json
[task 2020-04-22T17:32:21.847Z] 17:32:21 INFO - raptor-control-server Info: sent test settings to webext runner
[task 2020-04-22T17:32:21.866Z] 17:32:21 INFO - raptor-control-server Info: received webext_status: * pausing 1 seconds to let browser settle... *
[task 2020-04-22T17:32:22.877Z] 17:32:22 INFO - raptor-control-server Info: received webext_status: openinig new tab
[task 2020-04-22T17:32:22.896Z] 17:32:22 INFO - raptor-control-server Info: received webext_status: opened new empty tab: 3
[task 2020-04-22T17:32:22.896Z] 17:32:22 INFO - raptor-control-server Info: received webext_status: running 5 pagecycles of http://127.0.0.1:49799/StyleBench/index.html?raptor
[task 2020-04-22T17:32:23.902Z] 17:32:23 INFO - raptor-control-server Info: received webext_status: begin page cycle 1
[task 2020-04-22T17:32:23.902Z] 17:32:23 INFO - raptor-control-server Info: received webext_status: found active tab with id 3
[task 2020-04-22T17:32:23.907Z] 17:32:23 INFO - raptor-control-server Info: received webext_status: update tab 3 for http://127.0.0.1:49799/StyleBench/index.html?raptor
[task 2020-04-22T17:32:23.909Z] 17:32:23 INFO - raptor-control-server Info: received webext_status: tab 3 updated
[task 2020-04-22T17:34:23.924Z] 17:34:23 INFO - raptor-control-server Info: received webext_raptor-page-timeout: [u'raptor-stylebench-chrome', u'http://127.0.0.1:49799/StyleBench/index.html?raptor']
[task 2020-04-22T17:34:23.946Z] 17:34:23 INFO - raptor-control-server Info: received webext_screenshot
[task 2020-04-22T17:34:23.946Z] 17:34:23 INFO - perftest-results-handler Info: received screenshot
[task 2020-04-22T17:34:23.956Z] 17:34:23 INFO - raptor-control-server Info: received webext_status: found active tab with id 3
[task 2020-04-22T17:34:23.956Z] 17:34:23 INFO - raptor-control-server Info: received webext_status: closing Tab: 3
[task 2020-04-22T17:34:23.975Z] 17:34:23 INFO - raptor-control-server Info: received webext_status: closed tab: 3
[task 2020-04-22T17:34:23.975Z] 17:34:23 INFO - raptor-control-server Info: received request to shutdown the browser
[task 2020-04-22T17:34:23.975Z] 17:34:23 INFO - raptor-control-server Info: shutting down browser (pid: 7408)
[task 2020-04-22T17:34:25.654Z] 17:34:25 INFO - raptor-webext Info: removing webext C:\Users\task_1587571147\build\tests\raptor\raptor\webextension\..\..\webext\raptor
[task 2020-04-22T17:34:25.654Z] 17:34:25 INFO - perftest-results-handler Info: summarizing raptor test results
[task 2020-04-22T17:34:25.654Z] 17:34:25 INFO - perftest-output Error: no raptor test results found for raptor-stylebench-chrome
[task 2020-04-22T17:34:25.654Z] 17:34:25 INFO - perftest-output Info: error: no raptor test results found, so no need to combine browser cycles
[task 2020-04-22T17:34:25.654Z] 17:34:25 INFO - perftest-output Error: no summarized raptor results found for raptor-stylebench-chrome
[task 2020-04-22T17:34:25.654Z] 17:34:25 INFO - perftest-output Info: screen captures can be found locally at: C:\Users\task_1587571147\build\screenshots.html
[task 2020-04-22T17:34:25.671Z] 17:34:25 INFO - perftest-results-handler Critical: PERFHERDER_DATA was seen 0 times, expected 1.
[task 2020-04-22T17:34:25.671Z] 17:34:25 INFO - raptor-control-server Info: shutting down control server
[task 2020-04-22T17:34:25.972Z] 17:34:25 INFO - raptor-webext Info: finished
[task 2020-04-22T17:34:25.972Z] 17:34:25 ERROR - raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-stylebench-chrome' timed out loading test page: http://127.0.0.1:49799/StyleBench/index.html?raptor
[task 2020-04-22T17:34:26.081Z] 17:34:26 ERROR - Return code: 1
[task 2020-04-22T17:34:26.081Z] 17:34:26 WARNING - setting return code to 1
[task 2020-04-22T17:34:26.081Z] 17:34:26 INFO - Copying Raptor results to upload dir:
[task 2020-04-22T17:34:26.081Z] 17:34:26 INFO - C:\Users\task_1587571147\build\blobber_upload_dir\perfherder-data.json
[task 2020-04-22T17:34:26.081Z] 17:34:26 INFO - Copying raptor results from C:\Users\task_1587571147\build\raptor.json to C:\Users\task_1587571147\build\blobber_upload_dir\perfherder-data.json
[task 2020-04-22T17:34:26.082Z] 17:34:26 CRITICAL - Error copying results C:\Users\task_1587571147\build\raptor.json to upload dir C:\Users\task_1587571147\build\blobber_upload_dir\perfherder-data.json
[task 2020-04-22T17:34:26.082Z] 17:34:26 INFO - [Errno 2] No such file or directory: u'C:\\Users\\task_1587571147\\build\\raptor.json'
[task 2020-04-22T17:34:26.082Z] 17:34:26 INFO - C:\Users\task_1587571147\build\blobber_upload_dir\screenshots.html
[task 2020-04-22T17:34:26.082Z] 17:34:26 INFO - Copying raptor results from C:\Users\task_1587571147\build\screenshots.html to C:\Users\task_1587571147\build\blobber_upload_dir\screenshots.html
[task 2020-04-22T17:34:26.083Z] 17:34:26 INFO - Running post-action listener: _package_coverage_data
[task 2020-04-22T17:34:26.083Z] 17:34:26 INFO - Running post-action listener: _resource_record_post_action
[task 2020-04-22T17:34:26.083Z] 17:34:26 INFO - Running post-action listener: process_java_coverage_data
[task 2020-04-22T17:34:26.083Z] 17:34:26 INFO - Running post-action listener: stop_device
[task 2020-04-22T17:34:26.083Z] 17:34:26 INFO - [mozharness: 2020-04-22 17:34:26.083000Z] Finished run-tests step (success)
[task 2020-04-22T17:34:26.083Z] 17:34:26 INFO - Running post-run listener: _resource_record_post_run
[task 2020-04-22T17:34:26.159Z] 17:34:26 INFO - Total resource usage - Wall time: 128s; CPU: 2.0%; Read bytes: 461307392; Write bytes: 284936192; Read time: 5; Write time: 4
[task 2020-04-22T17:34:26.159Z] 17:34:26 INFO - TinderboxPrint: CPU usage<br/>1.8%
[task 2020-04-22T17:34:26.159Z] 17:34:26 INFO - TinderboxPrint: I/O read bytes / time<br/>461,307,392 / 5
[task 2020-04-22T17:34:26.159Z] 17:34:26 INFO - TinderboxPrint: I/O write bytes / time<br/>284,936,192 / 4
[task 2020-04-22T17:34:26.159Z] 17:34:26 INFO - TinderboxPrint: CPU idle<br/>1,002.7 (98.2%)
[task 2020-04-22T17:34:26.159Z] 17:34:26 INFO - TinderboxPrint: CPU user<br/>12.7 (1.2%)
[task 2020-04-22T17:34:26.159Z] 17:34:26 INFO - install - Wall time: 2s; CPU: 13.0%; Read bytes: 65536; Write bytes: 2826240; Read time: 0; Write time: 0
[task 2020-04-22T17:34:26.161Z] 17:34:26 INFO - run-tests - Wall time: 126s; CPU: 2.0%; Read bytes: 460666880; Write bytes: 273885184; Read time: 5; Write time: 4
[task 2020-04-22T17:34:26.188Z] 17:34:26 WARNING - returning nonzero exit status 1
[fetches 2020-04-22T17:34:26.201Z] removing C:/Users/task_1587571147/fetches
[fetches 2020-04-22T17:34:26.202Z] finished
[taskcluster 2020-04-22T17:34:26.219Z] Exit Code: 1
[taskcluster 2020-04-22T17:34:26.219Z] User Time: 0s
[taskcluster 2020-04-22T17:34:26.219Z] Kernel Time: 31.25ms
[taskcluster 2020-04-22T17:34:26.219Z] Wall Time: 3m18.2623613s
[taskcluster 2020-04-22T17:34:26.219Z] Result: FAILED
[taskcluster 2020-04-22T17:34:26.219Z] === Task Finished ===
[taskcluster 2020-04-22T17:34:26.219Z] Task Duration: 3m18.2623613s
[taskcluster 2020-04-22T17:34:26.314Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2021-04-22T17:30:50.529Z
[taskcluster 2020-04-22T17:34:26.552Z] Uploading artifact public/test_info/resource-usage.json from file build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2021-04-22T17:30:50.529Z
[taskcluster 2020-04-22T17:34:26.712Z] 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-04-22T17:30:50.529Z
[taskcluster 2020-04-22T17:34:26.849Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ME1p-t9BQ_CKlq5LdrUBiQ/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2021-04-22T17:30:50.529Z
[taskcluster:error] exit status 1
| Comment hidden (Intermittent Failures Robot) |
Summary: Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-stylebench-chrome' timed out loading test page: http://127.0.0.1:49799/StyleBench/index.html?raptor → Intermittent raptor-main Critical: TEST-UNEXPECTED-FAIL: test 'raptor-stylebench-chrome' timed out loading test page: waiting for pending metrics
|
||
Comment 2•6 years ago
|
||
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•