1 #!/usr/bin/env python 2 # Copyright (C) 2015 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 """Record the event logs during boot and output them to a file. 16 17 This script repeats the record of each event log during Android boot specified 18 times. By default, interval between measurements is adjusted in such a way that 19 CPUs are cooled down sufficiently to avoid boot time slowdown caused by CPU 20 thermal throttling. The result is output in a tab-separated value format. 21 22 Examples: 23 24 Repeat measurements 10 times. Interval between iterations is adjusted based on 25 CPU temperature of the device. 26 27 $ ./perfboot.py --iterations=10 28 29 Repeat measurements 20 times. 60 seconds interval is taken between each 30 iteration. 31 32 $ ./perfboot.py --iterations=20 --interval=60 33 34 Repeat measurements 20 times, show verbose output, output the result to 35 data.tsv, and read event tags from eventtags.txt. 36 37 $ ./perfboot.py --iterations=30 -v --output=data.tsv --tags=eventtags.txt 38 """ 39 40 import argparse 41 import atexit 42 import cStringIO 43 import glob 44 import inspect 45 import logging 46 import math 47 import os 48 import re 49 import subprocess 50 import sys 51 import threading 52 import time 53 54 sys.path.append(os.path.dirname(os.path.dirname(__file__))) 55 import adb 56 57 # The default event tags to record. 58 _DEFAULT_EVENT_TAGS = [ 59 'boot_progress_start', 60 'boot_progress_preload_start', 61 'boot_progress_preload_end', 62 'boot_progress_system_run', 63 'boot_progress_pms_start', 64 'boot_progress_pms_system_scan_start', 65 'boot_progress_pms_data_scan_start', 66 'boot_progress_pms_scan_end', 67 'boot_progress_pms_ready', 68 'boot_progress_ams_ready', 69 'boot_progress_enable_screen', 70 'sf_stop_bootanim', 71 'wm_boot_animation_done', 72 ] 73 74 75 class IntervalAdjuster(object): 76 """A helper class to take suffficient interval between iterations.""" 77 78 # CPU temperature values per product used to decide interval 79 _CPU_COOL_DOWN_THRESHOLDS = { 80 'flo': 40, 81 'flounder': 40000, 82 'razor': 40, 83 'volantis': 40000, 84 } 85 # The interval between CPU temperature checks 86 _CPU_COOL_DOWN_WAIT_INTERVAL = 10 87 # The wait time used when the value of _CPU_COOL_DOWN_THRESHOLDS for 88 # the product is not defined. 89 _CPU_COOL_DOWN_WAIT_TIME_DEFAULT = 120 90 91 def __init__(self, interval, device): 92 self._interval = interval 93 self._device = device 94 self._temp_paths = device.shell( 95 ['ls', '/sys/class/thermal/thermal_zone*/temp'])[0].splitlines() 96 self._product = device.get_prop('ro.build.product') 97 self._waited = False 98 99 def wait(self): 100 """Waits certain amount of time for CPUs cool-down.""" 101 if self._interval is None: 102 self._wait_cpu_cool_down(self._product, self._temp_paths) 103 else: 104 if self._waited: 105 print 'Waiting for %d seconds' % self._interval 106 time.sleep(self._interval) 107 self._waited = True 108 109 def _get_cpu_temp(self, threshold): 110 max_temp = 0 111 for temp_path in self._temp_paths: 112 temp = int(self._device.shell(['cat', temp_path])[0].rstrip()) 113 max_temp = max(max_temp, temp) 114 if temp >= threshold: 115 return temp 116 return max_temp 117 118 def _wait_cpu_cool_down(self, product, temp_paths): 119 threshold = IntervalAdjuster._CPU_COOL_DOWN_THRESHOLDS.get( 120 self._product) 121 if threshold is None: 122 print 'No CPU temperature threshold is set for ' + self._product 123 print ('Just wait %d seconds' % 124 IntervalAdjuster._CPU_COOL_DOWN_WAIT_TIME_DEFAULT) 125 time.sleep(IntervalAdjuster._CPU_COOL_DOWN_WAIT_TIME_DEFAULT) 126 return 127 while True: 128 temp = self._get_cpu_temp(threshold) 129 if temp < threshold: 130 logging.info('Current CPU temperature %s' % temp) 131 return 132 print 'Waiting until CPU temperature (%d) falls below %d' % ( 133 temp, threshold) 134 time.sleep(IntervalAdjuster._CPU_COOL_DOWN_WAIT_INTERVAL) 135 136 137 class WatchdogTimer(object): 138 """A timer that makes is_timedout() return true in |timeout| seconds.""" 139 def __init__(self, timeout): 140 self._timedout = False 141 142 def notify_timeout(): 143 self._timedout = True 144 self._timer = threading.Timer(timeout, notify_timeout) 145 self._timer.daemon = True 146 self._timer.start() 147 148 def is_timedout(self): 149 return self._timedout 150 151 def cancel(self): 152 self._timer.cancel() 153 154 155 def readlines_unbuffered(proc): 156 """Read lines from |proc|'s standard out without buffering.""" 157 while True: 158 buf = [] 159 c = proc.stdout.read(1) 160 if c == '' and proc.poll() is not None: 161 break 162 while c != '\n': 163 if c == '' and proc.poll() is not None: 164 break 165 buf.append(c) 166 c = proc.stdout.read(1) 167 yield ''.join(buf) 168 169 170 def disable_dropbox(device): 171 """Removes the files created by Dropbox and avoids creating the files.""" 172 device.root() 173 device.wait() 174 device.shell(['rm', '-rf', '/system/data/dropbox']) 175 original_dropbox_max_files = device.shell( 176 ['settings', 'get', 'global', 'dropbox_max_files'])[0].rstrip() 177 device.shell(['settings', 'put', 'global', 'dropbox_max_files', '0']) 178 return original_dropbox_max_files 179 180 181 def restore_dropbox(device, original_dropbox_max_files): 182 """Restores the dropbox_max_files setting.""" 183 device.root() 184 device.wait() 185 if original_dropbox_max_files == 'null': 186 device.shell(['settings', 'delete', 'global', 'dropbox_max_files']) 187 else: 188 device.shell(['settings', 'put', 'global', 'dropbox_max_files', 189 original_dropbox_max_files]) 190 191 192 def init_perf(device, output, record_list, tags): 193 device.wait() 194 debuggable = device.get_prop('ro.debuggable') 195 original_dropbox_max_files = None 196 if debuggable == '1': 197 # Workaround for Dropbox issue (http://b/20890386). 198 original_dropbox_max_files = disable_dropbox(device) 199 200 def cleanup(): 201 try: 202 if record_list: 203 print_summary(record_list, tags[-1]) 204 output_results(output, record_list, tags) 205 if original_dropbox_max_files is not None: 206 restore_dropbox(device, original_dropbox_max_files) 207 except (subprocess.CalledProcessError, RuntimeError): 208 pass 209 atexit.register(cleanup) 210 211 212 def check_dm_verity_settings(device): 213 device.wait() 214 for partition in ['system', 'vendor']: 215 verity_mode = device.get_prop('partition.%s.verified' % partition) 216 if verity_mode is None: 217 logging.warning('dm-verity is not enabled for /%s. Did you run ' 218 'adb disable-verity? That may skew the result.', 219 partition) 220 221 222 def read_event_tags(tags_file): 223 """Reads event tags from |tags_file|.""" 224 if not tags_file: 225 return _DEFAULT_EVENT_TAGS 226 tags = [] 227 with open(tags_file) as f: 228 for line in f: 229 if '#' in line: 230 line = line[:line.find('#')] 231 line = line.strip() 232 if line: 233 tags.append(line) 234 return tags 235 236 237 def make_event_tags_re(tags): 238 """Makes a regular expression object that matches event logs of |tags|.""" 239 return re.compile(r'(?P<pid>[0-9]+) +[0-9]+ I (?P<tag>%s): (?P<time>\d+)' % 240 '|'.join(tags)) 241 242 243 def filter_event_tags(tags, device): 244 """Drop unknown tags not listed in device's event-log-tags file.""" 245 device.wait() 246 supported_tags = set() 247 for l in device.shell( 248 ['cat', '/system/etc/event-log-tags'])[0].splitlines(): 249 tokens = l.split(' ') 250 if len(tokens) >= 2: 251 supported_tags.add(tokens[1]) 252 filtered = [] 253 for tag in tags: 254 if tag in supported_tags: 255 filtered.append(tag) 256 else: 257 logging.warning('Unknown tag \'%s\'. Ignoring...', tag) 258 return filtered 259 260 261 def get_values(record, tag): 262 """Gets values that matches |tag| from |record|.""" 263 keys = [key for key in record.keys() if key[0] == tag] 264 return [record[k] for k in sorted(keys)] 265 266 267 def get_last_value(record, tag): 268 """Gets the last value that matches |tag| from |record|.""" 269 values = get_values(record, tag) 270 if not values: 271 return 0 272 return values[-1] 273 274 275 def output_results(filename, record_list, tags): 276 """Outputs |record_list| into |filename| in a TSV format.""" 277 # First, count the number of the values of each tag. 278 # This is for dealing with events that occur multiple times. 279 # For instance, boot_progress_preload_start and boot_progress_preload_end 280 # are recorded twice on 64-bit system. One is for 64-bit zygote process 281 # and the other is for 32-bit zygote process. 282 values_counter = {} 283 for record in record_list: 284 for tag in tags: 285 # Some record might lack values for some tags due to unanticipated 286 # problems (e.g. timeout), so take the maximum count among all the 287 # record. 288 values_counter[tag] = max(values_counter.get(tag, 1), 289 len(get_values(record, tag))) 290 291 # Then creates labels for the data. If there are multiple values for one 292 # tag, labels for these values are numbered except the first one as 293 # follows: 294 # 295 # event_tag event_tag2 event_tag3 296 # 297 # The corresponding values are sorted in an ascending order of PID. 298 labels = [] 299 for tag in tags: 300 for i in range(1, values_counter[tag] + 1): 301 labels.append('%s%s' % (tag, '' if i == 1 else str(i))) 302 303 # Finally write the data into the file. 304 with open(filename, 'w') as f: 305 f.write('\t'.join(labels) + '\n') 306 for record in record_list: 307 line = cStringIO.StringIO() 308 invalid_line = False 309 for i, tag in enumerate(tags): 310 if i != 0: 311 line.write('\t') 312 values = get_values(record, tag) 313 if len(values) < values_counter[tag]: 314 invalid_line = True 315 # Fill invalid record with 0 316 values += [0] * (values_counter[tag] - len(values)) 317 line.write('\t'.join(str(t) for t in values)) 318 if invalid_line: 319 logging.error('Invalid record found: ' + line.getvalue()) 320 line.write('\n') 321 f.write(line.getvalue()) 322 print 'Wrote: ' + filename 323 324 325 def median(data): 326 """Calculates the median value from |data|.""" 327 data = sorted(data) 328 n = len(data) 329 if n % 2 == 1: 330 return data[n / 2] 331 else: 332 n2 = n / 2 333 return (data[n2 - 1] + data[n2]) / 2.0 334 335 336 def mean(data): 337 """Calculates the mean value from |data|.""" 338 return float(sum(data)) / len(data) 339 340 341 def stddev(data): 342 """Calculates the standard deviation value from |value|.""" 343 m = mean(data) 344 return math.sqrt(sum((x - m) ** 2 for x in data) / len(data)) 345 346 347 def print_summary(record_list, end_tag): 348 """Prints the summary of |record_list|.""" 349 # Filter out invalid data. 350 end_times = [get_last_value(record, end_tag) for record in record_list 351 if get_last_value(record, end_tag) != 0] 352 print 'mean: ', mean(end_times) 353 print 'median:', median(end_times) 354 print 'standard deviation:', stddev(end_times) 355 356 357 def do_iteration(device, interval_adjuster, event_tags_re, end_tag): 358 """Measures the boot time once.""" 359 device.wait() 360 interval_adjuster.wait() 361 device.reboot() 362 print 'Rebooted the device' 363 record = {} 364 booted = False 365 while not booted: 366 device.wait() 367 # Stop the iteration if it does not finish within 120 seconds. 368 timeout = 120 369 t = WatchdogTimer(timeout) 370 p = subprocess.Popen( 371 ['adb', 'logcat', '-b', 'events', '-v', 'threadtime'], 372 stdout=subprocess.PIPE) 373 for line in readlines_unbuffered(p): 374 if t.is_timedout(): 375 print '*** Timed out ***' 376 return record 377 m = event_tags_re.search(line) 378 if not m: 379 continue 380 tag = m.group('tag') 381 event_time = int(m.group('time')) 382 pid = m.group('pid') 383 record[(tag, pid)] = event_time 384 print 'Event log recorded: %s (%s) - %d ms' % ( 385 tag, pid, event_time) 386 if tag == end_tag: 387 booted = True 388 t.cancel() 389 break 390 return record 391 392 393 def parse_args(): 394 """Parses the command line arguments.""" 395 parser = argparse.ArgumentParser( 396 description=inspect.getdoc(sys.modules[__name__]), 397 formatter_class=argparse.RawDescriptionHelpFormatter) 398 parser.add_argument('--iterations', type=int, default=5, 399 help='Number of times to repeat boot measurements.') 400 parser.add_argument('--interval', type=int, 401 help=('Duration between iterations. If this is not ' 402 'set explicitly, durations are determined ' 403 'adaptively based on CPUs temperature.')) 404 parser.add_argument('-o', '--output', help='File name of output data.') 405 parser.add_argument('-v', '--verbose', action='store_true', 406 help='Show verbose output.') 407 parser.add_argument('-s', '--serial', default=os.getenv('ANDROID_SERIAL'), 408 help='Adb device serial number.') 409 parser.add_argument('-t', '--tags', help='Specify the filename from which ' 410 'event tags are read. Every line contains one event ' 411 'tag and the last event tag is used to detect that ' 412 'the device has finished booting unless --end-tag is ' 413 'specified.') 414 parser.add_argument('--end-tag', help='An event tag on which the script ' 415 'stops measuring the boot time.') 416 parser.add_argument('--apk-dir', help='Specify the directory which contains ' 417 'APK files to be installed before measuring boot time.') 418 return parser.parse_args() 419 420 421 def install_apks(device, apk_dir): 422 for apk in glob.glob(os.path.join(apk_dir, '*.apk')): 423 print 'Installing: ' + apk 424 device.install(apk, replace=True) 425 426 427 def main(): 428 args = parse_args() 429 if args.verbose: 430 logging.getLogger().setLevel(logging.INFO) 431 432 device = adb.get_device(args.serial) 433 434 if not args.output: 435 device.wait() 436 args.output = 'perf-%s-%s.tsv' % ( 437 device.get_prop('ro.build.flavor'), 438 device.get_prop('ro.build.version.incremental')) 439 check_dm_verity_settings(device) 440 441 if args.apk_dir: 442 install_apks(device, args.apk_dir) 443 444 record_list = [] 445 event_tags = filter_event_tags(read_event_tags(args.tags), device) 446 end_tag = args.end_tag or event_tags[-1] 447 if end_tag not in event_tags: 448 sys.exit('%s is not a valid tag.' % end_tag) 449 event_tags = event_tags[0 : event_tags.index(end_tag) + 1] 450 init_perf(device, args.output, record_list, event_tags) 451 interval_adjuster = IntervalAdjuster(args.interval, device) 452 event_tags_re = make_event_tags_re(event_tags) 453 454 for i in range(args.iterations): 455 print 'Run #%d ' % i 456 record = do_iteration( 457 device, interval_adjuster, event_tags_re, end_tag) 458 record_list.append(record) 459 460 461 if __name__ == '__main__': 462 main() 463