Consistently timing out
eg, https://logs.chromium.org/v/?s=chrome%2Fbb%2Finternal.client.clank%2Fperf-go-phone-512%2F926%2F%2B%2Frecipes%2Fsteps%2Fsystem_health.memory_mobile%2F0%2Fstdout
[ RUN ] long_running:tools:gmail-background@{'case': 'long_running', 'group': 'tools'}
...
(INFO) 2018-03-06 22:50:42,553 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 shell '( /system/bin/screencap -p /data/local/tmp/temp_file-a86ac3c10083.png );echo %$?'
(INFO) 2018-03-06 22:50:44,437 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 pull /data/local/tmp/temp_file-a86ac3c10083.png /tmp/tmp_1mUPF.png
(INFO) 2018-03-06 22:50:44,602 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 shell 'rm -f /data/local/tmp/temp_file-a86ac3c10083.png'
(INFO) 2018-03-06 22:50:44,618 artifact_results.AddArtifact:41 Deleting unused artifact 'screenshot' of 'long_running:tools:gmail-background'
Traceback (most recent call last):
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/story_runner.py", line 125, in _RunStoryAndProcessErrorIfNeeded
test.Measure(state.platform, results)
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/web_perf/timeline_based_measurement.py", line 261, in Measure
trace_result, _ = platform.tracing_controller.StopTracing()
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/core/tracing_controller.py", line 53, in StopTracing
return self._tracing_controller_backend.StopTracing()
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/platform/tracing_controller_backend.py", line 161, in StopTracing
'\n'.join(raised_exception_messages))
TracingException: Exceptions raised when trying to stop tracing:
Traceback (most recent call last):
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/platform/tracing_controller_backend.py", line 139, in StopTracing
agent.StopAgentTracing()
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/platform/tracing_agent/chrome_tracing_agent.py", line 233, in StopAgentTracing
'\n'.join(raised_exception_messages))
ChromeTracingStoppedError: Exceptions raised when trying to stop Chrome devtool tracing:
Error when trying to stop Chrome tracing
on devtools at port localabstract:chrome_devtools_remote:
Traceback (most recent call last):
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/platform/tracing_agent/chrome_tracing_agent.py", line 215, in StopAgentTracing
client.StopChromeTracing()
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/devtools_client_backend.py", line 450, in StopChromeTracing
backend_id=backend.id)
File "/b/build/slave/perf-go-phone-512/build/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/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 252, in EvaluateJavaScript
return self._EvaluateJavaScript(expression, context_id, timeout)
File "/b/build/slave/perf-go-phone-512/build/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/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 41, in Inner
inspector_backend._ConvertExceptionFromInspectorWebsocket(e)
File "/b/build/slave/perf-go-phone-512/build/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/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 38, in Inner
return func(inspector_backend, *args, **kwargs)
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py", line 524, in _EvaluateJavaScript
self._runtime.Crash(context_id, timeout)
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_runtime.py", line 81, in Crash
res = self._inspector_websocket.SyncRequest(request, timeout)
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 116, in SyncRequest
res = self._Receive(timeout)
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 155, in _Receive
data = self._socket.recv()
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 293, in recv
opcode, data = self.recv_data()
File "/b/build/slave/perf-go-phone-512/build/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/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 323, in recv_data_frame
frame = self.recv_frame()
File "/b/build/slave/perf-go-phone-512/build/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/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py", line 336, in recv_frame
self.recv_header()
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py", line 286, in recv_header
header = self.recv_strict(2)
File "/b/build/slave/perf-go-phone-512/build/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/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 427, in _recv
return recv(self.sock, bufsize)
File "/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_socket.py", line 83, in recv
raise WebSocketTimeoutException(message)
TimeoutException:
********************************************************************************
(/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py:487 _ConvertExceptionFromInspectorWebsocket) The app is probably crashed:
Found Minidump: True
Stack Trace:
********************************************************************************
(/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py:492 _ConvertExceptionFromInspectorWebsocket) Original exception:
timed out
********************************************************************************
(/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py:513 _AddDebuggingInformation) Received a socket error in the browser connection and the tab still exists. The operation probably timed out.
********************************************************************************
(/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_backend.py:514 _AddDebuggingInformation) Debugger url: ws://127.0.0.1:58921/devtools/page/0
(INFO) 2018-03-06 22:50:44,619 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 shell '( ps -e | grep -F com.google.android.apps.chrome; echo "PIPESTATUS: ${PIPESTATUS[@]}" );echo %$?'
(INFO) 2018-03-06 22:50:44,883 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 shell '( ps -e | grep -F zygote; echo "PIPESTATUS: ${PIPESTATUS[@]}" );echo %$?'
(INFO) 2018-03-06 22:50:45,147 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 shell '( ps -e | grep -F com.google.android.apps.chrome; echo "PIPESTATUS: ${PIPESTATUS[@]}" );echo %$?'
(INFO) 2018-03-06 22:50:45,411 browser.Close:214 Closing browser (pid=22513) ...
(INFO) 2018-03-06 22:50:45,418 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 forward --remove tcp:58921
(INFO) 2018-03-06 22:50:45,426 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 shell '( ps -e | grep -F com.google.android.apps.chrome; echo "PIPESTATUS: ${PIPESTATUS[@]}" );echo %$?'
(INFO) 2018-03-06 22:50:45,691 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 shell '( am force-stop com.google.android.apps.chrome );echo %$?'
(INFO) 2018-03-06 22:50:46,090 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 shell '( ps -e | grep -F com.google.android.apps.chrome; echo "PIPESTATUS: ${PIPESTATUS[@]}" );echo %$?'
(INFO) 2018-03-06 22:50:46,491 browser.Close:228 Browser is closed.
(INFO) 2018-03-06 22:50:46,493 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/forwarder_host --adb=/b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb --serial-id=A6R9K17624900624 --unmap 57968
(INFO) 2018-03-06 22:50:46,525 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 shell '( ls /root );echo %$?'
(INFO) 2018-03-06 22:50:46,726 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 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) 2018-03-06 22:50:46,934 perf_control._ConditionallyWriteEachCpuFile:128 Successfully set cpufreq/scaling_governor to 'ondemand' on: cpu0 cpu1 cpu2 cpu3
(INFO) 2018-03-06 22:50:46,934 cmd_helper._ValidateAndLogCommand:160 [host]> /b/build/slave/perf-go-phone-512/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s A6R9K17624900624 shell '( cd /sys/devices/system/cpu && for CPU in cpu0 cpu1 cpu2 cpu3; do cat "$CPU/online"; echo -n "%~%$?%~%"; done );echo %$?'
[ FAILED ] long_running:tools:gmail-background@{'case': 'long_running', 'group': 'tools'} (320764 ms)
Comment 1 by perezju@chromium.org
, Mar 7 2018