New issue
Advanced search Search tips
Note: Color blocks (like █ or █) mean that a user may not be available. Tooltip shows the reason.

Issue 691626 link

Starred by 3 users
Status: Fixed
Owner: ----
Closed: Apr 2017
Cc:
charliea@chromium.org
nedngu...@google.com
█ rnep...@chromium.org
charliea@google.com
jbudorick@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 1
Type: Bug-Regression



Sign in to add a comment

smoothness.gpu_rasterization.top_25_smooth flaky on N6

Project Member Reported by sullivan@chromium.org, Feb 13 2017 
Failed 14 of the last 25 runs, with this stack. I'm not sure if this is a device issue? Randy, Ned, any clues for narrowing it down?

https://luci-logdog.appspot.com/v/?s=chrome%2Fbb%2Fchromium.perf%2FAndroid_Nexus6_Perf__2_%2F5049%2F%2B%2Frecipes%2Fsteps%2Fsmoothness.gpu_rasterization.top_25_smooth%2F0%2Fstdout

Traceback (most recent call last):
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py", line 94, in _RunStoryAndProcessErrorIfNeeded
    state.RunStory(results)
  File "/b/rr/tmp1xKGD7/w/src/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/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/page/shared_page_state.py", line 299, in RunStory
    self._current_page.Run(self)
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/page/__init__.py", line 108, in Run
    shared_state.page_test.RunNavigateSteps(self, current_tab)
  File "/b/rr/tmp1xKGD7/w/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 "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/page/legacy_page_test.py", line 195, in RunNavigateSteps
    page.RunNavigateSteps(action_runner)
  File "/b/rr/tmp1xKGD7/w/src/tools/perf/page_sets/top_25_smooth.py", line 63, in RunNavigateSteps
    timeout=120)
  File "/b/rr/tmp1xKGD7/w/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 "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/actions/action_runner.py", line 254, in WaitForJavaScriptCondition2
    return self._tab.WaitForJavaScriptCondition2(*args, **kwargs)
  File "/b/rr/tmp1xKGD7/w/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 "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 209, in WaitForJavaScriptCondition2
    return self._inspector_backend.WaitForJavaScriptCondition2(*args, **kwargs)
  File "/b/rr/tmp1xKGD7/w/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 "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 281, in WaitForJavaScriptCondition2
    return py_utils.WaitFor(IsJavaScriptExpressionTrue, timeout)
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/common/py_utils/py_utils/__init__.py", line 120, in WaitFor
    res = condition()
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 278, in IsJavaScriptExpressionTrue
    return self._runtime.Evaluate(condition, context_id, timeout)
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 45, in Evaluate
    res = self._inspector_websocket.SyncRequest(request, timeout)
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 110, in SyncRequest
    res = self._Receive(timeout)
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 149, in _Receive
    data = self._socket.recv()
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 293, in recv
    opcode, data = self.recv_data()
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 310, in recv_data
    opcode, frame = self.recv_data_frame(control_frame)
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 323, in recv_data_frame
    frame = self.recv_frame()
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 357, in recv_frame
    return self.frame_buffer.recv_frame()
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py", line 336, in recv_frame
    self.recv_header()
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py", line 286, in recv_header
    header = self.recv_strict(2)
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py", line 371, in recv_strict
    bytes_ = self.recv(min(16384, shortage))
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 427, in _recv
    return recv(self.sock, bufsize)
  File "/b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_socket.py", line 93, in recv
    "Connection is already closed.")
WebSocketConnectionClosedException: Connection is already closed.

INFO:root:Try printing formatted exception: None None None

Exception raised when cleaning story run: 

Traceback (most recent call last):
  _RunStoryAndProcessErrorIfNeeded at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py:119
    test.DidRunPage(state.platform)
  traced_function at /b/rr/tmp1xKGD7/w/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py:75
    return func(*args, **kwargs)
  DidRunPage at /b/rr/tmp1xKGD7/w/src/tools/perf/measurements/smoothness.py:65
    self._tbm.DidRunStory(platform)
  DidRunStory at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/web_perf/timeline_based_measurement.py:315
    platform.tracing_controller.StopTracing()
  StopTracing at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/core/tracing_controller.py:47
    return self._tracing_controller_backend.StopTracing()
  StopTracing at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/platform/tracing_controller_backend.py:105
    self._IssueClockSyncMarker()
  _IssueClockSyncMarker at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/platform/tracing_controller_backend.py:200
    self._RecordIssuerClockSyncMarker)
  RecordClockSyncMarker at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/platform/tracing_agent/chrome_tracing_agent.py:177
    raise ChromeClockSyncError('Cannot issue clock sync. No devtools clients')
ChromeClockSyncError: Cannot issue clock sync. No devtools clients

