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''' TraceEventImporter imports TraceEvent-formatted data 5into the provided model. 6This is a port of the trace event importer from 7https://code.google.com/p/trace-viewer/ 8''' 9 10import copy 11import json 12import re 13 14from telemetry.core.timeline import importer 15import telemetry.core.timeline.async_slice as tracing_async_slice 16 17class TraceEventTimelineImporter(importer.TimelineImporter): 18 def __init__(self, model, event_data): 19 super(TraceEventTimelineImporter, self).__init__( 20 model, event_data, import_priority=1) 21 22 self._events_were_from_string = False 23 self._all_async_events = [] 24 self._all_object_events = [] 25 26 if type(event_data) is str: 27 # If the event data begins with a [, then we know it should end with a ]. 28 # The reason we check for this is because some tracing implementations 29 # cannot guarantee that a ']' gets written to the trace file. So, we are 30 # forgiving and if this is obviously the case, we fix it up before 31 # throwing the string at JSON.parse. 32 if event_data[0] == '[': 33 event_data = re.sub(r'[\r|\n]*$', '', event_data) 34 event_data = re.sub(r'\s*,\s*$', '', event_data) 35 if event_data[-1] != ']': 36 event_data = event_data + ']' 37 38 self._events = json.loads(event_data) 39 self._events_were_from_string = True 40 else: 41 self._events = event_data 42 43 # Some trace_event implementations put the actual trace events 44 # inside a container. E.g { ... , traceEvents: [ ] } 45 # If we see that, just pull out the trace events. 46 if 'traceEvents' in self._events: 47 container = self._events 48 self._events = self._events['traceEvents'] 49 for field_name in container: 50 if field_name == 'traceEvents': 51 continue 52 53 # Any other fields in the container should be treated as metadata. 54 self._model.metadata.append({ 55 'name' : field_name, 56 'value' : container['field_name']}) 57 58 @staticmethod 59 def CanImport(event_data): 60 ''' Returns whether obj is a TraceEvent array. ''' 61 # May be encoded JSON. But we dont want to parse it fully yet. 62 # Use a simple heuristic: 63 # - event_data that starts with [ are probably trace_event 64 # - event_data that starts with { are probably trace_event 65 # May be encoded JSON. Treat files that start with { as importable by us. 66 if isinstance(event_data, str): 67 return len(event_data) > 0 and (event_data[0] == '{' 68 or event_data[0] == '[') 69 70 # Might just be an array of events 71 if (isinstance(event_data, list) and len(event_data) 72 and 'ph' in event_data[0]): 73 return True 74 75 # Might be an object with a traceEvents field in it. 76 if 'traceEvents' in event_data: 77 trace_events = event_data.get('traceEvents', None) 78 return (type(trace_events) is list and 79 len(trace_events) > 0 and 'ph' in trace_events[0]) 80 81 return False 82 83 def _GetOrCreateProcess(self, pid): 84 return self._model.GetOrCreateProcess(pid) 85 86 def _DeepCopyIfNeeded(self, obj): 87 if self._events_were_from_string: 88 return obj 89 return copy.deepcopy(obj) 90 91 def _ProcessAsyncEvent(self, event): 92 '''Helper to process an 'async finish' event, which will close an 93 open slice. 94 ''' 95 thread = (self._GetOrCreateProcess(event['pid']) 96 .GetOrCreateThread(event['tid'])) 97 self._all_async_events.append({ 98 'event': event, 99 'thread': thread}) 100 101 def _ProcessCounterEvent(self, event): 102 '''Helper that creates and adds samples to a Counter object based on 103 'C' phase events. 104 ''' 105 if 'id' in event: 106 ctr_name = event['name'] + '[' + str(event['id']) + ']' 107 else: 108 ctr_name = event['name'] 109 110 ctr = (self._GetOrCreateProcess(event['pid']) 111 .GetOrCreateCounter(event['cat'], ctr_name)) 112 # Initialize the counter's series fields if needed. 113 if len(ctr.series_names) == 0: 114 #TODO: implement counter object 115 for series_name in event['args']: 116 ctr.series_names.append(series_name) 117 if len(ctr.series_names) == 0: 118 self._model.import_errors.append('Expected counter ' + event['name'] + 119 ' to have at least one argument to use as a value.') 120 # Drop the counter. 121 del ctr.parent.counters[ctr.full_name] 122 return 123 124 # Add the sample values. 125 ctr.timestamps.append(event['ts'] / 1000.0) 126 for series_name in ctr.series_names: 127 if series_name not in event['args']: 128 ctr.samples.append(0) 129 continue 130 ctr.samples.append(event['args'][series_name]) 131 132 def _ProcessObjectEvent(self, event): 133 thread = (self._GetOrCreateProcess(event['pid']) 134 .GetOrCreateThread(event['tid'])) 135 self._all_object_events.append({ 136 'event': event, 137 'thread': thread}) 138 139 def _ProcessDurationEvent(self, event): 140 thread = (self._GetOrCreateProcess(event['pid']) 141 .GetOrCreateThread(event['tid'])) 142 if not thread.IsTimestampValidForBeginOrEnd(event['ts'] / 1000.0): 143 self._model.import_errors.append( 144 'Timestamps are moving backward.') 145 return 146 147 if event['ph'] == 'B': 148 thread.BeginSlice(event['cat'], 149 event['name'], 150 event['ts'] / 1000.0, 151 event['tts'] / 1000.0 if 'tts' in event else None, 152 event['args']) 153 elif event['ph'] == 'E': 154 thread = (self._GetOrCreateProcess(event['pid']) 155 .GetOrCreateThread(event['tid'])) 156 if not thread.IsTimestampValidForBeginOrEnd(event['ts'] / 1000.0): 157 self._model.import_errors.append( 158 'Timestamps are moving backward.') 159 return 160 if not thread.open_slice_count: 161 self._model.import_errors.append( 162 'E phase event without a matching B phase event.') 163 return 164 165 new_slice = thread.EndSlice( 166 event['ts'] / 1000.0, 167 event['tts'] / 1000.0 if 'tts' in event else None) 168 for arg_name, arg_value in event.get('args', {}).iteritems(): 169 if arg_name in new_slice.args: 170 self._model.import_errors.append( 171 'Both the B and E phases of ' + new_slice.name + 172 ' provided values for argument ' + arg_name + '. ' + 173 'The value of the E phase event will be used.') 174 new_slice.args[arg_name] = arg_value 175 176 def _ProcessCompleteEvent(self, event): 177 thread = (self._GetOrCreateProcess(event['pid']) 178 .GetOrCreateThread(event['tid'])) 179 thread.PushCompleteSlice( 180 event['cat'], 181 event['name'], 182 event['ts'] / 1000.0, 183 event['dur'] / 1000.0 if 'dur' in event else None, 184 event['tts'] / 1000.0 if 'tts' in event else None, 185 event['tdur'] / 1000.0 if 'tdur' in event else None, 186 event['args']) 187 188 def _ProcessMetadataEvent(self, event): 189 if event['name'] == 'thread_name': 190 thread = (self._GetOrCreateProcess(event['pid']) 191 .GetOrCreateThread(event['tid'])) 192 thread.name = event['args']['name'] 193 if event['name'] == 'process_name': 194 process = self._GetOrCreateProcess(event['pid']) 195 process.name = event['args']['name'] 196 else: 197 self._model.import_errors.append( 198 'Unrecognized metadata name: ' + event['name']) 199 200 def _ProcessInstantEvent(self, event): 201 # Treat an Instant event as a duration 0 slice. 202 # SliceTrack's redraw() knows how to handle this. 203 thread = (self._GetOrCreateProcess(event['pid']) 204 .GetOrCreateThread(event['tid'])) 205 thread.BeginSlice(event['cat'], 206 event['name'], 207 event['ts'] / 1000.0, 208 args=event.get('args')) 209 thread.EndSlice(event['ts'] / 1000.0) 210 211 def _ProcessSampleEvent(self, event): 212 thread = (self._GetOrCreateProcess(event['pid']) 213 .GetOrCreateThread(event['tid'])) 214 thread.AddSample(event['cat'], 215 event['name'], 216 event['ts'] / 1000.0, 217 event.get('args')) 218 219 def ImportEvents(self): 220 ''' Walks through the events_ list and outputs the structures discovered to 221 model_. 222 ''' 223 for event in self._events: 224 phase = event.get('ph', None) 225 if phase == 'B' or phase == 'E': 226 self._ProcessDurationEvent(event) 227 elif phase == 'X': 228 self._ProcessCompleteEvent(event) 229 elif phase == 'S' or phase == 'F' or phase == 'T': 230 self._ProcessAsyncEvent(event) 231 # Note, I is historic. The instant event marker got changed, but we 232 # want to support loading load trace files so we have both I and i. 233 elif phase == 'I' or phase == 'i': 234 self._ProcessInstantEvent(event) 235 elif phase == 'P': 236 self._ProcessSampleEvent(event) 237 elif phase == 'C': 238 self._ProcessCounterEvent(event) 239 elif phase == 'M': 240 self._ProcessMetadataEvent(event) 241 elif phase == 'N' or phase == 'D' or phase == 'O': 242 self._ProcessObjectEvent(event) 243 elif phase == 's' or phase == 't' or phase == 'f': 244 # NB: toss until there's proper support 245 pass 246 else: 247 self._model.import_errors.append('Unrecognized event phase: ' + 248 phase + '(' + event['name'] + ')') 249 250 return self._model 251 252 def FinalizeImport(self): 253 '''Called by the Model after all other importers have imported their 254 events.''' 255 self._model.UpdateBounds() 256 257 # We need to reupdate the bounds in case the minimum start time changes 258 self._model.UpdateBounds() 259 self._CreateAsyncSlices() 260 self._CreateExplicitObjects() 261 self._CreateImplicitObjects() 262 263 def _CreateAsyncSlices(self): 264 if len(self._all_async_events) == 0: 265 return 266 267 self._all_async_events.sort( 268 cmp=lambda x, y: int(x['event']['ts'] - y['event']['ts'])) 269 270 async_event_states_by_name_then_id = {} 271 272 all_async_events = self._all_async_events 273 for async_event_state in all_async_events: 274 event = async_event_state['event'] 275 name = event.get('name', None) 276 if name is None: 277 self._model.import_errors.append( 278 'Async events (ph: S, T or F) require an name parameter.') 279 continue 280 281 event_id = event.get('id') 282 if event_id is None: 283 self._model.import_errors.append( 284 'Async events (ph: S, T or F) require an id parameter.') 285 continue 286 287 # TODO(simonjam): Add a synchronous tick on the appropriate thread. 288 289 if event['ph'] == 'S': 290 if not name in async_event_states_by_name_then_id: 291 async_event_states_by_name_then_id[name] = {} 292 if event_id in async_event_states_by_name_then_id[name]: 293 self._model.import_errors.append( 294 'At %d, a slice of the same id %s was alrady open.' % ( 295 event['ts'], event_id)) 296 continue 297 298 async_event_states_by_name_then_id[name][event_id] = [] 299 async_event_states_by_name_then_id[name][event_id].append( 300 async_event_state) 301 else: 302 if name not in async_event_states_by_name_then_id: 303 self._model.import_errors.append( 304 'At %d, no slice named %s was open.' % (event['ts'], name,)) 305 continue 306 if event_id not in async_event_states_by_name_then_id[name]: 307 self._model.import_errors.append( 308 'At %d, no slice named %s with id=%s was open.' % ( 309 event['ts'], name, event_id)) 310 continue 311 events = async_event_states_by_name_then_id[name][event_id] 312 events.append(async_event_state) 313 314 if event['ph'] == 'F': 315 # Create a slice from start to end. 316 async_slice = tracing_async_slice.AsyncSlice( 317 events[0]['event']['cat'], 318 name, 319 events[0]['event']['ts'] / 1000.0) 320 321 async_slice.duration = ((event['ts'] / 1000.0) 322 - (events[0]['event']['ts'] / 1000.0)) 323 324 async_slice.start_thread = events[0]['thread'] 325 async_slice.end_thread = async_event_state['thread'] 326 async_slice.id = event_id 327 async_slice.args = events[0]['event']['args'] 328 329 # Create sub_slices for each step. 330 for j in xrange(1, len(events)): 331 sub_name = name 332 if events[j - 1]['event']['ph'] == 'T': 333 sub_name = name + ':' + events[j - 1]['event']['args']['step'] 334 sub_slice = tracing_async_slice.AsyncSlice( 335 events[0]['event']['cat'], 336 sub_name, 337 events[j - 1]['event']['ts'] / 1000.0) 338 sub_slice.parent_slice = async_slice 339 340 sub_slice.duration = ((events[j]['event']['ts'] / 1000.0) 341 - (events[j - 1]['event']['ts'] / 1000.0)) 342 343 sub_slice.start_thread = events[j - 1]['thread'] 344 sub_slice.end_thread = events[j]['thread'] 345 sub_slice.id = event_id 346 sub_slice.args = events[j - 1]['event']['args'] 347 348 async_slice.AddSubSlice(sub_slice) 349 350 # The args for the finish event go in the last sub_slice. 351 last_slice = async_slice.sub_slices[-1] 352 for arg_name, arg_value in event['args'].iteritems(): 353 last_slice.args[arg_name] = arg_value 354 355 # Add |async_slice| to the start-thread's async_slices. 356 async_slice.start_thread.AddAsyncSlice(async_slice) 357 del async_event_states_by_name_then_id[name][event_id] 358 359 def _CreateExplicitObjects(self): 360 # TODO(tengs): Implement object instance parsing 361 pass 362 363 def _CreateImplicitObjects(self): 364 # TODO(tengs): Implement object instance parsing 365 pass 366