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