Locals:
  devtools_clients                             : []
  record_controller_clock_sync_marker_callback : <bound method TracingControllerBackend._RecordIssuerClockSyncMarker of <telemetry.internal.platform.tracing_controller_backend.TracingControllerBackend object at 0x7f75e5178fd0>>
  sync_id                                      : 'ab7b2690-ba33-4568-baea-242c70a27801'

[  FAILED  ] https://mail.google.com/mail/ (17318 ms)
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 shell '( ps | grep -F org.chromium.chrome; echo "PIPESTATUS: ${PIPESTATUS[@]}" );echo %$?'
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 shell '( ls /root );echo %$?'
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 shell '( cd /sys/devices/system/cpu && for CPU in cpu0 cpu1 cpu2 cpu3; do test -e "${CPU}/cpufreq/scaling_available_governors" && grep -q ondemand ${CPU}/cpufreq/scaling_available_governors && test -e "$CPU/cpufreq/scaling_governor" && echo ondemand > "$CPU/cpufreq/scaling_governor"; echo -n "%~%$?%~%"; done );echo %$?'
INFO:devil.android.perf.perf_control:Successfully set cpufreq/scaling_governor to 'ondemand' on: cpu0 cpu1 cpu2 cpu3
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 shell '( start mpdecision );echo %$?'
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 shell '( p=org.chromium.chrome;if [[ "$(ps)" = *$p* ]]; then am force-stop $p; fi );echo %$?'
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 shell '( dumpsys SurfaceFlinger --latency SurfaceView );echo %$?'
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 forward --remove tcp:33704
CRITICAL:root:(TimeoutThread-1-for-MainThread) Exception on _RunAdbCmd(<class 'devil.android.sdk.adb_wrapper.AdbWrapper'>, ['forward', '--remove', 'tcp:33704'], check_error=True, retries=2, device_serial=ZX1G22KFD7, timeout=30), attempt 1 of 3: AdbCommandFailedError('(device: ZX1G22KFD7) adb forward --remove tcp:33704: failed with exit status 1 and output:\n- error: listener not found\n- error: listener not found\n',)
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 forward --remove tcp:33704
CRITICAL:root:(TimeoutThread-2-for-MainThread) Exception on _RunAdbCmd(<class 'devil.android.sdk.adb_wrapper.AdbWrapper'>, ['forward', '--remove', 'tcp:33704'], check_error=True, retries=2, device_serial=ZX1G22KFD7, timeout=30), attempt 2 of 3: AdbCommandFailedError('(device: ZX1G22KFD7) adb forward --remove tcp:33704: failed with exit status 1 and output:\n- error: listener not found\n- error: listener not found\n',)
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 forward --remove tcp:33704
CRITICAL:root:Attempted to unforward port tcp:33704 but failed.
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 shell '( dumpsys SurfaceFlinger --latency SurfaceView );echo %$?'
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s ZX1G22KFD7 shell '( dumpsys SurfaceFlinger --latency SurfaceView );echo %$?'
INFO:devil.utils.cmd_helper:[host]> /b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/forwarder_host --adb=/b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb --serial-id=ZX1G22KFD7 --unmap 52881
ERROR:devil.android.forwarder:`/b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/forwarder_host --adb=/b/rr/tmp1xKGD7/w/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb --serial-id=ZX1G22KFD7 --unmap 52881` exited with 1:
[0212/144452:ERROR:host_forwarder_main.cc(477)] ERROR: could not unmap port.
ERROR: Existing controllers:


INFO:root:Try printing formatted exception: None None None

