# Copyright 2016 The Chromium Authors. All rights reserved. # Use of this source code is governed by a BSD-style license that can be # found in the LICENSE file. """Gives a picture of the CPU activity between timestamps. When executed as a script, takes a loading trace, and prints the activity breakdown for the request dependencies. """ import collections import logging import operator import request_track class ActivityLens(object): """Reconstructs the activity of the main renderer thread between requests.""" _SCRIPT_EVENT_NAMES = ('EvaluateScript', 'FunctionCall') _PARSING_EVENT_NAMES = ('ParseHTML', 'ParseAuthorStyleSheet') def __init__(self, trace): """Initializes an instance of ActivityLens. Args: trace: (LoadingTrace) loading trace. """ self._trace = trace events = trace.tracing_track.GetEvents() self._renderer_main_pid_tid = self._GetRendererMainThreadId(events) self._tracing = self._trace.tracing_track.Filter( *self._renderer_main_pid_tid) @classmethod def _GetRendererMainThreadId(cls, events): """Returns the most active main renderer thread. Several renderers may be running concurrently, but we assume that only one of them is busy during the time covered by the loading trace.. It can be selected by looking at the number of trace events generated. Args: events: [tracing.Event] List of trace events. Returns: (PID (int), TID (int)) of the busiest renderer main thread. """ events_count_per_pid_tid = collections.defaultdict(int) main_renderer_thread_ids = set() for event in events: tracing_event = event.tracing_event pid = event.tracing_event['pid'] tid = event.tracing_event['tid'] events_count_per_pid_tid[(pid, tid)] += 1 if (tracing_event['cat'] == '__metadata' and tracing_event['name'] == 'thread_name' and event.args['name'] == 'CrRendererMain'): main_renderer_thread_ids.add((pid, tid)) pid_tid_events_counts = sorted(events_count_per_pid_tid.items(), key=operator.itemgetter(1), reverse=True) if (len(pid_tid_events_counts) > 1 and pid_tid_events_counts[0][1] < 2 * pid_tid_events_counts[1][1]): logging.warning( 'Several active renderers (%d and %d with %d and %d events).' % (pid_tid_events_counts[0][0][0], pid_tid_events_counts[1][0][0], pid_tid_events_counts[0][1], pid_tid_events_counts[1][1])) return pid_tid_events_counts[0][0] def _OverlappingMainRendererThreadEvents(self, start_msec, end_msec): return self._tracing.OverlappingEvents(start_msec, end_msec) @classmethod def _ClampedDuration(cls, event, start_msec, end_msec): return max(0, (min(end_msec, event.end_msec) - max(start_msec, event.start_msec))) @classmethod def _ThreadBusyness(cls, events, start_msec, end_msec): """Amount of time a thread spent executing from the message loop.""" busy_duration = 0 message_loop_events = [ e for e in events if (e.tracing_event['cat'] == 'toplevel' and e.tracing_event['name'] == 'MessageLoop::RunTask')] for event in message_loop_events: clamped_duration = cls._ClampedDuration(event, start_msec, end_msec) busy_duration += clamped_duration interval_msec = end_msec - start_msec assert busy_duration <= interval_msec return busy_duration @classmethod def _ScriptsExecuting(cls, events, start_msec, end_msec): """Returns the time during which scripts executed within an interval. Args: events: ([tracing.Event]) list of tracing events. start_msec: (float) start time in ms, inclusive. end_msec: (float) end time in ms, inclusive. Returns: A dict {URL (str) -> duration_msec (float)}. The dict may have a None key for scripts that aren't associated with a URL. """ script_to_duration = collections.defaultdict(float) script_events = [e for e in events if ('devtools.timeline' in e.tracing_event['cat'] and (e.tracing_event['name'] in cls._SCRIPT_EVENT_NAMES))] for event in script_events: clamped_duration = cls._ClampedDuration(event, start_msec, end_msec) script_url = event.args['data'].get('scriptName', None) script_to_duration[script_url] += clamped_duration return dict(script_to_duration) @classmethod def _FullyIncludedEvents(cls, events, event): """Return a list of events wholly included in the |event| span.""" (start, end) = (event.start_msec, event.end_msec) result = [] for event in events: if start <= event.start_msec < end and start <= event.end_msec < end: result.append(event) return result @classmethod def _Parsing(cls, events, start_msec, end_msec): """Returns the HTML/CSS parsing time within an interval. Args: events: ([tracing.Event]) list of events. start_msec: (float) start time in ms, inclusive. end_msec: (float) end time in ms, inclusive. Returns: A dict {URL (str) -> duration_msec (float)}. The dict may have a None key for tasks that aren't associated with a URL. """ url_to_duration = collections.defaultdict(float) parsing_events = [e for e in events if ('devtools.timeline' in e.tracing_event['cat'] and (e.tracing_event['name'] in cls._PARSING_EVENT_NAMES))] for event in parsing_events: # Parsing events can contain nested script execution events, avoid # double-counting by discounting these. nested_events = cls._FullyIncludedEvents(events, event) events_tree = _EventsTree(event, nested_events) js_events = events_tree.DominatingEventsWithNames(cls._SCRIPT_EVENT_NAMES) duration_to_subtract = sum( cls._ClampedDuration(e, start_msec, end_msec) for e in js_events) tracing_event = event.tracing_event clamped_duration = cls._ClampedDuration(event, start_msec, end_msec) if tracing_event['name'] == 'ParseAuthorStyleSheet': url = tracing_event['args']['data']['styleSheetUrl'] else: url = tracing_event['args']['beginData']['url'] parsing_duration = clamped_duration - duration_to_subtract assert parsing_duration >= 0 url_to_duration[url] += parsing_duration return dict(url_to_duration) def GenerateEdgeActivity(self, dep): """For a dependency between two requests, returns the renderer activity breakdown. Args: dep: (Request, Request, str) As returned from RequestDependencyLens.GetRequestDependencies(). Returns: {'edge_cost': (float) ms, 'busy': (float) ms, 'parsing': {'url' -> time_ms}, 'script' -> {'url' -> time_ms}} """ (first, second, reason) = dep (start_msec, end_msec) = request_track.IntervalBetween( first, second, reason) assert end_msec - start_msec >= 0. events = self._OverlappingMainRendererThreadEvents(start_msec, end_msec) result = {'edge_cost': end_msec - start_msec, 'busy': self._ThreadBusyness(events, start_msec, end_msec), 'parsing': self._Parsing(events, start_msec, end_msec), 'script': self._ScriptsExecuting(events, start_msec, end_msec)} return result def BreakdownEdgeActivityByInitiator(self, dep): """For a dependency between two requests, categorizes the renderer activity. Args: dep: (Request, Request, str) As returned from RequestDependencyLens.GetRequestDependencies(). Returns: {'script': float, 'parsing': float, 'other_url': float, 'unknown_url': float, 'unrelated_work': float} where the values are durations in ms: - idle: The renderer main thread was idle. - script: The initiating file was executing. - parsing: The initiating file was being parsed. - other_url: Other scripts and/or parsing activities. - unknown_url: Activity which is not associated with a URL. - unrelated_work: Activity unrelated to scripts or parsing. """ activity = self.GenerateEdgeActivity(dep) breakdown = {'unrelated_work': activity['busy'], 'idle': activity['edge_cost'] - activity['busy'], 'script': 0, 'parsing': 0, 'other_url': 0, 'unknown_url': 0} for kind in ('script', 'parsing'): for (script_name, duration_ms) in activity[kind].items(): if not script_name: breakdown['unknown_url'] += duration_ms elif script_name == dep[0].url: breakdown[kind] += duration_ms else: breakdown['other_url'] += duration_ms breakdown['unrelated_work'] -= sum( breakdown[x] for x in ('script', 'parsing', 'other_url', 'unknown_url')) return breakdown def MainRendererThreadBusyness(self, start_msec, end_msec): """Returns the amount of time the main renderer thread was busy. Args: start_msec: (float) Start of the interval. end_msec: (float) End of the interval. """ events = self._OverlappingMainRendererThreadEvents(start_msec, end_msec) return self._ThreadBusyness(events, start_msec, end_msec) class _EventsTree(object): """Builds the hierarchy of events from a list of fully nested events.""" def __init__(self, root_event, events): """Creates the tree. Args: root_event: (Event) Event held by the tree root. events: ([Event]) List of events that are fully included in |root_event|. """ self.event = root_event self.start_msec = root_event.start_msec self.end_msec = root_event.end_msec self.children = [] events.sort(key=operator.attrgetter('start_msec')) if not events: return current_child = (events[0], []) for event in events[1:]: if event.end_msec < current_child[0].end_msec: current_child[1].append(event) else: self.children.append(_EventsTree(current_child[0], current_child[1])) current_child = (event, []) self.children.append(_EventsTree(current_child[0], current_child[1])) def DominatingEventsWithNames(self, names): """Returns a list of the top-most events in the tree with a matching name. """ if self.event.name in names: return [self.event] else: result = [] for child in self.children: result += child.DominatingEventsWithNames(names) return result if __name__ == '__main__': import sys import json import loading_trace import request_dependencies_lens filename = sys.argv[1] json_dict = json.load(open(filename)) loading_trace = loading_trace.LoadingTrace.FromJsonDict(json_dict) activity_lens = ActivityLens(loading_trace) dependencies_lens = request_dependencies_lens.RequestDependencyLens( loading_trace) deps = dependencies_lens.GetRequestDependencies() for requests_dep in deps: print activity_lens.GenerateEdgeActivity(requests_dep)