service_worker.service_worker_micro_benchmark broken on all platforms |
|||||||||
Issue descriptionhttps://build.chromium.org/p/chromium.perf/builders/Mac%2010.11%20Perf https://chromium-swarm.appspot.com/task?id=38b54ca586c67f10&refresh=10&show_raw=1 (INFO) 2017-09-19 17:23:29,428 browser.DumpStateUponFailure:393 DevTools listening on ws://127.0.0.1:56908/devtools/browser/25163d2c-725f-485c-acae-fdb23fc4906e 2017-09-19 17:22:11.302 Google Chrome[12780:143133] Errors logged by ksadmin: KSKeyedPersistentStore store directory does not exist. [com.google.UpdateEngine.CommonErrorDomain:501 - '/Library/Google/GoogleSoftwareUpdate/TicketStore' - 'KSKeyedPersistentStore.m:372'] KSPersistentTicketStore failed to load tickets. (productID: com.google.Chrome) [com.google.UpdateEngine.CoreErrorDomain:1051 - '/Library/Google/GoogleSoftwareUpdate/TicketStore/Keystone.ticketstore'] (KSKeyedPersistentStore store directory does not exist. - '/Library/Google/GoogleSoftwareUpdate/TicketStore' [com.google.UpdateEngine.CommonErrorDomain:501]) ksadmin cannot access the ticket store:<KSUpdateError:0x10030f260 domain="com.google.UpdateEngine.CoreErrorDomain" code=1051 userInfo={ function = "-[KSProductKeyedStore(ProtectedMethods) errorForStoreError:productID:message:timeoutMessage:]"; date = 2017-09-20 00:22:11 +0000; productids = {( "com.google.Chrome" )}; filename = "KSProductKeyedStore.m"; line = 91; NSFilePath = "/Library/Google/GoogleSoftwareUpdate/TicketStore/Keystone.ticketstore"; NSUnderlyingError = <KSError:0x10030d200 domain="com.google.UpdateEngine.CommonErrorDomain" code=501 userInfo={ date = 2017-09-20 00:22:11 +0000; line = 372; filename = "KSKeyedPersistentStore.m"; function = "-[KSKeyedPersistentStore(PrivateMethods) validateStorePath]"; NSFilePath = "/Library/Google/GoogleSoftwareUpdate/TicketStore"; NSLocalizedDescription = "KSKeyedPersistentStore store directory does not exist."; } >; NSLocalizedDescription = "KSPersistentTicketStore failed to load tickets."; } > (INFO) 2017-09-19 17:23:29,428 browser.DumpStateUponFailure:396 *********** END OF BROWSER STANDARD OUTPUT ************ (INFO) 2017-09-19 17:23:29,428 browser.DumpStateUponFailure:398 ********************* BROWSER LOG ********************* (INFO) 2017-09-19 17:23:29,428 browser.DumpStateUponFailure:400 No log file (INFO) 2017-09-19 17:23:29,429 browser.DumpStateUponFailure:403 ***************** END OF BROWSER LOG ****************** Traceback (most recent call last): File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/story_runner.py", line 105, in _RunStoryAndProcessErrorIfNeeded state.RunStory(results) File "/b/s/w/ir/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function return func(*args, **kwargs) File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/page/shared_page_state.py", line 330, in RunStory self._current_page.Run(self) File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/page/__init__.py", line 108, in Run shared_state.page_test.RunNavigateSteps(self, current_tab) File "/b/s/w/ir/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function return func(*args, **kwargs) File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/page/legacy_page_test.py", line 152, in RunNavigateSteps page.RunNavigateSteps(action_runner) File "/b/s/w/ir/tools/perf/page_sets/service_worker_micro_benchmark.py", line 14, in RunNavigateSteps action_runner.WaitForJavaScriptCondition('window.done') File "/b/s/w/ir/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function return func(*args, **kwargs) File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/actions/action_runner.py", line 262, in WaitForJavaScriptCondition return self._tab.WaitForJavaScriptCondition(*args, **kwargs) File "/b/s/w/ir/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function return func(*args, **kwargs) File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 239, in WaitForJavaScriptCondition return self._inspector_backend.WaitForJavaScriptCondition(*args, **kwargs) File "/b/s/w/ir/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function return func(*args, **kwargs) File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 291, in WaitForJavaScriptCondition e.message + '\n' + debug_message) TimeoutException: Timed out while waiting 60s for IsJavaScriptExpressionTrue. Console output:
,
Sep 20 2017
Started bisect job https://chromeperf.appspot.com/buildbucket_job_status/8967914350259469696
,
Sep 20 2017
Started bisect job https://chromeperf.appspot.com/buildbucket_job_status/8967914176791505536
,
Sep 20 2017
=== Auto-CCing suspected CL author nednguyen@google.com === Hi nednguyen@google.com, the bisect results pointed to your CL, please take a look at the results. === BISECT JOB RESULTS === Test failure found with culprit Suspected Commit Author : nednguyen Commit : 86c099bf6743822659c9b445653d2eeb3c4b400c Date : Tue Sep 19 17:37:22 2017 Subject: Roll tsproxy to the latest version Bisect Details Configuration: android_nexus5X_perf_bisect Benchmark : service_worker.service_worker_micro_benchmark Metric : benchmark_duration/benchmark_duration Revision Exit Code N chromium@502825 0 +- N/A 2 good chromium@502904 0 +- N/A 2 good chromium@502943 0 +- N/A 2 good chromium@502948 0 +- N/A 2 good chromium@502950 0 +- N/A 2 good chromium@502950,catapult@86c099bf67 1 +- N/A 2 bad <-- chromium@502950,catapult@ab30bb20a8 1 +- N/A 2 bad chromium@502951 1 +- N/A 2 bad chromium@502953 1 +- N/A 2 bad chromium@502963 1 +- N/A 2 bad chromium@502982 1 +- N/A 2 bad To Run This Test src/tools/perf/run_benchmark -v --browser=android-chromium --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests service_worker.service_worker_micro_benchmark More information on addressing performance regressions: http://g.co/ChromePerformanceRegressions Debug information about this bisect: https://chromeperf.appspot.com/buildbucket_job_status/8967914176791505536 For feedback, file a bug with component Speed>Bisection
,
Sep 20 2017
I would revert this, but IIRC that tsproxy roll was to fix failures in serving static pages, so reverting it would only shift the failure and not fix anything. (If that is wrong, please revert).
,
Sep 20 2017
=== BISECT JOB RESULTS === Test failure found with culprit Suspected Commit Author : nednguyen Commit : 86c099bf6743822659c9b445653d2eeb3c4b400c Date : Tue Sep 19 17:37:22 2017 Subject: Roll tsproxy to the latest version Bisect Details Configuration: mac_10_11_perf_bisect Benchmark : service_worker.service_worker_micro_benchmark Metric : benchmark_duration/benchmark_duration Revision Exit Code N chromium@502872 0 +- N/A 1 good chromium@502927 0 +- N/A 1 good chromium@502941 0 +- N/A 1 good chromium@502948 0 +- N/A 1 good chromium@502950 0 +- N/A 1 good chromium@502950,catapult@86c099bf67 1 +- N/A 1 bad <-- chromium@502950,catapult@ab30bb20a8 1 +- N/A 1 bad chromium@502951 1 +- N/A 1 bad chromium@502952 1 +- N/A 1 bad chromium@502955 1 +- N/A 1 bad chromium@502982 1 +- N/A 1 bad To Run This Test src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests service_worker.service_worker_micro_benchmark More information on addressing performance regressions: http://g.co/ChromePerformanceRegressions Debug information about this bisect: https://chromeperf.appspot.com/buildbucket_job_status/8967914678739397920 For feedback, file a bug with component Speed>Bisection
,
Sep 20 2017
=== BISECT JOB RESULTS === Test failure found with culprit Suspected Commit Author : nednguyen Commit : 86c099bf6743822659c9b445653d2eeb3c4b400c Date : Tue Sep 19 17:37:22 2017 Subject: Roll tsproxy to the latest version Bisect Details Configuration: win_perf_bisect Benchmark : service_worker.service_worker_micro_benchmark Metric : benchmark_duration/benchmark_duration Revision Exit Code N chromium@502867 0 +- N/A 2 good chromium@502920 0 +- N/A 2 good chromium@502946 0 +- N/A 2 good chromium@502950 0 +- N/A 2 good chromium@502950,catapult@86c099bf67 1 +- N/A 2 bad <-- chromium@502950,catapult@ab30bb20a8 1 +- N/A 2 bad chromium@502951 1 +- N/A 2 bad chromium@502952 1 +- N/A 2 bad chromium@502953 1 +- N/A 2 bad chromium@502959 1 +- N/A 2 bad chromium@502972 1 +- N/A 2 bad To Run This Test src/tools/perf/run_benchmark -v --browser=release --output-format=chartjson --upload-results --pageset-repeat=1 --also-run-disabled-tests service_worker.service_worker_micro_benchmark More information on addressing performance regressions: http://g.co/ChromePerformanceRegressions Debug information about this bisect: https://chromeperf.appspot.com/buildbucket_job_status/8967914350259469696 For feedback, file a bug with component Speed>Bisection
,
Sep 21 2017
Adding owner of change that was rolled with Ned's CL.
,
Sep 21 2017
Ned, is it possible that the fix exposed an issue with the original test by no longer accidentally sending the requests to WPR? When I ran it locally it looks like the test was loading "http://localhost:8091/index.html" and the browser reported a SOCKS connection error. Looking at the tsproxy log I see: 10:15:02.728 - [7] Incoming connection from ('127.0.0.1', 37544) 10:15:02.728 - [7] New Socks5 client 10:15:02.729 - [7] SOCKS <= 2 byte(s) 10:15:02.729 - [7] Resolving localhost:8091 10:15:02.729 - [7] Connection to localhost detected 10:15:02.729 - [7] AsyncDNS - calling getaddrinfo for 127.0.0.1:8091 10:15:02.729 - [7] Resolving 127.0.0.1:8091 Completed 10:15:02.730 - [7] Resolved localhost, Connecting 10:15:02.731 - [7] Connecting to 127.0.0.1:8091 10:15:02.731 - [7] Error 10:15:02.731 - [7] SOCKS <= 16 byte(s) 10:15:02.731 - [7] Connected 10:15:02.732 - [7] Browser Connection Closed by browser 10:15:02.732 - [7] Server Connection Closed From tsproxy's point of view it looks like it is correctly detecting it as a localhost request and bypassing WPR but the socket connect to the requested localhost port failed.
,
Sep 21 2017
I think it's possible. I will look closely of the behavior of the benchmark before & after patch. Cc'ed benchmark owners as well
,
Sep 21 2017
I confirm that undo the change to tsproxy make the test passing. It's a bit baffling to me why that is the case.
,
Sep 22 2017
Patrick: after comparing the two logs (without the latest fix & with the latest fix), I think it's likely that the fix introduce another tsproxy bug which makes this particular cases fail. I am assigning this bug to you, lemme know if you need any help.
,
Sep 22 2017
It looks like it is loading a WPR page set /home/pmeenan/src/chrome/src/tools/perf/page_sets/data/service_worker_micro_benchmark_004.wprgo The page set has recorded pages for http://localhost:8091/request-latency-worker.js The way tsproxy is used for telemetry, all localhost requests bypass the WPR rewriting so as best as I can tell this is working as WAI. There are a few ways to fix it: 1 - Add an option to tsproxy and telemetry to turn off the localhost bypass and allow WPR recordings of localhost content. 2 - Use a local web server for the recorded content instead of replay of a local server. 3 - Make a replay recording of the content from a hosted page somewhere other than localhost. 4 - Have tsproxy only ignore the re-mapping for 127.0.0.1 explicitly and treat "localhost" as a named site that doesn't get bypassed. #4 may transparently fix this one but I can't guarantee it wouldn't break others. Ned, let me know if you want either of the tsproxy changes and I can take care of that part.
,
Sep 22 2017
Oh wow. I think (2) is the best option. Asssign to horo@ to put the request-latency-worker.js in the local directory instead of using WPR recording. If this is not possible, xunjieli@ also made a script that can convert the domainname from http://localhost:8091 --> http://testing/.. which I think can be use to address this kind of issue.
,
Sep 25 2017
I will disable the failing test why owner deciding the options to fix this. Reverting 86c099bf6743822659c9b445653d2eeb3c4b400c is not an option as reverting it will make other tests fail.
,
Sep 26 2017
Perfbot sheriff checking in: ping on disabling the test per #15?
,
Sep 26 2017
,
Sep 26 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/dc10ba2abdf20a272e2ff39fa249603559bd9fcc commit dc10ba2abdf20a272e2ff39fa249603559bd9fcc Author: Ned Nguyen <nednguyen@google.com> Date: Tue Sep 26 14:41:57 2017 Disable service_worker.service_worker_micro_benchmark on all platform TBR=horo@chromium.org, falken@chromium.org Bug: 767086 Change-Id: Ibbbe0ef8f1d4b90cf5daa511756a741f2acb200a Reviewed-on: https://chromium-review.googlesource.com/682494 Reviewed-by: Ned Nguyen <nednguyen@google.com> Commit-Queue: Ned Nguyen <nednguyen@google.com> Cr-Commit-Position: refs/heads/master@{#504366} [modify] https://crrev.com/dc10ba2abdf20a272e2ff39fa249603559bd9fcc/tools/perf/benchmarks/service_worker.py
,
Oct 10 2017
,
Jan 16
,
Jan 16
|
|||||||||
►
Sign in to add a comment |
|||||||||
Comment 1 by 42576172...@developer.gserviceaccount.com
, Sep 20 2017