1#!/usr/bin/python3
2
3# Copyright (C) 2016 The Android Open Source Project
4#
5# Licensed under the Apache License, Version 2.0 (the "License");
6# you may not use this file except in compliance with the License.
7# You may obtain a copy of the License at
8#
9#      http://www.apache.org/licenses/LICENSE-2.0
10#
11# Unless required by applicable law or agreed to in writing, software
12# distributed under the License is distributed on an "AS IS" BASIS,
13# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14# See the License for the specific language governing permissions and
15# limitations under the License.
16#
17"""Tool to analyze logcat and dmesg logs.
18
19bootanalyze read logcat and dmesg logs and determines key points for boot.
20"""
21
22import argparse
23import collections
24import datetime
25import math
26import operator
27import os
28import re
29import select
30import subprocess
31import time
32import threading
33import yaml
34
35from datetime import datetime
36
37TIME_DMESG = r"\[\s*(\d+\.\d+)\]"
38TIME_LOGCAT = r"[0-9]+\.?[0-9]*"
39KERNEL_TIME_KEY = "kernel"
40BOOT_ANIM_END_TIME_KEY = "BootAnimEnd"
41KERNEL_BOOT_COMPLETE = "BootComplete_kernel"
42LOGCAT_BOOT_COMPLETE = "BootComplete"
43CARWATCHDOG_BOOT_COMPLETE = "CarWatchdogBootupProfilingComplete"
44LAUNCHER_START = "LauncherStart"
45CARWATCHDOG_DUMP_COMMAND = "adb shell dumpsys android.automotive.watchdog.ICarWatchdog/default"
46BOOT_TIME_TOO_BIG = 200.0
47MAX_RETRIES = 5
48DEBUG = False
49DEBUG_PATTERN = False
50ADB_CMD = "adb"
51TIMING_THRESHOLD = 5.0
52BOOT_PROP = r"\[ro\.boottime\.([^\]]+)\]:\s+\[(\d+)\]"
53BOOTLOADER_TIME_PROP = r"\[ro\.boot\.boottime\]:\s+\[([^\]]+)\]"
54CARWATCHDOG_PARSER_CMD = 'perf_stats_parser'
55
56max_wait_time = BOOT_TIME_TOO_BIG
57
58def main():
59  global ADB_CMD
60
61  args = init_arguments()
62
63  if args.iterate < 1:
64    raise Exception('Number of iteration must be >=1')
65
66  if args.iterate > 1 and not args.reboot:
67    print("Forcing reboot flag")
68    args.reboot = True
69
70  if args.serial:
71    ADB_CMD = "%s %s" % ("adb -s", args.serial)
72
73  error_time = BOOT_TIME_TOO_BIG * 10
74  if args.errortime:
75    error_time = float(args.errortime)
76  if args.maxwaittime:
77    global max_wait_time
78    max_wait_time = float(args.maxwaittime)
79
80  components_to_monitor = {}
81  if args.componentmonitor:
82    items = args.componentmonitor.split(",")
83    for item in items:
84      kv = item.split("=")
85      key = kv[0]
86      value = float(kv[1])
87      components_to_monitor[key] = value
88
89  cfg = yaml.load(args.config, Loader=yaml.SafeLoader)
90
91  if args.stressfs:
92    if run_adb_cmd('install -r -g ' + args.stressfs) != 0:
93      raise Exception('StressFS APK not installed')
94
95  if args.iterate > 1 and args.bootchart:
96    run_adb_shell_cmd_as_root('touch /data/bootchart/enabled')
97
98  search_events_pattern = {key: re.compile(pattern)
99                   for key, pattern in cfg['events'].items()}
100  timing_events_pattern = {key: re.compile(pattern)
101                   for key, pattern in cfg['timings'].items()}
102  shutdown_events_pattern = {key: re.compile(pattern)
103                   for key, pattern in cfg['shutdown_events'].items()}
104  if DEBUG_PATTERN:
105    print("search event:{} timing event:{}".format(search_events_pattern, timing_events_pattern))
106
107  now = datetime.now().strftime("%Y-%m-%d-%H-%M-%S")
108  boot_chart_file_path_prefix = "bootchart-" + now
109  systrace_file_path_prefix = "systrace-" + now
110
111  if args.output:
112    boot_chart_file_path_prefix = args.output + '/' + boot_chart_file_path_prefix
113    systrace_file_path_prefix = args.output + '/' + systrace_file_path_prefix
114
115  data_points = {}
116  kernel_timing_points = collections.OrderedDict()
117  logcat_timing_points = collections.OrderedDict()
118  boottime_points = collections.OrderedDict()
119  shutdown_event_all = collections.OrderedDict()
120  shutdown_timing_event_all = collections.OrderedDict()
121  for it in range(0, args.iterate):
122    if args.iterate > 1:
123      print("Run: {0}".format(it))
124    attempt = 1
125    processing_data = None
126    timings = None
127    boottime_events = None
128    while attempt <= MAX_RETRIES and processing_data is None:
129      attempt += 1
130      processing_data, kernel_timings, logcat_timings, boottime_events, shutdown_events,\
131          shutdown_timing_events = iterate(\
132        args, search_events_pattern, timing_events_pattern, shutdown_events_pattern, cfg,\
133        error_time, components_to_monitor)
134    if shutdown_events:
135      for k, v in shutdown_events.items():
136        events = shutdown_event_all.get(k)
137        if not events:
138          events = []
139          shutdown_event_all[k] = events
140        events.append(v)
141    if shutdown_timing_events:
142      for k, v in shutdown_timing_events.items():
143        events = shutdown_timing_event_all.get(k)
144        if not events:
145          events = []
146          shutdown_timing_event_all[k] = events
147        events.append(v)
148    if not processing_data or not boottime_events:
149      # Processing error
150      print("Failed to collect valid samples for run {0}".format(it))
151      continue
152
153    if args.bootchart:
154      grab_bootchart(boot_chart_file_path_prefix + "_run_" + str(it))
155
156    if args.systrace:
157      grab_systrace(systrace_file_path_prefix + "_run_" + str(it))
158
159    if args.carwatchdog:
160      grab_carwatchdog_bootstats(args.output)
161
162    for k, v in processing_data.items():
163      if k not in data_points:
164        data_points[k] = []
165      data_points[k].append(v['value'])
166
167    if kernel_timings is not None:
168      for k, v in kernel_timings.items():
169        if k not in kernel_timing_points:
170          kernel_timing_points[k] = []
171        kernel_timing_points[k].append(v)
172    if logcat_timings is not None:
173      for k, v in logcat_timings.items():
174        if k not in logcat_timing_points:
175          logcat_timing_points[k] = []
176        logcat_timing_points[k].append(v)
177
178    for k, v in boottime_events.items():
179      if k not in boottime_points:
180        boottime_points[k] = []
181      boottime_points[k].append(v)
182
183  if args.stressfs:
184    run_adb_cmd('uninstall com.android.car.test.stressfs')
185    run_adb_shell_cmd('"rm -rf /storage/emulated/0/stressfs_data*"')
186
187  if args.iterate > 1:
188    print("-----------------")
189    print("\nshutdown events after {0} runs".format(args.iterate))
190    print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
191    for item in list(shutdown_event_all.items()):
192      num_runs = len(item[1])
193      print('{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format(
194          item[0], sum(item[1])/num_runs, stddev(item[1]),\
195          "*time taken" if item[0].startswith("init.") else "",\
196          num_runs if num_runs != args.iterate else ""))
197    print("\nshutdown timing events after {0} runs".format(args.iterate))
198    print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
199    for item in list(shutdown_timing_event_all.items()):
200      num_runs = len(item[1])
201      print('{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format(
202          item[0], sum(item[1])/num_runs, stddev(item[1]),\
203          "*time taken" if item[0].startswith("init.") else "",\
204          num_runs if num_runs != args.iterate else ""))
205
206    print("-----------------")
207    print("ro.boottime.* after {0} runs".format(args.iterate))
208    print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
209    for item in list(boottime_points.items()):
210        num_runs = len(item[1])
211        print('{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format(
212          item[0], sum(item[1])/num_runs, stddev(item[1]),\
213          "*time taken" if item[0].startswith("init.") else "",\
214          num_runs if num_runs != args.iterate else ""))
215
216    if args.timings:
217      dump_timings_points_summary("Kernel", kernel_timing_points, args)
218      dump_timings_points_summary("Logcat", logcat_timing_points, args)
219
220
221    print("-----------------")
222    print("Avg values after {0} runs".format(args.iterate))
223    print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
224
225    average_with_stddev = []
226    for item in list(data_points.items()):
227      average_with_stddev.append((item[0], sum(item[1])/len(item[1]), stddev(item[1]),\
228                                  len(item[1])))
229    for item in sorted(average_with_stddev, key=lambda entry: entry[1]):
230      print('{0:30}: {1:<7.5} {2:<7.5} {3}'.format(
231        item[0], item[1], item[2], item[3] if item[3] != args.iterate else ""))
232
233    run_adb_shell_cmd_as_root('rm /data/bootchart/enabled')
234
235
236def dump_timings_points_summary(msg_header, timing_points, args):
237      averaged_timing_points = []
238      for item in list(timing_points.items()):
239        average = sum(item[1])/len(item[1])
240        std_dev = stddev(item[1])
241        averaged_timing_points.append((item[0], average, std_dev, len(item[1])))
242
243      print("-----------------")
244      print(msg_header + " timing in order, Avg time values after {0} runs".format(args.iterate))
245      print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
246      for item in averaged_timing_points:
247        print('{0:30}: {1:<7.5} {2:<7.5} {3}'.format(
248          item[0], item[1], item[2], item[3] if item[3] != args.iterate else ""))
249
250      print("-----------------")
251      print(msg_header + " timing top items, Avg time values after {0} runs".format(args.iterate))
252      print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
253      for item in sorted(averaged_timing_points, key=lambda entry: entry[1], reverse=True):
254        if item[1] < TIMING_THRESHOLD:
255          break
256        print('{0:30}: {1:<7.5} {2:<7.5} {3}'.format(
257          item[0], item[1], item[2], item[3] if item[3] != args.iterate else ""))
258
259def capture_bugreport(bugreport_hint, boot_complete_time):
260    now = datetime.now()
261    bugreport_file = ("bugreport-%s-" + bugreport_hint + "-%s.zip") \
262        % (now.strftime("%Y-%m-%d-%H-%M-%S"), str(boot_complete_time))
263    print("Boot up time too big, will capture bugreport %s" % (bugreport_file))
264    os.system(ADB_CMD + " bugreport " + bugreport_file)
265
266def generate_timing_points(timing_events, timings):
267  timing_points = collections.OrderedDict()
268  monitor_contention_points = collections.OrderedDict()
269  for k, l in timing_events.items():
270      for v in l:
271        name, time_v = extract_timing(v, timings)
272        if name and time_v:
273          if v.find("SystemServerTimingAsync") > 0:
274            name = "(" + name + ")"
275          if k.endswith("_secs"):
276            time_v = time_v * 1000.0
277          if k.startswith("long_monitor_contention"):
278            monitor_contention_points[v] = time_v
279            continue
280          new_name = name
281          name_index = 0
282          while timing_points.get(new_name): # if the name is already taken, append #digit
283            name_index += 1
284            new_name = name + "#" + str(name_index)
285          timing_points[new_name] = time_v
286  return timing_points, monitor_contention_points
287
288def dump_timing_points(msg_header, timing_points):
289    print(msg_header + " event timing in time order, key: time")
290    for item in list(timing_points.items()):
291      print('{0:30}: {1:<7.5}'.format(item[0], item[1]))
292    print("-----------------")
293    print(msg_header + " event timing top items")
294    for item in sorted(list(timing_points.items()), key=operator.itemgetter(1), reverse=True):
295      if item[1] < TIMING_THRESHOLD:
296        break
297      print('{0:30}: {1:<7.5}'.format(
298        item[0], item[1]))
299    print("-----------------")
300
301def dump_monitor_contentions(logcat_monitor_contentions):
302  print("Monitor contentions over 100ms:")
303  for item in list(logcat_monitor_contentions.items()):
304      if item[1] > 100:
305        print('{0:<7.5}ms: {1}'.format(item[1], item[0]))
306  print("-----------------")
307
308def handle_reboot_log(capture_log_on_error, shutdown_events_pattern, components_to_monitor):
309  shutdown_events, shutdown_timing_events = collect_logcat_for_shutdown(capture_log_on_error,\
310		shutdown_events_pattern, components_to_monitor)
311  print("\nshutdown events: time")
312  for item in list(shutdown_events.items()):
313    print('{0:30}: {1:<7.5}'.format(item[0], item[1]))
314  print("\nshutdown timing events: time")
315  for item in list(shutdown_timing_events.items()):
316    print('{0:30}: {1:<7.5}'.format(item[0], item[1]))
317  return shutdown_events, shutdown_timing_events
318
319def collect_dmesg_events(search_events_pattern, timings_pattern, results):
320  dmesg_events, kernel_timing_events = collect_events(search_events_pattern, ADB_CMD +\
321                                                      ' shell su root dmesg -w', timings_pattern,\
322                                                      [KERNEL_BOOT_COMPLETE], True)
323  results.append(dmesg_events)
324  results.append(kernel_timing_events)
325
326def iterate(args, search_events_pattern, timings_pattern, shutdown_events_pattern, cfg, error_time,\
327    components_to_monitor):
328  shutdown_events = None
329  shutdown_timing_events = None
330  if args.reboot:
331    # sleep to make sure that logcat reader is reading before adb is gone by reboot. ugly but make
332    # impl simple.
333    t = threading.Thread(target=lambda: (time.sleep(2), reboot(args.serial, args.stressfs != '',\
334        args.permissive, args.adb_reboot, args.buffersize)))
335    t.start()
336    shutdown_events, shutdown_timing_events = handle_reboot_log(True, shutdown_events_pattern,\
337        components_to_monitor)
338    t.join()
339
340  results = []
341  t = threading.Thread(target=collect_dmesg_events, args=(search_events_pattern,\
342    timings_pattern, results))
343  t.start()
344
345  logcat_stop_events = [LOGCAT_BOOT_COMPLETE, LAUNCHER_START]
346  if args.fs_check:
347    logcat_stop_events.append("FsStat")
348  if args.carwatchdog:
349    logcat_stop_events.append(CARWATCHDOG_BOOT_COMPLETE)
350  logcat_events, logcat_timing_events = collect_events(
351    search_events_pattern, ADB_CMD + ' logcat -b all -v epoch', timings_pattern,\
352    logcat_stop_events, False)
353
354  t.join()
355  dmesg_events = results[0]
356  kernel_timing_events = results[1]
357
358  logcat_event_time = extract_time(logcat_events, TIME_LOGCAT, float)
359  logcat_original_time = extract_time(logcat_events, TIME_LOGCAT, str);
360  dmesg_event_time = extract_time(dmesg_events, TIME_DMESG, float);
361  boottime_events = fetch_boottime_property()
362  events = {}
363  events_to_correct = []
364  replaced_from_dmesg = set()
365
366  time_correction_delta = 0
367  time_correction_time = 0
368  if ('time_correction_key' in cfg
369      and cfg['time_correction_key'] in logcat_events):
370    match = search_events_pattern[cfg['time_correction_key']].search(
371      logcat_events[cfg['time_correction_key']])
372    if match and logcat_event_time[cfg['time_correction_key']]:
373      time_correction_delta = float(match.group(1))
374      time_correction_time = logcat_event_time[cfg['time_correction_key']]
375
376  debug("time_correction_delta = {0}, time_correction_time = {1}".format(
377    time_correction_delta, time_correction_time))
378
379  for k, v in logcat_event_time.items():
380    if v <= time_correction_time:
381      logcat_event_time[k] += time_correction_delta
382      v = v + time_correction_delta
383      debug("correcting event to event[{0}, {1}]".format(k, v))
384
385  diffs = []
386  if logcat_event_time.get(KERNEL_TIME_KEY) is None:
387    print("kernel time not captured in logcat")
388  else:
389    diffs.append((logcat_event_time[KERNEL_TIME_KEY], logcat_event_time[KERNEL_TIME_KEY]))
390
391  if logcat_event_time.get(BOOT_ANIM_END_TIME_KEY) and dmesg_event_time.get(BOOT_ANIM_END_TIME_KEY):
392      diffs.append((logcat_event_time[BOOT_ANIM_END_TIME_KEY],\
393                    logcat_event_time[BOOT_ANIM_END_TIME_KEY] -\
394                      dmesg_event_time[BOOT_ANIM_END_TIME_KEY]))
395  if not dmesg_event_time.get(KERNEL_BOOT_COMPLETE):
396      print("BootAnimEnd time or BootComplete-kernel not captured in both log" +\
397        ", cannot get time diff")
398      print("dmesg {} logcat {}".format(dmesg_event_time, logcat_event_time))
399      return None, None, None, None, None, None
400  diffs.append((logcat_event_time[LOGCAT_BOOT_COMPLETE],\
401                logcat_event_time[LOGCAT_BOOT_COMPLETE] - dmesg_event_time[KERNEL_BOOT_COMPLETE]))
402
403  for k, v in logcat_event_time.items():
404    debug("event[{0}, {1}]".format(k, v))
405    events[k] = v
406    if k in dmesg_event_time:
407      debug("{0} is in dmesg".format(k))
408      events[k] = dmesg_event_time[k]
409      replaced_from_dmesg.add(k)
410    else:
411      events_to_correct.append(k)
412
413  diff_prev = diffs[0]
414  for k in events_to_correct:
415    diff = diffs[0]
416    while diff[0] < events[k] and len(diffs) > 1:
417      diffs.pop(0)
418      diff_prev = diff
419      diff = diffs[0]
420    events[k] = events[k] - diff[1]
421    if events[k] < 0.0:
422        if events[k] < -0.1: # maybe previous one is better fit
423          events[k] = events[k] + diff[1] - diff_prev[1]
424        else:
425          events[k] = 0.0
426
427  data_points = collections.OrderedDict()
428
429  print("-----------------")
430  print("ro.boottime.*: time")
431  for item in list(boottime_events.items()):
432    print('{0:30}: {1:<7.5} {2}'.format(item[0], item[1],\
433      "*time taken" if item[0].startswith("init.") else ""))
434  print("-----------------")
435
436  if args.timings:
437    kernel_timing_points, _ = generate_timing_points(kernel_timing_events, timings_pattern)
438    logcat_timing_points, logcat_monitor_contentions =\
439      generate_timing_points(logcat_timing_events, timings_pattern)
440    dump_timing_points("Kernel", kernel_timing_points)
441    dump_timing_points("Logcat", logcat_timing_points)
442    dump_monitor_contentions(logcat_monitor_contentions)
443
444  for item in sorted(list(events.items()), key=operator.itemgetter(1)):
445    data_points[item[0]] = {
446      'value': item[1],
447      'from_dmesg': item[0] in replaced_from_dmesg,
448      'logcat_value': logcat_original_time[item[0]]
449    }
450  # add times with bootloader
451  if events.get("BootComplete") and boottime_events.get("bootloader"):
452    total = events["BootComplete"] + boottime_events["bootloader"]
453    data_points["*BootComplete+Bootloader"] = {
454      'value': total,
455      'from_dmesg': False,
456      'logcat_value': 0.0
457    }
458  if events.get("LauncherStart") and boottime_events.get("bootloader"):
459    total = events["LauncherStart"] + boottime_events["bootloader"]
460    data_points["*LauncherStart+Bootloader"] = {
461      'value': total,
462      'from_dmesg': False,
463      'logcat_value': 0.0
464    }
465  for k, v in data_points.items():
466    print('{0:30}: {1:<7.5} {2:1} ({3})'.format(
467      k, v['value'], '*' if v['from_dmesg'] else '', v['logcat_value']))
468
469  print('\n* - event time was obtained from dmesg log\n')
470
471  if events[LOGCAT_BOOT_COMPLETE] > error_time and not args.ignore:
472    capture_bugreport("bootuptoolong", events[LOGCAT_BOOT_COMPLETE])
473
474  for k, v in components_to_monitor.items():
475    logcat_value_measured = logcat_timing_points.get(k)
476    kernel_value_measured = kernel_timing_points.get(k)
477    data_from_data_points = data_points.get(k)
478    if logcat_value_measured and logcat_value_measured > v:
479      capture_bugreport(k + "-" + str(logcat_value_measured), events[LOGCAT_BOOT_COMPLETE])
480      break
481    elif kernel_value_measured and kernel_value_measured > v:
482      capture_bugreport(k + "-" + str(kernel_value_measured), events[LOGCAT_BOOT_COMPLETE])
483      break
484    elif data_from_data_points and data_from_data_points['value'] * 1000.0 > v:
485      capture_bugreport(k + "-" + str(data_from_data_points['value']), events[LOGCAT_BOOT_COMPLETE])
486      break
487
488  if args.fs_check:
489    fs_stat = None
490    if logcat_events.get("FsStat"):
491      fs_stat_pattern = cfg["events"]["FsStat"]
492      m = re.search(fs_stat_pattern, logcat_events.get("FsStat"))
493      if m:
494        fs_stat = m.group(1)
495    print('fs_stat:', fs_stat)
496
497    if fs_stat:
498      fs_stat_val = int(fs_stat, 0)
499      if (fs_stat_val & ~0x17) != 0:
500        capture_bugreport("fs_stat_" + fs_stat, events[LOGCAT_BOOT_COMPLETE])
501
502  return data_points, kernel_timing_points, logcat_timing_points, boottime_events, shutdown_events,\
503      shutdown_timing_events
504
505def debug(string):
506  if DEBUG:
507    print(string)
508
509def extract_timing(s, patterns):
510  for _, p in patterns.items():
511    m = p.search(s)
512    if m:
513      timing_dict = m.groupdict()
514      return timing_dict['name'], float(timing_dict['time'])
515  return None, None
516
517def init_arguments():
518  parser = argparse.ArgumentParser(description='Measures boot time.')
519  parser.add_argument('-r', '--reboot', dest='reboot',
520                      action='store_true',
521                      help='reboot device for measurement', )
522  parser.add_argument('-o', '--output', dest='output', type=str,
523                      help='Output directory where results are stored')
524  parser.add_argument('-c', '--config', dest='config',
525                      default='config.yaml', type=argparse.FileType('r'),
526                      help='config file for the tool', )
527  parser.add_argument('-s', '--stressfs', dest='stressfs',
528                      default='', type=str,
529                      help='APK file for the stressfs tool used to write to the data partition ' +\
530                           'during shutdown')
531  parser.add_argument('-n', '--iterate', dest='iterate', type=int, default=1,
532                      help='number of time to repeat the measurement', )
533  parser.add_argument('-g', '--ignore', dest='ignore', action='store_true',
534                      help='ignore too big values error', )
535  parser.add_argument('-t', '--timings', dest='timings', action='store_true',
536                      help='print individual component times', default=True, )
537  parser.add_argument('-p', '--serial', dest='serial', action='store',
538                      help='android device serial number')
539  parser.add_argument('-e', '--errortime', dest='errortime', action='store',
540                      help='handle bootup time bigger than this as error')
541  parser.add_argument('-w', '--maxwaittime', dest='maxwaittime', action='store',
542                      help='wait for up to this time to collect logs. Retry after this time.' +\
543                           ' Default is 200 sec.')
544  parser.add_argument('-f', '--fs_check', dest='fs_check',
545                      action='store_true',
546                      help='check fs_stat after reboot', )
547  parser.add_argument('-a', '--adb_reboot', dest='adb_reboot',
548                      action='store_true',
549                      help='reboot with adb reboot', )
550  parser.add_argument('-v', '--permissive', dest='permissive',
551                      action='store_true',
552                      help='set selinux into permissive before reboot', )
553  parser.add_argument('-m', '--componentmonitor', dest='componentmonitor', action='store',
554                      help='capture bugreport if specified timing component is taking more than ' +\
555                           'certain time. Unlike errortime, the result will not be rejected in' +\
556                           'averaging. Format is key1=time1,key2=time2...')
557  parser.add_argument('-b', '--bootchart', dest='bootchart',
558                      action='store_true',
559                      help='collect bootchart from the device.', )
560  parser.add_argument('-y', '--systrace', dest='systrace',
561                      action='store_true',
562                      help='collect systrace from the device. kernel trace should be already enabled', )
563  parser.add_argument('-W', '--carwatchdog', dest='carwatchdog', action='store_true',
564                      help='collect carwatchdog boot stats')
565  parser.add_argument('-G', '--buffersize', dest='buffersize', action='store', type=str,
566                      default=None,
567                      help='set logcat buffersize')
568  return parser.parse_args()
569
570def handle_zygote_event(zygote_pids, events, event, line):
571  words = line.split()
572  if len(words) > 1:
573    pid = int(words[1])
574    if len(zygote_pids) == 2:
575      if pid == zygote_pids[1]: # secondary
576        event = event + "-secondary"
577    elif len(zygote_pids) == 1:
578      if zygote_pids[0] != pid: # new pid, need to decide if old ones were secondary
579        primary_pid = min(pid, zygote_pids[0])
580        secondary_pid = max(pid, zygote_pids[0])
581        zygote_pids.pop()
582        zygote_pids.append(primary_pid)
583        zygote_pids.append(secondary_pid)
584        if pid == primary_pid: # old one was secondary:
585          move_to_secondary = []
586          for k, l in events.items():
587            if k.startswith("zygote"):
588              move_to_secondary.append((k, l))
589          for item in move_to_secondary:
590            del events[item[0]]
591            if item[0].endswith("-secondary"):
592              print("Secondary already exists for event %s  while found new pid %d, primary %d "\
593                % (item[0], secondary_pid, primary_pid))
594            else:
595              events[item[0] + "-secondary"] = item[1]
596        else:
597          event = event + "-secondary"
598    else:
599      zygote_pids.append(pid)
600  events[event] = line
601
602def update_name_if_already_exist(events, name):
603  existing_event = events.get(name)
604  i = 0
605  new_name = name
606  while existing_event:
607    i += 1
608    new_name = name + "_" + str(i)
609    existing_event = events.get(new_name)
610  return new_name
611
612def collect_logcat_for_shutdown(capture_log_on_error, shutdown_events_pattern,\
613    log_capture_conditions):
614  events = collections.OrderedDict()
615  # shutdown does not have timing_events but calculated from checking Xyz - XyzDone / XyzTimeout
616  timing_events = collections.OrderedDict()
617  process = subprocess.Popen(ADB_CMD + ' logcat -b all -v epoch', shell=True,
618                             stdout=subprocess.PIPE)
619  lines = []
620  capture_log = False
621  shutdown_start_time = 0
622  while True:
623    line = process.stdout.readline()
624    if not line:
625      break
626    line = line.decode('utf-8', 'ignore').lstrip().rstrip()
627    lines.append(line)
628    event = get_boot_event(line, shutdown_events_pattern)
629    if not event:
630      continue
631    time = extract_a_time(line, TIME_LOGCAT, float)
632    if time is None:
633      print("cannot get time from: " + line)
634      continue
635    if shutdown_start_time == 0:
636      shutdown_start_time = time
637    time = time - shutdown_start_time
638    events[event] = time
639    time_limit1 = log_capture_conditions.get(event)
640    if time_limit1 and time_limit1 <= time:
641      capture_log = True
642    pair_event = None
643    if event.endswith('Done'):
644      pair_event = event[:-4]
645    elif event.endswith('Timeout'):
646      pair_event = event[:-7]
647      if capture_log_on_error:
648        capture_log = True
649    if not pair_event:
650      continue
651    start_time = events.get(pair_event)
652    if not start_time:
653      print("No start event for " + event)
654      continue
655    time_spent = time - start_time
656    timing_event_name = pair_event + "Duration"
657    timing_events[timing_event_name] = time_spent
658    time_limit2 = log_capture_conditions.get(timing_event_name)
659    if time_limit2 and time_limit2 <= time_spent:
660      capture_log = True
661
662  if capture_log:
663    now = datetime.now()
664    log_file = ("shutdownlog-error-%s.txt") % (now.strftime("%Y-%m-%d-%H-%M-%S"))
665    print("Shutdown error, capture log to %s" % (log_file))
666    with open(log_file, 'w') as f:
667      f.write('\n'.join(lines))
668  return events, timing_events
669
670def log_timeout(time_left, stop_events, events, timing_events):
671  print("timeout waiting for event, continue", time_left)
672  print(" remaininig events {}, event {} timing events {}".\
673    format(stop_events, events, timing_events))
674
675def collect_events(search_events, command, timings, stop_events, disable_timing_after_zygote):
676  events = collections.OrderedDict()
677  timing_events = {}
678
679  data_available = stop_events is None
680  zygote_pids = []
681  start_time = time.time()
682  zygote_found = False
683  line = None
684  print("remaining stop_events:", stop_events)
685  init = True
686  while True:
687    if init:
688      process = subprocess.Popen(command, shell=True, stdout=subprocess.PIPE)
689      read_poll = select.poll()
690      read_poll.register(process.stdout, select.POLLIN)
691      init = False
692    if len(stop_events) == 0:
693      break
694    time_left = start_time + max_wait_time - time.time()
695    if time_left <= 0:
696      log_timeout(time_left, stop_events, events, timing_events)
697      break
698    polled_events = read_poll.poll(time_left * 1000.0)
699    # adb logcat subprocess is auto-terminated when the adb connection is lost.
700    # Thus, check for the subprocess return code and reconnect to the device if
701    # needed. Otherwise, the logcat events cannot be polled completely.
702    if process.poll() is not None:
703      print("adb might be disconnected?\nRetrying to connect.")
704      run_adb_cmd('wait-for-device')
705      print(" reconnected")
706      init = True
707      continue
708    if len(polled_events) == 0:
709      log_timeout(time_left, stop_events, events, timing_events)
710      break
711    for polled_event in polled_events:
712      if polled_event[1] == select.POLLIN:
713        line = process.stdout.readline().decode('utf-8', 'ignore')
714      else:
715        if polled_event[1] == select.POLLHUP:
716          if len(stop_events) == 0:
717            break;
718        # adb connection lost
719        print("poll error waiting for event, adb lost?")
720        if time_left > 0:
721          print("retry adb")
722          run_adb_cmd('wait-for-device')
723          print(" reconnected")
724          init = True
725          continue
726        else:
727          break
728      if not data_available:
729        print("Collecting data samples from '%s'. Please wait...\n" % command)
730        data_available = True
731      event = get_boot_event(line, search_events)
732      if event:
733        debug("event[{0}] captured: {1}".format(event, line))
734        if event == "starting_zygote":
735          events[event] = line
736          zygote_found = True
737        elif event.startswith("zygote"):
738          handle_zygote_event(zygote_pids, events, event, line)
739        else:
740          new_event = update_name_if_already_exist(events, event)
741          events[new_event] = line
742        if event in stop_events:
743          stop_events.remove(event)
744          print("remaining stop_events:", stop_events)
745
746      timing_event = get_boot_event(line, timings)
747      if timing_event and (not disable_timing_after_zygote or not zygote_found):
748        if timing_event not in timing_events:
749          timing_events[timing_event] = []
750        timing_events[timing_event].append(line)
751        debug("timing_event[{0}] captured: {1}".format(timing_event, line))
752
753  process.terminate()
754  return events, timing_events
755
756def fetch_boottime_property():
757  cmd = ADB_CMD + ' shell su root getprop'
758  events = {}
759  process = subprocess.Popen(cmd, shell=True, stdout=subprocess.PIPE)
760  out = process.stdout
761  pattern = re.compile(BOOT_PROP)
762  pattern_bootloader = re.compile(BOOTLOADER_TIME_PROP)
763  bootloader_time = 0.0
764  for line in out:
765    line = line.decode('utf-8', 'ignore')
766    match = pattern.match(line)
767    if match:
768      if match.group(1).startswith("init."):
769        events[match.group(1)] = float(match.group(2)) / 1000.0 #ms to s
770      else:
771        events[match.group(1)] = float(match.group(2)) / 1000000000.0 #ns to s
772    match = pattern_bootloader.match(line)
773    if match:
774      items = match.group(1).split(",")
775      for item in items:
776        entry_pair = item.split(":")
777        entry_name = entry_pair[0]
778        time_spent = float(entry_pair[1]) / 1000 #ms to s
779        if entry_name != "SW":
780          bootloader_time = bootloader_time + time_spent
781  ordered_event = collections.OrderedDict()
782  if bootloader_time != 0.0:
783    ordered_event["bootloader"] = bootloader_time
784  for item in sorted(list(events.items()), key=operator.itemgetter(1)):
785    ordered_event[item[0]] = item[1]
786  return ordered_event
787
788
789def get_boot_event(line, events):
790  for event_key, event_pattern in events.items():
791    if event_pattern.search(line):
792      return event_key
793  return None
794
795def extract_a_time(line, pattern, date_transform_function):
796    found = re.findall(pattern, line)
797    if len(found) > 0:
798      return date_transform_function(found[0])
799    else:
800      return None
801
802def extract_time(events, pattern, date_transform_function):
803  result = collections.OrderedDict()
804  for event, data in events.items():
805    time = extract_a_time(data, pattern, date_transform_function)
806    if time is not None:
807      result[event] = time
808    else:
809      print("Failed to find time for event: ", event, data)
810  return result
811
812
813def do_reboot(serial, use_adb_reboot):
814  # do not update time
815  run_adb_cmd('shell settings put global auto_time 0')
816  run_adb_cmd('shell settings put global auto_time_zone 0')
817  original_devices = subprocess.check_output("adb devices", shell=True).decode('utf-8', 'ignore')
818  if use_adb_reboot:
819    print('Rebooting the device using adb reboot')
820    run_adb_cmd('reboot')
821  else:
822    print('Rebooting the device using svc power reboot')
823    run_adb_shell_cmd_as_root('svc power reboot')
824  # Wait for the device to go away
825  retry = 0
826  while retry < 20:
827    current_devices = subprocess.check_output("adb devices", shell=True).decode('utf-8', 'ignore')
828    if original_devices != current_devices:
829      if not serial or (serial and current_devices.find(serial) < 0):
830        return True
831    time.sleep(1)
832    retry += 1
833  return False
834
835def reboot(serial, use_stressfs, permissive, use_adb_reboot, adb_buffersize=None):
836  if use_stressfs:
837    print('Starting write to data partition')
838    run_adb_shell_cmd('am start' +\
839                      ' -n com.android.car.test.stressfs/.WritingActivity' +\
840                      ' -a com.android.car.test.stressfs.START')
841    # Give this app some time to start.
842    time.sleep(1)
843  if permissive:
844    run_adb_shell_cmd_as_root('setenforce 0')
845
846  retry = 0
847  while retry < 5:
848    if do_reboot(serial, use_adb_reboot):
849      break
850    retry += 1
851
852  print('Waiting the device')
853  run_adb_cmd('wait-for-device')
854  print(' found a device')
855
856  if adb_buffersize is not None:
857    # increase the buffer size
858    if run_adb_cmd('logcat -G {}'.format(adb_buffersize)) != 0:
859      debug('Fail to set logcat buffer size as {}'.format(adb_buffersize))
860
861'''
862Runs adb command. If do_return_result is true then output of command is
863returned otherwise an empty string is returned.
864'''
865def run_adb_cmd(cmd, do_return_result=False):
866  if do_return_result:
867    return subprocess.check_output(ADB_CMD + ' ' + cmd, shell=True).decode('utf-8', 'ignore').strip()
868  subprocess.call(ADB_CMD + ' ' + cmd, shell=True)
869  return ""
870
871def run_adb_shell_cmd(cmd, do_return_result=False):
872  return run_adb_cmd('shell ' + cmd, do_return_result)
873
874def run_adb_shell_cmd_as_root(cmd, do_return_result=False):
875  return run_adb_shell_cmd('su root ' + cmd, do_return_result)
876
877def logcat_time_func(offset_year):
878  def f(date_str):
879    ndate = datetime.datetime.strptime(str(offset_year) + '-' +
880                                 date_str, '%Y-%m-%d %H:%M:%S.%f')
881    return datetime_to_unix_time(ndate)
882  return f
883
884def datetime_to_unix_time(ndate):
885  return time.mktime(ndate.timetuple()) + ndate.microsecond/1000000.0
886
887def stddev(data):
888  items_count = len(data)
889  avg = sum(data) / items_count
890  sq_diffs_sum = sum([(v - avg) ** 2 for v in data])
891  variance = sq_diffs_sum / items_count
892  return math.sqrt(variance)
893
894def grab_bootchart(boot_chart_file_path):
895  subprocess.run("$ANDROID_BUILD_TOP/system/core/init/grab-bootchart.sh", shell=True,
896                 stdout=subprocess.DEVNULL)
897  print("Saving boot chart as " + boot_chart_file_path + ".tgz")
898  subprocess.call('cp /tmp/android-bootchart/bootchart.tgz ' + boot_chart_file_path + '.tgz', \
899                  shell=True)
900  subprocess.call('cp ./bootchart.png ' + boot_chart_file_path + '.png', shell=True)
901
902def grab_systrace(systrace_file_path_prefix):
903  trace_file = systrace_file_path_prefix + "_trace.txt"
904  with open(trace_file, 'w') as f:
905    f.write("TRACE:\n")
906  run_adb_shell_cmd_as_root("cat /d/tracing/trace >> " + trace_file)
907  html_file = systrace_file_path_prefix + ".html"
908  subprocess.call("$ANDROID_BUILD_TOP/external/chromium-trace/systrace.py --from-file=" + trace_file + " -o " +\
909                  html_file, shell=True)
910
911def capture_build_info(out_dir, build_info_file_name):
912  fingerprint = run_adb_shell_cmd('getprop ro.build.fingerprint', True)
913  brand = run_adb_shell_cmd('getprop ro.product.brand', True)
914  product = run_adb_shell_cmd('getprop ro.product.name', True)
915  device = run_adb_shell_cmd('getprop ro.product.device', True)
916  version_release = run_adb_shell_cmd('getprop ro.build.version.release', True)
917  id = run_adb_shell_cmd('getprop ro.build.id', True)
918  version_incremental = run_adb_shell_cmd('getprop ro.build.version.incremental', True)
919  type = run_adb_shell_cmd('getprop ro.build.type', True)
920  tags = run_adb_shell_cmd('getprop ro.build.tags', True)
921  sdk = run_adb_shell_cmd('getprop ro.build.version.sdk', True)
922  platform_minor = run_adb_shell_cmd('getprop ro.android.car.version.platform_minor', True)
923  codename = run_adb_shell_cmd('getprop ro.build.version.codename', True)
924  carwatchdog_collection_interval = run_adb_shell_cmd('getprop ro.carwatchdog.system_event_collection_interval', True)
925  carwatchdog_post_event_duration = run_adb_shell_cmd('getprop ro.carwatchdog.post_system_event_duration', True)
926  carwatchdog_top_n_category = run_adb_shell_cmd('getprop ro.carwatchdog.top_n_stats_per_category', True)
927  carwatchdog_top_n_subcategory = run_adb_shell_cmd('getprop ro.carwatchdog.top_n_stats_per_subcategory', True)
928
929  # TODO: Change file format to JSON to avoid custom parser
930  build_info = []
931  build_info.append('Build information: ')
932  build_info.append('-' * 20)
933  build_info.append('fingerprint: ' + fingerprint)
934  build_info.append('brand: ' + brand)
935  build_info.append('product: ' + product)
936  build_info.append('device: ' + device)
937  build_info.append('version.release: ' + version_release)
938  build_info.append('id: ' + id)
939  build_info.append('version.incremental: ' + version_incremental)
940  build_info.append('type: ' + type)
941  build_info.append('tags: ' + tags)
942  build_info.append('sdk: ' + sdk)
943  build_info.append('platform minor version: ' + platform_minor)
944  build_info.append('codename: ' + codename)
945  build_info.append('carwatchdog collection interval (s): ' + carwatchdog_collection_interval)
946  build_info.append('carwatchdog post event duration (s): ' + carwatchdog_post_event_duration)
947  build_info.append('carwatchdog top N packages: ' + carwatchdog_top_n_category)
948  build_info.append('carwatchdog top N processes: ' + carwatchdog_top_n_subcategory)
949
950  build_info_str = '\n'.join(build_info)
951
952  with open(out_dir + '/' + build_info_file_name, 'w') as f:
953    f.write(build_info_str)
954
955def generate_proto(dump_file, build_info_file, out_proto_file):
956  subprocess.run("{} -f {} -b {} -d {}".format(CARWATCHDOG_PARSER_CMD,
957                                               dump_file,
958                                               build_info_file,
959                                               out_proto_file),
960                  shell=True, stdout=subprocess.DEVNULL)
961
962def grab_carwatchdog_bootstats(result_dir):
963  carwatchdog_state = run_adb_shell_cmd_as_root('getprop init.svc.carwatchdogd', True)
964  if carwatchdog_state != "running":
965    print('carwatchdog (-d) flag set but CarWatchdog is not running on device')
966    return
967  elif not result_dir:
968    print('carwatchdog needs the output directory to be specified.')
969    return
970  print("Capturing carwatchdog stats")
971  build_info_file_name = "device_build_info.txt"
972  capture_build_info(result_dir, build_info_file_name)
973
974  # Capture CW dump and save dump to txt
975  dump_file_name = result_dir + '/carwatchdog_dump.txt'
976  subprocess.call(CARWATCHDOG_DUMP_COMMAND + " > " + dump_file_name, shell=True)
977
978  # Generate proto from dump
979  build_info_file_path = result_dir + '/' + build_info_file_name
980  out_proto_file_path = result_dir + '/carwatchdog_perf_stats_out.pb'
981  generate_proto(dump_file_name, build_info_file_path, out_proto_file_path)
982
983
984if __name__ == '__main__':
985  main()
986