1# Copyright 2014 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 re 6 7from telemetry import decorators 8import telemetry.timeline.bounds as timeline_bounds 9 10 11IS_SMOOTH = 'is_smooth' 12IS_RESPONSIVE = 'is_responsive' 13 14FLAGS = [ 15 IS_SMOOTH, 16 IS_RESPONSIVE 17] 18 19 20class ThreadTimeRangeOverlappedException(Exception): 21 """Exception that can be thrown when computing overlapped thread time range 22 with other events. 23 """ 24 25class NoThreadTimeDataException(ThreadTimeRangeOverlappedException): 26 """Exception that can be thrown if there is not sufficient thread time data 27 to compute the overlapped thread time range.""" 28 29def IsTimelineInteractionRecord(event_name): 30 return event_name.startswith('Interaction.') 31 32 33class TimelineInteractionRecord(object): 34 """Represents an interaction that took place during a timeline recording. 35 36 As a page runs, typically a number of different (simulated) user interactions 37 take place. For instance, a user might click a button in a mail app causing a 38 popup to animate in. Then they might press another button that sends data to a 39 server and simultaneously closes the popup without an animation. These are two 40 interactions. 41 42 From the point of view of the page, each interaction might have a different 43 logical name: ClickComposeButton and SendEmail, for instance. From the point 44 of view of the benchmarking harness, the names aren't so interesting as what 45 the performance expectations are for that interaction: was it loading 46 resources from the network? was there an animation? 47 48 Determining these things is hard to do, simply by observing the state given to 49 a page from javascript. There are hints, for instance if network requests are 50 sent, or if a CSS animation is pending. But this is by no means a complete 51 story. 52 53 Instead, we expect pages to mark up the timeline what they are doing, with 54 logical names, and flags indicating the semantics of that interaction. This 55 is currently done by pushing markers into the console.time/timeEnd API: this 56 for instance can be issued in JS: 57 58 var str = 'Interaction.SendEmail/is_smooth,is_responsive'; 59 console.time(str); 60 setTimeout(function() { 61 console.timeEnd(str); 62 }, 1000); 63 64 When run with perf.measurements.timeline_based_measurement running, this will 65 then cause a TimelineInteractionRecord to be created for this range and both 66 smoothness and network metrics to be reported for the marked up 1000ms 67 time-range. 68 69 """ 70 71 def __init__(self, logical_name, start, end, async_event=None): 72 assert logical_name 73 self.logical_name = logical_name 74 self.start = start 75 self.end = end 76 self.is_smooth = False 77 self.is_responsive = False 78 self._async_event = async_event 79 80 # TODO(nednguyen): After crbug.com/367175 is marked fixed, we should be able 81 # to get rid of perf.measurements.smooth_gesture_util and make this the only 82 # constructor method for TimelineInteractionRecord. 83 @staticmethod 84 def FromAsyncEvent(async_event): 85 """Construct an timeline_interaction_record from an async event. 86 Args: 87 async_event: An instance of 88 telemetry.timeline.async_slices.AsyncSlice 89 """ 90 assert async_event.start_thread == async_event.end_thread, ( 91 'Start thread of this record\'s async event is not the same as its ' 92 'end thread') 93 m = re.match('Interaction\.(.+)\/(.+)', async_event.name) 94 if m: 95 logical_name = m.group(1) 96 if m.group(1) != '': 97 flags = m.group(2).split(',') 98 else: 99 flags = [] 100 else: 101 m = re.match('Interaction\.(.+)', async_event.name) 102 assert m 103 logical_name = m.group(1) 104 flags = [] 105 106 record = TimelineInteractionRecord(logical_name, async_event.start, 107 async_event.end, async_event) 108 for f in flags: 109 if not f in FLAGS: 110 raise Exception( 111 'Unrecognized flag in timeline Interaction record: %s' % f) 112 record.is_smooth = IS_SMOOTH in flags 113 record.is_responsive = IS_RESPONSIVE in flags 114 return record 115 116 def GetResultNameFor(self, result_name): 117 return '%s-%s' % (self.logical_name, result_name) 118 119 @decorators.Cache 120 def GetBounds(self): 121 bounds = timeline_bounds.Bounds() 122 bounds.AddValue(self.start) 123 bounds.AddValue(self.end) 124 return bounds 125 126 @staticmethod 127 def GetJavaScriptMarker(logical_name, flags): 128 """ Get the marker string of an interaction record with logical_name 129 and flags. 130 """ 131 assert isinstance(flags, list) 132 for f in flags: 133 if f not in FLAGS: 134 raise AssertionError( 135 'Unrecognized flag for a timeline Interaction record: %s' % f) 136 return 'Interaction.%s/%s' % (logical_name, ','.join(flags)) 137 138 def GetOverlappedThreadTimeForSlice(self, timeline_slice): 139 """Get the thread duration of timeline_slice that overlaps with this record. 140 141 There are two cases : 142 143 Case 1: timeline_slice runs in the same thread as the record. 144 145 | [ timeline_slice ] 146 THREAD 1 | | | 147 | record starts record ends 148 149 (relative order in thread time) 150 151 As the thread timestamps in timeline_slice and record are consistent, we 152 simply use them to compute the overlap. 153 154 Case 2: timeline_slice runs in a different thread from the record's. 155 156 | 157 THREAD 2 | [ timeline_slice ] 158 | 159 160 | 161 THREAD 1 | | | 162 | record starts record ends 163 164 (relative order in wall-time) 165 166 Unlike case 1, thread timestamps of a thread are measured by its 167 thread-specific clock, which is inconsistent with that of the other 168 thread, and thus can't be used to compute the overlapped thread duration. 169 Hence, we use a heuristic to compute the overlap (see 170 _GetOverlappedThreadTimeForSliceInDifferentThread for more details) 171 172 Args: 173 timeline_slice: An instance of telemetry.timeline.slice.Slice 174 """ 175 if not self._async_event: 176 raise ThreadTimeRangeOverlappedException( 177 'This record was not constructed from async event') 178 if not self._async_event.has_thread_timestamps: 179 raise NoThreadTimeDataException( 180 'This record\'s async_event does not contain thread time data. ' 181 'Event data: %s' % repr(self._async_event)) 182 if not timeline_slice.has_thread_timestamps: 183 raise NoThreadTimeDataException( 184 'slice does not contain thread time data') 185 186 if timeline_slice.parent_thread == self._async_event.start_thread: 187 return self._GetOverlappedThreadTimeForSliceInSameThread( 188 timeline_slice) 189 else: 190 return self._GetOverlappedThreadTimeForSliceInDifferentThread( 191 timeline_slice) 192 193 def _GetOverlappedThreadTimeForSliceInSameThread(self, timeline_slice): 194 return timeline_bounds.Bounds.GetOverlap( 195 timeline_slice.thread_start, timeline_slice.thread_end, 196 self._async_event.thread_start, self._async_event.thread_end) 197 198 def _GetOverlappedThreadTimeForSliceInDifferentThread(self, timeline_slice): 199 # In case timeline_slice's parent thread is not the parent thread of the 200 # async slice that issues this record, we assume that events are descheduled 201 # uniformly. The overlap duration in thread time is then computed by 202 # multiplying the overlap wall-time duration of timeline_slice and the 203 # record's async slice with their thread_duration/duration ratios. 204 overlapped_walltime_duration = timeline_bounds.Bounds.GetOverlap( 205 timeline_slice.start, timeline_slice.end, 206 self.start, self.end) 207 if timeline_slice.duration == 0 or self._async_event.duration == 0: 208 return 0 209 timeline_slice_scheduled_ratio = ( 210 timeline_slice.thread_duration / float(timeline_slice.duration)) 211 record_scheduled_ratio = ( 212 self._async_event.thread_duration / float(self._async_event.duration)) 213 return (overlapped_walltime_duration * timeline_slice_scheduled_ratio * 214 record_scheduled_ratio) 215 216 def __repr__(self): 217 flags = [] 218 if self.is_smooth: 219 flags.append(IS_SMOOTH) 220 elif self.is_responsive: 221 flags.append(IS_RESPONSIVE) 222 flags_str = ','.join(flags) 223 224 return ('TimelineInteractionRecord(logical_name=\'%s\', start=%f, end=%f,' + 225 ' flags=%s, async_event=%s)') % ( 226 self.logical_name, 227 self.start, 228 self.end, 229 flags_str, 230 repr(self._async_event)) 231