Traceback (most recent call last):
  RunBenchmark at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py:371
    benchmark.ShouldTearDownStateAfterEachStorySetRun())
  Run at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py:250
    _RunStoryAndProcessErrorIfNeeded(story, results, state, test)
  _RunStoryAndProcessErrorIfNeeded at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py:94
    state.RunStory(results)
  traced_function at /b/rr/tmp1xKGD7/w/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py:52
    return func(*args, **kwargs)
  RunStory at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/page/shared_page_state.py:299
    self._current_page.Run(self)
  Run at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/page/__init__.py:108
    shared_state.page_test.RunNavigateSteps(self, current_tab)
  traced_function at /b/rr/tmp1xKGD7/w/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py:75
    return func(*args, **kwargs)
  RunNavigateSteps at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/page/legacy_page_test.py:195
    page.RunNavigateSteps(action_runner)
  RunNavigateSteps at /b/rr/tmp1xKGD7/w/src/tools/perf/page_sets/top_25_smooth.py:63
    timeout=120)
  traced_function at /b/rr/tmp1xKGD7/w/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py:75
    return func(*args, **kwargs)
  WaitForJavaScriptCondition2 at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/actions/action_runner.py:254
    return self._tab.WaitForJavaScriptCondition2(*args, **kwargs)
  traced_function at /b/rr/tmp1xKGD7/w/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py:75
    return func(*args, **kwargs)
  WaitForJavaScriptCondition2 at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py:209
    return self._inspector_backend.WaitForJavaScriptCondition2(*args, **kwargs)
  traced_function at /b/rr/tmp1xKGD7/w/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py:75
    return func(*args, **kwargs)
  WaitForJavaScriptCondition2 at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py:281
    return py_utils.WaitFor(IsJavaScriptExpressionTrue, timeout)
  WaitFor at /b/rr/tmp1xKGD7/w/src/third_party/catapult/common/py_utils/py_utils/__init__.py:120
    res = condition()
  IsJavaScriptExpressionTrue at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py:278
    return self._runtime.Evaluate(condition, context_id, timeout)
  Evaluate at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py:45
    res = self._inspector_websocket.SyncRequest(request, timeout)
  SyncRequest at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py:110
    res = self._Receive(timeout)
  _Receive at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py:149
    data = self._socket.recv()
  recv at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py:293
    opcode, data = self.recv_data()
  recv_data at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py:310
    opcode, frame = self.recv_data_frame(control_frame)
  recv_data_frame at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py:323
    frame = self.recv_frame()
  recv_frame at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py:357
    return self.frame_buffer.recv_frame()
  recv_frame at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py:336
    self.recv_header()
  recv_header at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py:286
    header = self.recv_strict(2)
  recv_strict at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py:371
    bytes_ = self.recv(min(16384, shortage))
  _recv at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py:427
    return recv(self.sock, bufsize)
  recv at /b/rr/tmp1xKGD7/w/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_socket.py:93
    "Connection is already closed.")
WebSocketConnectionClosedException: Connection is already closed.

Comment 1 by nedngu...@google.com, Feb 13 2017

Owner: jbudorick@chromium.org
Seem like an issue with the host forwarder?

[0212/144452:ERROR:host_forwarder_main.cc(477)] ERROR: could not unmap port.
ERROR: Existing controllers:


John: can you take a look at this?

Comment 2 by rnep...@chromium.org, Feb 13 2017 

Looking at run: 
https://build.chromium.org/p/chromium.perf/builders/Android%20Nexus6%20Perf%20%282%29/builds/5050
https://storage.cloud.google.com/chromium-testrunner-trace/Android%20Nexus6%20Perf%20(2)/trace_5040.html

Tests that fail while running at the same time:
 smoothness.gpu_rasterization.top_25_smooth
 system_health.common_mobile.reference
 image_decoding.image_decoding_measurement.reference
 smoothness.pathological_mobile_sites.reference


Looking at run:
https://build.chromium.org/p/chromium.perf/builders/Android%20Nexus6%20Perf%20%282%29/builds/5040
https://storage.cloud.google.com/chromium-testrunner-trace/Android%20Nexus6%20Perf%20(2)/trace_5050.html

Tests that fail while running at the same time:
 thread_times.key_idle_power_cases
 smoothness.gpu_rasterization.top_25_smooth
 system_health.common_mobile.reference
 moothness.pathological_mobile_sites.referenc
 (A v8 test failed but wasn't running at the same time)



This may be related to  crbug.com/667470  which John was looking at forwarder logs for the other day and said something was wrong in them.

Comment 3 by rnep...@chromium.org, Feb 13 2017 

test trace links on above post are flipped.

Comment 4 by rnep...@chromium.org, Feb 13 2017

Cc: -nednguyen@chromium.org nedngu...@google.com

Comment 5 by rnep...@chromium.org, Mar 29 2017 

John has a fix for a forwarder bug incoming. That may help fix this issue.

Comment 6 by rnep...@chromium.org, Mar 31 2017 

It looks like this was disabled on android. Should we reenable it and check if it still  is broken after the forwarder fix?

Comment 7 by rnep...@chromium.org, Mar 31 2017

Cc: charliea@chromium.org
Actually, Charlie, didn't you recent discover that gpu rasterization is on by default on android? We could just scrap this benchmark if so, since it is then an exact duplicate of smoothness.top_25_smooth

Comment 8 by jbudorick@chromium.org, Mar 31 2017

Cc: jbudorick@chromium.org
Owner: ----
Status: Available (was: Untriaged)
Seems like I'm probably not the right person to own this any more.

Forwarder fix is https://bugs.chromium.org/p/chromium/issues/detail?id=691654, fwiw.

Comment 9 by rnep...@chromium.org, Mar 31 2017

Cc: charliea@google.com
 Issue 698025  has been merged into this issue.

Comment 10 by rnep...@chromium.org, Apr 3 2017

Status: Fixed (was: Available)
This problem hasn't occurred since the Johns fix landed. I'm going to close this issue out.

Discussion on gpu_rasterizaiton tests on android will continue on crbug.com/707400

Comment 11 by benhenry@google.com, Jan 16

Components: Test>Telemetry

Comment 12 by benhenry@google.com, Jan 16

Components: -Speed>Telemetry
►

Sign in to add a comment