1# 2# Copyright (C) 2018 The Android Open Source Project 3# 4# Licensed under the Apache License, Version 2.0 (the "License"); 5# you may not use this file except in compliance with the License. 6# You may obtain a copy of the License at 7# 8# http://www.apache.org/licenses/LICENSE-2.0 9# 10# Unless required by applicable law or agreed to in writing, software 11# distributed under the License is distributed on an "AS IS" BASIS, 12# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13# See the License for the specific language governing permissions and 14# limitations under the License. 15 16import logging 17import time 18import re 19 20 21# Log prefix to be parsed by performance analysis tools 22LOGGING_PREFIX = '[Instrumentation]' 23# Log line template in the format of <prefix> <type> @<category> #<name> 24# Do not use tab(\t) because sometime they can be printed to log as the string '\t' 25LOGGING_TEMPLATE = LOGGING_PREFIX + ' {category}: {name} {status}' 26# Characters not allowed in provided event category or name 27# In event init method, these characters are joint by '|' as regex. Modifications to 28# the replacing logic be required if escape character is needed. 29ILLEGAL_CHARS = ':\t\r\n' 30 31# A list of events that have began but not ended. 32event_stack = [] 33# A list of events that have finished 34# TODO(yuexima): use a new class to store data 35event_data = [] 36 37 38def NormalizeNameCategory(name, category): 39 """Replaces illegal characters in name and category. 40 41 Illegal characters defined in ILLEGAL_CHARS will be replaced with '_'. 42 43 Args: 44 name: string 45 category: string 46 47 Returns: 48 a tuple (string, string), name and category 49 """ 50 if set(ILLEGAL_CHARS) & set(category + name): 51 category = re.sub('|'.join(ILLEGAL_CHARS), '_', category) 52 name = re.sub('|'.join(ILLEGAL_CHARS), '_', name) 53 54 return name, category 55 56 57class TestFrameworkInstrumentationEvent(object): 58 """An object that represents an event. 59 60 Attributes: 61 category: string, a category mark represents a high level event 62 category such as preparer setup and test execution. 63 error: string, None if no error. Otherwise contains error messages such 64 as duplicated Begin or End. 65 name: string, a string to mark specific name of an event for human 66 reading. Final performance analysis will mostly focus on category 67 granularity instead of name granularity. 68 status: int, 0 for not started, 1 for started, 2 for ended, 3 for removed. 69 timestamp_begin_cpu: float, cpu time of event begin 70 timestamp_begin_wall: float, wall time of event begin 71 timestamp_end_cpu: float, cpu time of event end 72 Note: on some operating system (such as windows), the difference 73 between start and end cpu time may be measured using 74 wall time. 75 timestamp_end_wall: float, wall time of event end 76 _enable_logging: bool or None. Whether to put the event in logging. 77 Should be set to False when timing small pieces of code that could take 78 very short time to run. 79 This value should only be set once for log consistency. 80 If is None, global configuration will be used. 81 _disable_subevent_logging: bool, whether to disable logging for events created after this 82 event begins and before this event ends. This will overwrite 83 subevent's logging setting if set to True. 84 """ 85 category = None 86 name = None 87 status = 0 88 error = None 89 _enable_logging = False 90 _disable_subevent_logging = False 91 # TODO(yuexima): add on/off toggle param for logging. 92 93 timestamp_begin_cpu = -1 94 timestamp_begin_wall = -1 95 timestamp_end_cpu = -1 96 timestamp_end_wall = -1 97 98 def __init__(self, name, category): 99 self.name, self.category = NormalizeNameCategory(name, category) 100 101 if (name, category) != (self.name, self.category): 102 self.LogW('TestFrameworkInstrumentation: illegal character detected in ' 103 'category or name string. Provided name: %s, category: %s. ' 104 'Replacing them as "_"', name, category) 105 106 def Match(self, name, category): 107 """Checks whether the given category and name matches this event.""" 108 return category == self.category and name == self.name 109 110 def Begin(self, enable_logging=None, disable_subevent_logging=False): 111 """Performs logging action for the beginning of this event. 112 113 Args: 114 enable_logging: bool or None. Whether to put the event in logging. 115 Should be set to False when timing small pieces of code that could take 116 very short time to run. 117 If not specified or is None, global configuration will be used. 118 This value can only be set in Begin method to make logging consistent. 119 disable_subevent_logging: bool, whether to disable logging for events created after this 120 event begins and before this event ends. This will overwrite 121 subevent's logging setting if set to True. 122 """ 123 timestamp_begin_cpu = time.clock() 124 timestamp_begin_wall = time.time() 125 global event_stack 126 if event_stack and event_stack[-1]._disable_subevent_logging: 127 self._enable_logging = False 128 self._disable_subevent_logging = True 129 else: 130 if enable_logging is not None: 131 self._enable_logging = enable_logging 132 self._disable_subevent_logging = disable_subevent_logging 133 134 if self.status == 1: 135 self.LogE('TestFrameworkInstrumentation: event %s has already began. ' 136 'Skipping Begin.', self) 137 self.error = 'Tried to Begin but already began' 138 return 139 elif self.status == 2: 140 self.LogE('TestFrameworkInstrumentation: event %s has already ended. ' 141 'Skipping Begin.', self) 142 self.error = 'Tried to Begin but already ended' 143 return 144 elif self.status == 3: 145 self.LogE('TestFrameworkInstrumentation: event %s has already been removed. ' 146 'Skipping Begin.', self) 147 self.error = 'Tried to Begin but already been removed' 148 return 149 150 self.LogD(LOGGING_TEMPLATE.format(category=self.category, 151 name=self.name, 152 status='BEGIN')) 153 154 self.status = 1 155 self.timestamp_begin_cpu = timestamp_begin_cpu 156 self.timestamp_begin_wall = timestamp_begin_wall 157 event_stack.append(self) 158 159 def End(self): 160 """Performs logging action for the end of this event.""" 161 timestamp_end_cpu = time.clock() 162 timestamp_end_wall = time.time() 163 if self.status == 0: 164 self.LogE('TestFrameworkInstrumentation: event %s has not yet began. ' 165 'Skipping End.', self) 166 self.error = 'Tried to End but have not began' 167 return 168 elif self.status == 2: 169 self.LogE('TestFrameworkInstrumentation: event %s has already ended. ' 170 'Skipping End.', self) 171 self.error = 'Tried to End but already ended' 172 return 173 elif self.status == 3: 174 self.LogE('TestFrameworkInstrumentation: event %s has already been removed. ' 175 'Skipping End.', self) 176 self.error = 'Tried to End but already been removed' 177 return 178 179 self.LogD(LOGGING_TEMPLATE.format(category=self.category, 180 name=self.name, 181 status='END')) 182 183 self.status = 2 184 self.timestamp_end_cpu = timestamp_end_cpu 185 self.timestamp_end_wall = timestamp_end_wall 186 global event_data 187 event_data.append(self) 188 global event_stack 189 event_stack.remove(self) 190 191 def CheckEnded(self, remove_reason=''): 192 """Checks whether this event has ended and remove it if not. 193 194 This method is designed to be used in a try-catch exception block, where it is 195 not obvious whether the End() method has ever been called. In such case, if 196 End() has not been called, it usually means exception has happened and the event 197 should either be removed or automatically ended. Here we choose remove because 198 this method could be called in the finally block in a try-catch block, and there 199 could be a lot of noise before reaching the finally block. 200 201 This method does not support being called directly in test_framework_instrumentation 202 module with category and name lookup, because there can be events with same names. 203 204 Calling this method multiple times on the same Event object is ok. 205 206 Args: 207 remove_reason: string, reason to remove to be recorded when the event was 208 not properly ended. Default is empty string. 209 """ 210 if self.status < 2: 211 self.Remove(remove_reason) 212 213 def Remove(self, remove_reason=''): 214 """Removes this event from reports and record the reason. 215 216 Calling this method multiple times on the same Event object is ok. 217 218 Args: 219 remove_reason: string, reason to remove to be recorded when the event was 220 not properly ended. Default is empty string. 221 """ 222 if self.status == 3: 223 return 224 225 self.LogD(LOGGING_TEMPLATE.format(category=self.category, 226 name=self.name, 227 status='REMOVE') + 228 ' | Reason: %s' % remove_reason) 229 230 self.error = remove_reason 231 self.status = 3 232 global event_stack 233 event_stack.remove(self) 234 235 def LogD(self, *args): 236 """Wrapper function for logging.debug""" 237 self._Log(logging.debug, *args) 238 239 def LogI(self, *args): 240 """Wrapper function for logging.info""" 241 self._Log(logging.info, *args) 242 243 def LogW(self, *args): 244 """Wrapper function for logging.warn""" 245 self._Log(logging.warn, *args) 246 247 def LogE(self, *args): 248 """Wrapper function for logging.error""" 249 self._Log(logging.error, *args) 250 251 def _Log(self, log_func, *args): 252 if self._enable_logging != False: 253 log_func(*args) 254 255 def __str__(self): 256 return 'Event object: @%s #%s' % (self.category, self.name) + \ 257 '\n Begin timestamp(CPU): %s' % self.timestamp_begin_cpu + \ 258 '\n End timestamp(CPU): %s' % self.timestamp_end_cpu + \ 259 '\n Begin timestamp(wall): %s' % self.timestamp_begin_wall + \ 260 '\n End timestamp(wall): %s' % self.timestamp_end_wall + \ 261 '\n Status: %s' % self.status + \ 262 '\n Duration(CPU): %s' % (self.timestamp_end_cpu - self.timestamp_begin_cpu) + \ 263 '\n Duration(wall): %s' % (self.timestamp_end_wall - self.timestamp_begin_wall) 264