1# Copyright 2013 The Chromium Authors. All rights reserved.
2# Use of this source code is governed by a BSD-style license that can be
3# found in the LICENSE file.
4
5import json
6import logging
7import socket
8import time
9import traceback
10
11from telemetry import decorators
12from telemetry.internal.backends.chrome_inspector import inspector_websocket
13from telemetry.internal.backends.chrome_inspector import websocket
14from tracing.trace_data import trace_data as trace_data_module
15
16
17class TracingUnsupportedException(Exception):
18  pass
19
20
21class TracingTimeoutException(Exception):
22  pass
23
24
25class TracingUnrecoverableException(Exception):
26  pass
27
28
29class TracingHasNotRunException(Exception):
30  pass
31
32
33class TracingUnexpectedResponseException(Exception):
34  pass
35
36
37class ClockSyncResponseException(Exception):
38  pass
39
40
41class _DevToolsStreamReader(object):
42  def __init__(self, inspector_socket, stream_handle):
43    self._inspector_websocket = inspector_socket
44    self._handle = stream_handle
45    self._trace_file_handle = None
46    self._callback = None
47
48  def Read(self, callback):
49    # Do not allow the instance of this class to be reused, as
50    # we only read data sequentially at the moment, so a stream
51    # can only be read once.
52    assert not self._callback
53    self._trace_file_handle = trace_data_module.TraceFileHandle()
54    self._trace_file_handle.Open()
55    self._callback = callback
56    self._ReadChunkFromStream()
57    # The below is not a typo -- queue one extra read ahead to avoid latency.
58    self._ReadChunkFromStream()
59
60  def _ReadChunkFromStream(self):
61    # Limit max block size to avoid fragmenting memory in sock.recv(),
62    # (see https://github.com/liris/websocket-client/issues/163 for details)
63    req = {'method': 'IO.read', 'params': {
64        'handle': self._handle, 'size': 32768}}
65    self._inspector_websocket.AsyncRequest(req, self._GotChunkFromStream)
66
67  def _GotChunkFromStream(self, response):
68    # Quietly discard responses from reads queued ahead after EOF.
69    if self._trace_file_handle is None:
70      return
71    if 'error' in response:
72      raise TracingUnrecoverableException(
73          'Reading trace failed: %s' % response['error']['message'])
74    result = response['result']
75    # Convert the trace data that's receive as UTF32 to its native encoding of
76    # UTF8 in order to reduce its size.
77    self._trace_file_handle.AppendTraceData(result['data'].encode('utf8'))
78    if not result.get('eof', False):
79      self._ReadChunkFromStream()
80      return
81    req = {'method': 'IO.close', 'params': {'handle': self._handle}}
82    self._inspector_websocket.SendAndIgnoreResponse(req)
83    self._trace_file_handle.Close()
84    self._callback(self._trace_file_handle)
85    self._trace_file_handle = None
86
87
88class TracingBackend(object):
89
90  _TRACING_DOMAIN = 'Tracing'
91
92  def __init__(self, inspector_socket, is_tracing_running=False,
93               support_modern_devtools_tracing_start_api=False):
94    self._inspector_websocket = inspector_socket
95    self._inspector_websocket.RegisterDomain(
96        self._TRACING_DOMAIN, self._NotificationHandler)
97    self._is_tracing_running = is_tracing_running
98    self._start_issued = False
99    self._can_collect_data = False
100    self._has_received_all_tracing_data = False
101    self._support_modern_devtools_tracing_start_api = (
102        support_modern_devtools_tracing_start_api)
103    self._trace_data_builder = None
104
105  @property
106  def is_tracing_running(self):
107    return self._is_tracing_running
108
109  def StartTracing(self, chrome_trace_config, timeout=10):
110    """When first called, starts tracing, and returns True.
111
112    If called during tracing, tracing is unchanged, and it returns False.
113    """
114    if self.is_tracing_running:
115      return False
116    assert not self._can_collect_data, 'Data not collected from last trace.'
117    # Reset collected tracing data from previous tracing calls.
118
119    if not self.IsTracingSupported():
120      raise TracingUnsupportedException(
121          'Chrome tracing not supported for this app.')
122
123    params = {'transferMode': 'ReturnAsStream'}
124    if self._support_modern_devtools_tracing_start_api:
125      params['traceConfig'] = (
126          chrome_trace_config.GetChromeTraceConfigForDevTools())
127    else:
128      if chrome_trace_config.requires_modern_devtools_tracing_start_api:
129        raise TracingUnsupportedException(
130            'Trace options require modern Tracing.start DevTools API, '
131            'which is NOT supported by the browser')
132      params['categories'], params['options'] = (
133          chrome_trace_config.GetChromeTraceCategoriesAndOptionsForDevTools())
134
135    req = {'method': 'Tracing.start', 'params': params}
136    logging.info('Start Tracing Request: %r', req)
137    response = self._inspector_websocket.SyncRequest(req, timeout)
138
139    if 'error' in response:
140      raise TracingUnexpectedResponseException(
141          'Inspector returned unexpected response for '
142          'Tracing.start:\n' + json.dumps(response, indent=2))
143
144    self._is_tracing_running = True
145    self._start_issued = True
146    return True
147
148  def RecordClockSyncMarker(self, sync_id):
149    assert self.is_tracing_running, 'Tracing must be running to clock sync.'
150    req = {
151      'method': 'Tracing.recordClockSyncMarker',
152      'params': {
153        'syncId': sync_id
154      }
155    }
156    rc = self._inspector_websocket.SyncRequest(req, timeout=2)
157    if 'error' in rc:
158      raise ClockSyncResponseException(rc['error']['message'])
159
160  def StopTracing(self):
161    """Stops tracing and pushes results to the supplied TraceDataBuilder.
162
163    If this is called after tracing has been stopped, trace data from the last
164    tracing run is pushed.
165    """
166    if not self.is_tracing_running:
167      raise TracingHasNotRunException()
168    else:
169      if not self._start_issued:
170        # Tracing is running but start was not issued so, startup tracing must
171        # be in effect. Issue another Tracing.start to update the transfer mode.
172        # TODO(caseq): get rid of it when streaming is the default.
173        params = {
174          'transferMode': 'ReturnAsStream',
175          'traceConfig': {}
176        }
177        req = {'method': 'Tracing.start', 'params': params}
178        self._inspector_websocket.SendAndIgnoreResponse(req)
179
180      req = {'method': 'Tracing.end'}
181      self._inspector_websocket.SendAndIgnoreResponse(req)
182
183    self._is_tracing_running = False
184    self._start_issued = False
185    self._can_collect_data = True
186
187  def DumpMemory(self, timeout=30):
188    """Dumps memory.
189
190    Returns:
191      GUID of the generated dump if successful, None otherwise.
192
193    Raises:
194      TracingTimeoutException: If more than |timeout| seconds has passed
195      since the last time any data is received.
196      TracingUnrecoverableException: If there is a websocket error.
197      TracingUnexpectedResponseException: If the response contains an error
198      or does not contain the expected result.
199    """
200    request = {
201      'method': 'Tracing.requestMemoryDump'
202    }
203    try:
204      response = self._inspector_websocket.SyncRequest(request, timeout)
205    except websocket.WebSocketTimeoutException:
206      raise TracingTimeoutException(
207          'Exception raised while sending a Tracing.requestMemoryDump '
208          'request:\n' + traceback.format_exc())
209    except (socket.error, websocket.WebSocketException,
210            inspector_websocket.WebSocketDisconnected):
211      raise TracingUnrecoverableException(
212          'Exception raised while sending a Tracing.requestMemoryDump '
213          'request:\n' + traceback.format_exc())
214
215
216    if ('error' in response or
217        'result' not in response or
218        'success' not in response['result'] or
219        'dumpGuid' not in response['result']):
220      raise TracingUnexpectedResponseException(
221          'Inspector returned unexpected response for '
222          'Tracing.requestMemoryDump:\n' + json.dumps(response, indent=2))
223
224    result = response['result']
225    return result['dumpGuid'] if result['success'] else None
226
227  def CollectTraceData(self, trace_data_builder, timeout=60):
228    if not self._can_collect_data:
229      raise Exception('Cannot collect before tracing is finished.')
230    self._CollectTracingData(trace_data_builder, timeout)
231    self._can_collect_data = False
232
233  def _CollectTracingData(self, trace_data_builder, timeout):
234    """Collects tracing data. Assumes that Tracing.end has already been sent.
235
236    Args:
237      trace_data_builder: An instance of TraceDataBuilder to put results into.
238      timeout: The timeout in seconds.
239
240    Raises:
241      TracingTimeoutException: If more than |timeout| seconds has passed
242      since the last time any data is received.
243      TracingUnrecoverableException: If there is a websocket error.
244    """
245    self._has_received_all_tracing_data = False
246    start_time = time.time()
247    self._trace_data_builder = trace_data_builder
248    try:
249      while True:
250        try:
251          self._inspector_websocket.DispatchNotifications(timeout)
252          start_time = time.time()
253        except websocket.WebSocketTimeoutException:
254          pass
255        except (socket.error, websocket.WebSocketException):
256          raise TracingUnrecoverableException(
257              'Exception raised while collecting tracing data:\n' +
258                  traceback.format_exc())
259
260        if self._has_received_all_tracing_data:
261          break
262
263        elapsed_time = time.time() - start_time
264        if elapsed_time > timeout:
265          raise TracingTimeoutException(
266              'Only received partial trace data due to timeout after %s '
267              'seconds. If the trace data is big, you may want to increase '
268              'the timeout amount.' % elapsed_time)
269    finally:
270      self._trace_data_builder = None
271
272  def _NotificationHandler(self, res):
273    if 'Tracing.dataCollected' == res.get('method'):
274      value = res.get('params', {}).get('value')
275      self._trace_data_builder.AddTraceFor(
276        trace_data_module.CHROME_TRACE_PART, value)
277    elif 'Tracing.tracingComplete' == res.get('method'):
278      stream_handle = res.get('params', {}).get('stream')
279      if not stream_handle:
280        self._has_received_all_tracing_data = True
281        return
282      reader = _DevToolsStreamReader(self._inspector_websocket, stream_handle)
283      reader.Read(self._ReceivedAllTraceDataFromStream)
284
285  def _ReceivedAllTraceDataFromStream(self, trace_handle):
286    self._trace_data_builder.AddTraceFor(
287        trace_data_module.CHROME_TRACE_PART, trace_handle)
288    self._has_received_all_tracing_data = True
289
290  def Close(self):
291    self._inspector_websocket.UnregisterDomain(self._TRACING_DOMAIN)
292    self._inspector_websocket = None
293
294  @decorators.Cache
295  def IsTracingSupported(self):
296    req = {'method': 'Tracing.hasCompleted'}
297    res = self._inspector_websocket.SyncRequest(req, timeout=10)
298    return not res.get('response')
299