New issue
Advanced search Search tips

Issue 860544 link

Starred by 1 user

Issue metadata

Status: Unconfirmed
Owner: ----
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux
Pri: 3
Type: Bug



Sign in to add a comment

TimeoutException running loading.cluster_telemetry on sfgate.com

Project Member Reported by skobes@chromium.org, Jul 5

Issue description

Attempting to run this benchmark with --cache-temperature=hot often produces exceptions in telemetry (see output below).  It looks like it's waiting for some change in document.readyState that never happens.

---

$ tools/perf/run_benchmark loading.cluster_telemetry --browser=exact --browser-executable=out/d/chrome --extra-browser-args="--enable-experimental-web-platform-features --disable-features=SubresourceFilter" --urls-list=https://www.sfgate.com/ --user-agent=desktop --use-live-sites --cache-temperature=hot
(WARNING) 2018-07-05 15:14:02,879 desktop_browser_finder.FindAllAvailableBrowsers:274  Chrome build location for linux_x86_64 not found. Browser will be run without Flash.
(WARNING) 2018-07-05 15:14:06,097 desktop_browser_finder.FindAllAvailableBrowsers:274  Chrome build location for linux_x86_64 not found. Browser will be run without Flash.
(WARNING) 2018-07-05 15:14:09,304 desktop_browser_finder.FindAllAvailableBrowsers:274  Chrome build location for linux_x86_64 not found. Browser will be run without Flash.
[ RUN      ] loading.cluster_telemetry/https://www.sfgate.com/@{'temperature': 'hot'}
(ERROR) 2018-07-05 15:17:59,101 story_runner.ProcessError:100  Handleable error
Traceback (most recent call last):
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py", line 125, in _RunStoryAndProcessErrorIfNeeded
    state.RunStory(results)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/telemetry/telemetry/page/shared_page_state.py", line 310, in RunStory
    self._current_page.Run(self)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/telemetry/telemetry/page/__init__.py", line 95, in Run
    shared_state.page_test.RunNavigateSteps(self, current_tab)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/telemetry/telemetry/page/legacy_page_test.py", line 152, in RunNavigateSteps
    page.RunNavigateSteps(action_runner)
  File "/usr/local/google/home/skobes/c/a/src/tools/perf/contrib/cluster_telemetry/page_set.py", line 35, in RunNavigateSteps
    action_runner.Navigate(self.url)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/telemetry/telemetry/internal/actions/action_runner.py", line 186, in Navigate
    timeout_in_seconds=timeout_in_seconds))
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/telemetry/telemetry/internal/actions/action_runner.py", line 62, in _RunAction
    action.RunAction(self._tab)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/telemetry/telemetry/internal/actions/navigate.py", line 27, in RunAction
    tab.WaitForDocumentReadyStateToBeInteractiveOrBetter(time_left_in_seconds)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 103, in WaitForDocumentReadyStateToBeInteractiveOrBetter
    'document.readyState == "complete"', timeout=timeout)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 239, in WaitForJavaScriptCondition
    return self._inspector_backend.WaitForJavaScriptCondition(*args, **kwargs)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "/usr/local/google/home/skobes/c/a/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 302, in WaitForJavaScriptCondition
    e.message + '\n' + debug_message)
TimeoutException: Timed out while waiting 59s for IsJavaScriptExpressionTrue.
Console output:
(error) https://maps.googleapis.com/maps/api/js?sensor=false&libraries=places&key=AIzaSyDe35QHDRNUkZHYH9sC3aTbv0IYImJRYjY&dummy=.js:96: You have included the Google Maps JavaScript API multiple times on this page. This may cause unexpected errors.
(warning) https://maps.googleapis.com/maps-api-v3/api/js/33/6a/util.js:226: Google Maps JavaScript API warning: SensorNotRequired https://developers.google.com/maps/documentation/javascript/error-messages#sensor-not-required

(WARNING) 2018-07-05 15:17:59,416 artifact_results.AddArtifact:134  Moving artifact file '/tmp/tmp7FUf_3.png' to '/usr/local/google/home/skobes/c/a/src/tools/perf/artifacts'
[  FAILED  ] loading.cluster_telemetry/https://www.sfgate.com/@{'temperature': 'hot'} (256376 ms)
View generated trace files online at https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/https___www_sfgate_com__2018-07-05_15-14-09_64921.html for story https://www.sfgate.com/
Uploading logs of page https://www.sfgate.com/ to https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/328b7f3e-8088-11e8-a81e-3c52825ed297 (1 out of 1)
Uploading screenshot of page https://www.sfgate.com/ to https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/3359229a-8088-11e8-a81e-3c52825ed297 (1 out of 1)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ]  loading.cluster_telemetry/https://www.sfgate.com/@{'temperature': 'hot'}

1 FAILED TEST

View HTML results online at https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/html-results/results-2018-07-05_15-18-33
View result at file:///usr/local/google/home/skobes/c/a/src/tools/perf/results.html
 
Cc: dproy@chromium.org maxlg@chromium.org
Max/Deep have you folks seen this?
I had encountered this issue before. Try if increasing the navigation timeout would work:

https://chromium-review.googlesource.com/c/catapult/+/833151/3/telemetry/telemetry/internal/actions/action_runner.py

Comment 3 by benhenry@google.com, Jan 16 (6 days ago)

Components: Test>Telemetry

Comment 4 by benhenry@google.com, Jan 16 (6 days ago)

Components: -Speed>Telemetry

Sign in to add a comment