New issue
Advanced search Search tips

Issue 863404 link

Starred by 1 user

Issue metadata

Status: Untriaged
Owner: ----
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 1
Type: Bug



Sign in to add a comment

Tracing Clock sync failure interrupt benchmark run, causing many tests to be unexpectedly skipped

Project Member Reported by nednguyen@chromium.org, Jul 13

Issue description

Log: 
https://chrome-swarming.appspot.com/task?id=3eac153733de3110&refresh=10&show_raw=1

Traceback (most recent call last):
  File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/platform/tracing_agent/chrome_tracing_agent.py", line 140, in _RecordClockSyncMarkerDevTools
    client.RecordChromeClockSyncMarker(sync_id)
  File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/devtools_client_backend.py", line 430, in RecordChromeClockSyncMarker
    self._tracing_backend.RecordClockSyncMarker(sync_id)
  File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/tracing_backend.py", line 159, in RecordClockSyncMarker
    raise ClockSyncResponseException(rc['error']['message'])
ClockSyncResponseException: Tracing is not started
(INFO) 2018-07-13 03:54:33,904 exception_formatter.PrintFormattedException:19  Try printing formatted exception: None None None

Exception raised when cleaning story run: 

Traceback (most recent call last):
  _RunStoryAndProcessErrorIfNeeded at /b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/story_runner.py:152
    test.DidRunStory(state.platform, results)
  DidRunStory at /b/s/w/ir/third_party/catapult/telemetry/telemetry/web_perf/timeline_based_measurement.py:289
    trace_result, _ = platform.tracing_controller.StopTracing()
  StopTracing at /b/s/w/ir/third_party/catapult/telemetry/telemetry/core/tracing_controller.py:53
    return self._tracing_controller_backend.StopTracing()
  StopTracing at /b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/platform/tracing_controller_backend.py:125
    self._IssueClockSyncMarker()
  _IssueClockSyncMarker at /b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/platform/tracing_controller_backend.py:229
    self._RecordIssuerClockSyncMarker)
  RecordClockSyncMarker at /b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/platform/tracing_agent/chrome_tracing_agent.py:189
    devtools_clients)
  _RecordClockSyncMarkerDevTools at /b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/platform/tracing_agent/chrome_tracing_agent.py:149
    'Failed to issue clock sync to devtools client')
ChromeClockSyncError: Failed to issue clock sync to devtools client

Locals:
  client                                       : <telemetry.internal.backends.chrome_inspector.devtools_client_backend.DevToolsClientBackend object at 0x10f780610>
  devtools_clients                             : [<telemetry.internal.backends.chrome_inspector.devtools_client_backend.DevToolsClientBackend object at 0x10f780610>]
  has_clock_synced                             : False
  record_controller_clock_sync_marker_callback : <bound method TracingControllerBackend._RecordIssuerClockSyncMarker of <telemetry.internal.platform.tracing_controller_backend.TracingControllerBackend object at 0x10f358190>>
  sync_id                                      : 'a263d91f-c491-4049-b619-24b9be9bb0cf'
  timestamp                                    : 29544792026.763

(INFO) 2018-07-13 03:54:33,907 browser.Close:207  Closing browser (pid=27641) ...
(INFO) 2018-07-13 03:54:33,910 chrome_tracing_agent.RecordClockSyncMarker:180  Chrome version: 3491
(ERROR) 2018-07-13 03:54:33,916 chrome_tracing_agent._RecordClockSyncMarkerDevTools:146  Failed to record clock sync marker with sync_id='f52c9f6e-1590-4af1-a368-7079911d2536' via DevTools client <telemetry.internal.backends.chrome_inspector.devtools_client_backend.DevToolsClientBackend object at 0x10f780610>:
Traceback (most recent call last):
  File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/platform/tracing_agent/chrome_tracing_agent.py", line 140, in _RecordClockSyncMarkerDevTools
    client.RecordChromeClockSyncMarker(sync_id)
  File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/devtools_client_backend.py", line 430, in RecordChromeClockSyncMarker
    self._tracing_backend.RecordClockSyncMarker(sync_id)
  File "/b/s/w/ir/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/tracing_backend.py", line 159, in RecordClockSyncMarker
    raise ClockSyncResponseException(rc['error']['message'])
ClockSyncResponseException: Tracing is not started
[  FAILED  ] loading.desktop/Vietnamnet_cold@{'cache_temperature': 'cold'} (83484 ms)


Based on the log, the clock sync failure eventually made Telemetry threw ClockSyncResponseException, which is an unrecoverable exception, making Telemetry skips the rest of tests in the benchmark. 

We should make Telemetry handle clock sync failure more gracefully.
 

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

Components: Test>Telemetry

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

Components: -Speed>Telemetry

Sign in to add a comment