path: root/boottime_tools/bootanalyze/bootanalyze.py

#!/usr/bin/python3

# Copyright (C) 2016 The Android Open Source Project
#
# Licensed under the Apache License, Version 2.0 (the "License");
# you may not use this file except in compliance with the License.
# You may obtain a copy of the License at
#
#      http://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS,
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.
#
"""Tool to analyze logcat and dmesg logs.

bootanalyze read logcat and dmesg logs and determines key points for boot.
"""

import argparse
import collections
import datetime
import math
import operator
import os
import re
import select
import subprocess
import time
import threading
import yaml

from datetime import datetime

TIME_DMESG = r"\[\s*(\d+\.\d+)\]"
TIME_LOGCAT = r"[0-9]+\.?[0-9]*"
KERNEL_TIME_KEY = "kernel"
BOOT_ANIM_END_TIME_KEY = "BootAnimEnd"
KERNEL_BOOT_COMPLETE = "BootComplete_kernel"
LOGCAT_BOOT_COMPLETE = "BootComplete"
CARWATCHDOG_BOOT_COMPLETE = "CarWatchdogBootupProfilingComplete"
LAUNCHER_START = "LauncherStart"
CARWATCHDOG_DUMP_COMMAND = "adb shell dumpsys android.automotive.watchdog.ICarWatchdog/default"
BOOT_TIME_TOO_BIG = 200.0
MAX_RETRIES = 5
DEBUG = False
DEBUG_PATTERN = False
ADB_CMD = "adb"
TIMING_THRESHOLD = 5.0
BOOT_PROP = r"\[ro\.boottime\.([^\]]+)\]:\s+\[(\d+)\]"
BOOTLOADER_TIME_PROP = r"\[ro\.boot\.boottime\]:\s+\[([^\]]+)\]"
CARWATCHDOG_PARSER_CMD = 'perf_stats_parser'

max_wait_time = BOOT_TIME_TOO_BIG

def main():
  global ADB_CMD

  args = init_arguments()

  if args.iterate < 1:
    raise Exception('Number of iteration must be >=1')

  if args.iterate > 1 and not args.reboot:
    print("Forcing reboot flag")
    args.reboot = True

  if args.serial:
    ADB_CMD = "%s %s" % ("adb -s", args.serial)

  error_time = BOOT_TIME_TOO_BIG * 10
  if args.errortime:
    error_time = float(args.errortime)
  if args.maxwaittime:
    global max_wait_time
    max_wait_time = float(args.maxwaittime)

  components_to_monitor = {}
  if args.componentmonitor:
    items = args.componentmonitor.split(",")
    for item in items:
      kv = item.split("=")
      key = kv[0]
      value = float(kv[1])
      components_to_monitor[key] = value

  cfg = yaml.load(args.config, Loader=yaml.SafeLoader)

  if args.stressfs:
    if run_adb_cmd('install -r -g ' + args.stressfs) != 0:
      raise Exception('StressFS APK not installed')

  if args.iterate > 1 and args.bootchart:
    run_adb_shell_cmd_as_root('touch /data/bootchart/enabled')

  search_events_pattern = {key: re.compile(pattern)
                   for key, pattern in cfg['events'].items()}
  timing_events_pattern = {key: re.compile(pattern)
                   for key, pattern in cfg['timings'].items()}
  shutdown_events_pattern = {key: re.compile(pattern)
                   for key, pattern in cfg['shutdown_events'].items()}
  if DEBUG_PATTERN:
    print("search event:{} timing event:{}".format(search_events_pattern, timing_events_pattern))

  now = datetime.now().strftime("%Y-%m-%d-%H-%M-%S")
  boot_chart_file_path_prefix = "bootchart-" + now
  systrace_file_path_prefix = "systrace-" + now

  if args.output:
    boot_chart_file_path_prefix = args.output + '/' + boot_chart_file_path_prefix
    systrace_file_path_prefix = args.output + '/' + systrace_file_path_prefix

  data_points = {}
  kernel_timing_points = collections.OrderedDict()
  logcat_timing_points = collections.OrderedDict()
  boottime_points = collections.OrderedDict()
  shutdown_event_all = collections.OrderedDict()
  shutdown_timing_event_all = collections.OrderedDict()
  for it in range(0, args.iterate):
    if args.iterate > 1:
      print("Run: {0}".format(it))
    attempt = 1
    processing_data = None
    timings = None
    boottime_events = None
    while attempt <= MAX_RETRIES and processing_data is None:
      attempt += 1
      processing_data, kernel_timings, logcat_timings, boottime_events, shutdown_events,\
          shutdown_timing_events = iterate(\
        args, search_events_pattern, timing_events_pattern, shutdown_events_pattern, cfg,\
        error_time, components_to_monitor)
    if shutdown_events:
      for k, v in shutdown_events.items():
        events = shutdown_event_all.get(k)
        if not events:
          events = []
          shutdown_event_all[k] = events
        events.append(v)
    if shutdown_timing_events:
      for k, v in shutdown_timing_events.items():
        events = shutdown_timing_event_all.get(k)
        if not events:
          events = []
          shutdown_timing_event_all[k] = events
        events.append(v)
    if not processing_data or not boottime_events:
      # Processing error
      print("Failed to collect valid samples for run {0}".format(it))
      continue

    if args.bootchart:
      grab_bootchart(boot_chart_file_path_prefix + "_run_" + str(it))

    if args.systrace:
      grab_systrace(systrace_file_path_prefix + "_run_" + str(it))

    if args.carwatchdog:
      grab_carwatchdog_bootstats(args.output)

    for k, v in processing_data.items():
      if k not in data_points:
        data_points[k] = []
      data_points[k].append(v['value'])

    if kernel_timings is not None:
      for k, v in kernel_timings.items():
        if k not in kernel_timing_points:
          kernel_timing_points[k] = []
        kernel_timing_points[k].append(v)
    if logcat_timings is not None:
      for k, v in logcat_timings.items():
        if k not in logcat_timing_points:
          logcat_timing_points[k] = []
        logcat_timing_points[k].append(v)

    for k, v in boottime_events.items():
      if k not in boottime_points:
        boottime_points[k] = []
      boottime_points[k].append(v)

  if args.stressfs:
    run_adb_cmd('uninstall com.android.car.test.stressfs')
    run_adb_shell_cmd('"rm -rf /storage/emulated/0/stressfs_data*"')

  if args.iterate > 1:
    print("-----------------")
    print("\nshutdown events after {0} runs".format(args.iterate))
    print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
    for item in list(shutdown_event_all.items()):
      num_runs = len(item[1])
      print('{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format(
          item[0], sum(item[1])/num_runs, stddev(item[1]),\
          "*time taken" if item[0].startswith("init.") else "",\
          num_runs if num_runs != args.iterate else ""))
    print("\nshutdown timing events after {0} runs".format(args.iterate))
    print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
    for item in list(shutdown_timing_event_all.items()):
      num_runs = len(item[1])
      print('{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format(
          item[0], sum(item[1])/num_runs, stddev(item[1]),\
          "*time taken" if item[0].startswith("init.") else "",\
          num_runs if num_runs != args.iterate else ""))

    print("-----------------")
    print("ro.boottime.* after {0} runs".format(args.iterate))
    print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
    for item in list(boottime_points.items()):
        num_runs = len(item[1])
        print('{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format(
          item[0], sum(item[1])/num_runs, stddev(item[1]),\
          "*time taken" if item[0].startswith("init.") else "",\
          num_runs if num_runs != args.iterate else ""))

    if args.timings:
      dump_timings_points_summary("Kernel", kernel_timing_points, args)
      dump_timings_points_summary("Logcat", logcat_timing_points, args)


    print("-----------------")
    print("Avg values after {0} runs".format(args.iterate))
    print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))

    average_with_stddev = []
    for item in list(data_points.items()):
      average_with_stddev.append((item[0], sum(item[1])/len(item[1]), stddev(item[1]),\
                                  len(item[1])))
    for item in sorted(average_with_stddev, key=lambda entry: entry[1]):
      print('{0:30}: {1:<7.5} {2:<7.5} {3}'.format(
        item[0], item[1], item[2], item[3] if item[3] != args.iterate else ""))

    run_adb_shell_cmd_as_root('rm /data/bootchart/enabled')


def dump_timings_points_summary(msg_header, timing_points, args):
      averaged_timing_points = []
      for item in list(timing_points.items()):
        average = sum(item[1])/len(item[1])
        std_dev = stddev(item[1])
        averaged_timing_points.append((item[0], average, std_dev, len(item[1])))

      print("-----------------")
      print(msg_header + " timing in order, Avg time values after {0} runs".format(args.iterate))
      print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
      for item in averaged_timing_points:
        print('{0:30}: {1:<7.5} {2:<7.5} {3}'.format(
          item[0], item[1], item[2], item[3] if item[3] != args.iterate else ""))

      print("-----------------")
      print(msg_header + " timing top items, Avg time values after {0} runs".format(args.iterate))
      print('{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs"))
      for item in sorted(averaged_timing_points, key=lambda entry: entry[1], reverse=True):
        if item[1] < TIMING_THRESHOLD:
          break
        print('{0:30}: {1:<7.5} {2:<7.5} {3}'.format(
          item[0], item[1], item[2], item[3] if item[3] != args.iterate else ""))

def capture_bugreport(bugreport_hint, boot_complete_time):
    now = datetime.now()
    bugreport_file = ("bugreport-%s-" + bugreport_hint + "-%s.zip") \
        % (now.strftime("%Y-%m-%d-%H-%M-%S"), str(boot_complete_time))
    print("Boot up time too big, will capture bugreport %s" % (bugreport_file))
    os.system(ADB_CMD + " bugreport " + bugreport_file)

def generate_timing_points(timing_events, timings):
  timing_points = collections.OrderedDict()
  monitor_contention_points = collections.OrderedDict()
  for k, l in timing_events.items():
      for v in l:
        name, time_v = extract_timing(v, timings)
        if name and time_v:
          if v.find("SystemServerTimingAsync") > 0:
            name = "(" + name + ")"
          if k.endswith("_secs"):
            time_v = time_v * 1000.0
          if k.startswith("long_monitor_contention"):
            monitor_contention_points[v] = time_v
            continue
          new_name = name
          name_index = 0
          while timing_points.get(new_name): # if the name is already taken, append #digit
            name_index += 1
            new_name = name + "#" + str(name_index)
          timing_points[new_name] = time_v
  return timing_points, monitor_contention_points

def dump_timing_points(msg_header, timing_points):
    print(msg_header + " event timing in time order, key: time")
    for item in list(timing_points.items()):
      print('{0:30}: {1:<7.5}'.format(item[0], item[1]))
    print("-----------------")
    print(msg_header + " event timing top items")
    for item in sorted(list(timing_points.items()), key=operator.itemgetter(1), reverse=True):
      if item[1] < TIMING_THRESHOLD:
        break
      print('{0:30}: {1:<7.5}'.format(
        item[0], item[1]))
    print("-----------------")

def dump_monitor_contentions(logcat_monitor_contentions):
  print("Monitor contentions over 100ms:")
  for item in list(logcat_monitor_contentions.items()):
      if item[1] > 100:
        print('{0:<7.5}ms: {1}'.format(item[1], item[0]))
  print("-----------------")

def handle_reboot_log(capture_log_on_error, shutdown_events_pattern, components_to_monitor):
  shutdown_events, shutdown_timing_events = collect_logcat_for_shutdown(capture_log_on_error,\
		shutdown_events_pattern, components_to_monitor)
  print("\nshutdown events: time")
  for item in list(shutdown_events.items()):
    print('{0:30}: {1:<7.5}'.format(item[0], item[1]))
  print("\nshutdown timing events: time")
  for item in list(shutdown_timing_events.items()):
    print('{0:30}: {1:<7.5}'.format(item[0], item[1]))
  return shutdown_events, shutdown_timing_events

def collect_dmesg_events(search_events_pattern, timings_pattern, results):
  dmesg_events, kernel_timing_events = collect_events(search_events_pattern, ADB_CMD +\
                                                      ' shell su root dmesg -w', timings_pattern,\
                                                      [KERNEL_BOOT_COMPLETE], True)
  results.append(dmesg_events)
  results.append(kernel_timing_events)

def iterate(args, search_events_pattern, timings_pattern, shutdown_events_pattern, cfg, error_time,\
    components_to_monitor):
  shutdown_events = None
  shutdown_timing_events = None
  if args.reboot:
    # sleep to make sure that logcat reader is reading before adb is gone by reboot. ugly but make
    # impl simple.
    t = threading.Thread(target=lambda: (time.sleep(2), reboot(args.serial, args.stressfs != '',\
        args.permissive, args.adb_reboot, args.buffersize)))
    t.start()
    shutdown_events, shutdown_timing_events = handle_reboot_log(True, shutdown_events_pattern,\
        components_to_monitor)
    t.join()

  results = []
  t = threading.Thread(target=collect_dmesg_events, args=(search_events_pattern,\
    timings_pattern, results))
  t.start()

  logcat_stop_events = [LOGCAT_BOOT_COMPLETE, LAUNCHER_START]
  if args.fs_check:
    logcat_stop_events.append("FsStat")
  if args.carwatchdog:
    logcat_stop_events.append(CARWATCHDOG_BOOT_COMPLETE)
  logcat_events, logcat_timing_events = collect_events(
    search_events_pattern, ADB_CMD + ' logcat -b all -v epoch', timings_pattern,\
    logcat_stop_events, False)

  t.join()
  dmesg_events = results[0]
  kernel_timing_events = results[1]

  logcat_event_time = extract_time(logcat_events, TIME_LOGCAT, float)
  logcat_original_time = extract_time(logcat_events, TIME_LOGCAT, str);
  dmesg_event_time = extract_time(dmesg_events, TIME_DMESG, float);
  boottime_events = fetch_boottime_property()
  events = {}
  events_to_correct = []
  replaced_from_dmesg = set()

  time_correction_delta = 0
  time_correction_time = 0
  if ('time_correction_key' in cfg
      and cfg['time_correction_key'] in logcat_events):
    match = search_events_pattern[cfg['time_correction_key']].search(
      logcat_events[cfg['time_correction_key']])
    if match and logcat_event_time[cfg['time_correction_key']]:
      time_correction_delta = float(match.group(1))
      time_correction_time = logcat_event_time[cfg['time_correction_key']]

  debug("time_correction_delta = {0}, time_correction_time = {1}".format(
    time_correction_delta, time_correction_time))

  for k, v in logcat_event_time.items():
    if v <= time_correction_time:
      logcat_event_time[k] += time_correction_delta
      v = v + time_correction_delta
      debug("correcting event to event[{0}, {1}]".format(k, v))

  diffs = []
  if logcat_event_time.get(KERNEL_TIME_KEY) is None:
    print("kernel time not captured in logcat")
  else:
    diffs.append((logcat_event_time[KERNEL_TIME_KEY], logcat_event_time[KERNEL_TIME_KEY]))

  if logcat_event_time.get(BOOT_ANIM_END_TIME_KEY) and dmesg_event_time.get(BOOT_ANIM_END_TIME_KEY):
      diffs.append((logcat_event_time[BOOT_ANIM_END_TIME_KEY],\
                    logcat_event_time[BOOT_ANIM_END_TIME_KEY] -\
                      dmesg_event_time[BOOT_ANIM_END_TIME_KEY]))
  if not dmesg_event_time.get(KERNEL_BOOT_COMPLETE):
      print("BootAnimEnd time or BootComplete-kernel not captured in both log" +\
        ", cannot get time diff")
      print("dmesg {} logcat {}".format(dmesg_event_time, logcat_event_time))
      return None, None, None, None, None, None
  diffs.append((logcat_event_time[LOGCAT_BOOT_COMPLETE],\
                logcat_event_time[LOGCAT_BOOT_COMPLETE] - dmesg_event_time[KERNEL_BOOT_COMPLETE]))

  for k, v in logcat_event_time.items():
    debug("event[{0}, {1}]".format(k, v))
    events[k] = v
    if k in dmesg_event_time:
      debug("{0} is in dmesg".format(k))
      events[k] = dmesg_event_time[k]
      replaced_from_dmesg.add(k)
    else:
      events_to_correct.append(k)

  diff_prev = diffs[0]
  for k in events_to_correct:
    diff = diffs[0]
    while diff[0] < events[k] and len(diffs) > 1:
      diffs.pop(0)
      diff_prev = diff
      diff = diffs[0]
    events[k] = events[k] - diff[1]
    if events[k] < 0.0:
        if events[k] < -0.1: # maybe previous one is better fit
          events[k] = events[k] + diff[1] - diff_prev[1]
        else:
          events[k] = 0.0

  data_points = collections.OrderedDict()

  print("-----------------")
  print("ro.boottime.*: time")
  for item in list(boottime_events.items()):
    print('{0:30}: {1:<7.5} {2}'.format(item[0], item[1],\
      "*time taken" if item[0].startswith("init.") else ""))
  print("-----------------")

  if args.timings:
    kernel_timing_points, _ = generate_timing_points(kernel_timing_events, timings_pattern)
    logcat_timing_points, logcat_monitor_contentions =\
      generate_timing_points(logcat_timing_events, timings_pattern)
    dump_timing_points("Kernel", kernel_timing_points)
    dump_timing_points("Logcat", logcat_timing_points)
    dump_monitor_contentions(logcat_monitor_contentions)

  for item in sorted(list(events.items()), key=operator.itemgetter(1)):
    data_points[item[0]] = {
      'value': item[1],
      'from_dmesg': item[0] in replaced_from_dmesg,
      'logcat_value': logcat_original_time[item[0]]
    }
  # add times with bootloader
  if events.get("BootComplete") and boottime_events.get("bootloader"):
    total = events["BootComplete"] + boottime_events["bootloader"]
    data_points["*BootComplete+Bootloader"] = {
      'value': total,
      'from_dmesg': False,
      'logcat_value': 0.0
    }
  if events.get("LauncherStart") and boottime_events.get("bootloader"):
    total = events["LauncherStart"] + boottime_events["bootloader"]
    data_points["*LauncherStart+Bootloader"] = {
      'value': total,
      'from_dmesg': False,
      'logcat_value': 0.0
    }
  for k, v in data_points.items():
    print('{0:30}: {1:<7.5} {2:1} ({3})'.format(
      k, v['value'], '*' if v['from_dmesg'] else '', v['logcat_value']))

  print('\n* - event time was obtained from dmesg log\n')

  if events[LOGCAT_BOOT_COMPLETE] > error_time and not args.ignore:
    capture_bugreport("bootuptoolong", events[LOGCAT_BOOT_COMPLETE])

  for k, v in components_to_monitor.items():
    logcat_value_measured = logcat_timing_points.get(k)
    kernel_value_measured = kernel_timing_points.get(k)
    data_from_data_points = data_points.get(k)
    if logcat_value_measured and logcat_value_measured > v:
      capture_bugreport(k + "-" + str(logcat_value_measured), events[LOGCAT_BOOT_COMPLETE])
      break
    elif kernel_value_measured and kernel_value_measured > v:
      capture_bugreport(k + "-" + str(kernel_value_measured), events[LOGCAT_BOOT_COMPLETE])
      break
    elif data_from_data_points and data_from_data_points['value'] * 1000.0 > v:
      capture_bugreport(k + "-" + str(data_from_data_points['value']), events[LOGCAT_BOOT_COMPLETE])
      break

  if args.fs_check:
    fs_stat = None
    if logcat_events.get("FsStat"):
      fs_stat_pattern = cfg["events"]["FsStat"]
      m = re.search(fs_stat_pattern, logcat_events.get("FsStat"))
      if m:
        fs_stat = m.group(1)
    print('fs_stat:', fs_stat)

    if fs_stat:
      fs_stat_val = int(fs_stat, 0)
      if (fs_stat_val & ~0x17) != 0:
        capture_bugreport("fs_stat_" + fs_stat, events[LOGCAT_BOOT_COMPLETE])

  return data_points, kernel_timing_points, logcat_timing_points, boottime_events, shutdown_events,\
      shutdown_timing_events

def debug(string):
  if DEBUG:
    print(string)

def extract_timing(s, patterns):
  for _, p in patterns.items():
    m = p.search(s)
    if m:
      timing_dict = m.groupdict()
      return timing_dict['name'], float(timing_dict['time'])
  return None, None

def init_arguments():
  parser = argparse.ArgumentParser(description='Measures boot time.')
  parser.add_argument('-r', '--reboot', dest='reboot',
                      action='store_true',
                      help='reboot device for measurement', )
  parser.add_argument('-o', '--output', dest='output', type=str,
                      help='Output directory where results are stored')
  parser.add_argument('-c', '--config', dest='config',
                      default='config.yaml', type=argparse.FileType('r'),
                      help='config file for the tool', )
  parser.add_argument('-s', '--stressfs', dest='stressfs',
                      default='', type=str,
                      help='APK file for the stressfs tool used to write to the data partition ' +\
                           'during shutdown')
  parser.add_argument('-n', '--iterate', dest='iterate', type=int, default=1,
                      help='number of time to repeat the measurement', )
  parser.add_argument('-g', '--ignore', dest='ignore', action='store_true',
                      help='ignore too big values error', )
  parser.add_argument('-t', '--timings', dest='timings', action='store_true',
                      help='print individual component times', default=True, )
  parser.add_argument('-p', '--serial', dest='serial', action='store',
                      help='android device serial number')
  parser.add_argument('-e', '--errortime', dest='errortime', action='store',
                      help='handle bootup time bigger than this as error')
  parser.add_argument('-w', '--maxwaittime', dest='maxwaittime', action='store',
                      help='wait for up to this time to collect logs. Retry after this time.' +\
                           ' Default is 200 sec.')
  parser.add_argument('-f', '--fs_check', dest='fs_check',
                      action='store_true',
                      help='check fs_stat after reboot', )
  parser.add_argument('-a', '--adb_reboot', dest='adb_reboot',
                      action='store_true',
                      help='reboot with adb reboot', )
  parser.add_argument('-v', '--permissive', dest='permissive',
                      action='store_true',
                      help='set selinux into permissive before reboot', )
  parser.add_argument('-m', '--componentmonitor', dest='componentmonitor', action='store',
                      help='capture bugreport if specified timing component is taking more than ' +\
                           'certain time. Unlike errortime, the result will not be rejected in' +\
                           'averaging. Format is key1=time1,key2=time2...')
  parser.add_argument('-b', '--bootchart', dest='bootchart',
                      action='store_true',
                      help='collect bootchart from the device.', )
  parser.add_argument('-y', '--systrace', dest='systrace',
                      action='store_true',
                      help='collect systrace from the device. kernel trace should be already enabled', )
  parser.add_argument('-W', '--carwatchdog', dest='carwatchdog', action='store_true',
                      help='collect carwatchdog boot stats')
  parser.add_argument('-G', '--buffersize', dest='buffersize', action='store', type=str,
                      default=None,
                      help='set logcat buffersize')
  return parser.parse_args()

def handle_zygote_event(zygote_pids, events, event, line):
  words = line.split()
  if len(words) > 1:
    pid = int(words[1])
    if len(zygote_pids) == 2:
      if pid == zygote_pids[1]: # secondary
        event = event + "-secondary"
    elif len(zygote_pids) == 1:
      if zygote_pids[0] != pid: # new pid, need to decide if old ones were secondary
        primary_pid = min(pid, zygote_pids[0])
        secondary_pid = max(pid, zygote_pids[0])
        zygote_pids.pop()
        zygote_pids.append(primary_pid)
        zygote_pids.append(secondary_pid)
        if pid == primary_pid: # old one was secondary:
          move_to_secondary = []
          for k, l in events.items():
            if k.startswith("zygote"):
              move_to_secondary.append((k, l))
          for item in move_to_secondary:
            del events[item[0]]
            if item[0].endswith("-secondary"):
              print("Secondary already exists for event %s  while found new pid %d, primary %d "\
                % (item[0], secondary_pid, primary_pid))
            else:
              events[item[0] + "-secondary"] = item[1]
        else:
          event = event + "-secondary"
    else:
      zygote_pids.append(pid)
  events[event] = line

def update_name_if_already_exist(events, name):
  existing_event = events.get(name)
  i = 0
  new_name = name
  while existing_event:
    i += 1
    new_name = name + "_" + str(i)
    existing_event = events.get(new_name)
  return new_name

def collect_logcat_for_shutdown(capture_log_on_error, shutdown_events_pattern,\
    log_capture_conditions):
  events = collections.OrderedDict()
  # shutdown does not have timing_events but calculated from checking Xyz - XyzDone / XyzTimeout
  timing_events = collections.OrderedDict()
  process = subprocess.Popen(ADB_CMD + ' logcat -b all -v epoch', shell=True,
                             stdout=subprocess.PIPE)
  lines = []
  capture_log = False
  shutdown_start_time = 0
  while True:
    line = process.stdout.readline()
    if not line:
      break
    line = line.decode('utf-8', 'ignore').lstrip().rstrip()
    lines.append(line)
    event = get_boot_event(line, shutdown_events_pattern)
    if not event:
      continue
    time = extract_a_time(line, TIME_LOGCAT, float)
    if time is None:
      print("cannot get time from: " + line)
      continue
    if shutdown_start_time == 0:
      shutdown_start_time = time
    time = time - shutdown_start_time
    events[event] = time
    time_limit1 = log_capture_conditions.get(event)
    if time_limit1 and time_limit1 <= time:
      capture_log = True
    pair_event = None
    if event.endswith('Done'):
      pair_event = event[:-4]
    elif event.endswith('Timeout'):
      pair_event = event[:-7]
      if capture_log_on_error:
        capture_log = True
    if not pair_event:
      continue
    start_time = events.get(pair_event)
    if not start_time:
      print("No start event for " + event)
      continue
    time_spent = time - start_time
    timing_event_name = pair_event + "Duration"
    timing_events[timing_event_name] = time_spent
    time_limit2 = log_capture_conditions.get(timing_event_name)
    if time_limit2 and time_limit2 <= time_spent:
      capture_log = True

  if capture_log:
    now = datetime.now()
    log_file = ("shutdownlog-error-%s.txt") % (now.strftime("%Y-%m-%d-%H-%M-%S"))
    print("Shutdown error, capture log to %s" % (log_file))
    with open(log_file, 'w') as f:
      f.write('\n'.join(lines))
  return events, timing_events

def log_timeout(time_left, stop_events, events, timing_events):
  print("timeout waiting for event, continue", time_left)
  print(" remaininig events {}, event {} timing events {}".\
    format(stop_events, events, timing_events))

def collect_events(search_events, command, timings, stop_events, disable_timing_after_zygote):
  events = collections.OrderedDict()
  timing_events = {}

  data_available = stop_events is None
  zygote_pids = []
  start_time = time.time()
  zygote_found = False
  line = None
  print("remaining stop_events:", stop_events)
  init = True
  while True:
    if init:
      process = subprocess.Popen(command, shell=True, stdout=subprocess.PIPE)
      read_poll = select.poll()
      read_poll.register(process.stdout, select.POLLIN)
      init = False
    if len(stop_events) == 0:
      break
    time_left = start_time + max_wait_time - time.time()
    if time_left <= 0:
      log_timeout(time_left, stop_events, events, timing_events)
      break
    polled_events = read_poll.poll(time_left * 1000.0)
    # adb logcat subprocess is auto-terminated when the adb connection is lost.
    # Thus, check for the subprocess return code and reconnect to the device if
    # needed. Otherwise, the logcat events cannot be polled completely.
    if process.poll() is not None:
      print("adb might be disconnected?\nRetrying to connect.")
      run_adb_cmd('wait-for-device')
      print(" reconnected")
      init = True
      continue
    if len(polled_events) == 0:
      log_timeout(time_left, stop_events, events, timing_events)
      break
    for polled_event in polled_events:
      if polled_event[1] == select.POLLIN:
        line = process.stdout.readline().decode('utf-8', 'ignore')
      else:
        if polled_event[1] == select.POLLHUP:
          if len(stop_events) == 0:
            break;
        # adb connection lost
        print("poll error waiting for event, adb lost?")
        if time_left > 0:
          print("retry adb")
          run_adb_cmd('wait-for-device')
          print(" reconnected")
          init = True
          continue
        else:
          break
      if not data_available:
        print("Collecting data samples from '%s'. Please wait...\n" % command)
        data_available = True
      event = get_boot_event(line, search_events)
      if event:
        debug("event[{0}] captured: {1}".format(event, line))
        if event == "starting_zygote":
          events[event] = line
          zygote_found = True
        elif event.startswith("zygote"):
          handle_zygote_event(zygote_pids, events, event, line)
        else:
          new_event = update_name_if_already_exist(events, event)
          events[new_event] = line
        if event in stop_events:
          stop_events.remove(event)
          print("remaining stop_events:", stop_events)

      timing_event = get_boot_event(line, timings)
      if timing_event and (not disable_timing_after_zygote or not zygote_found):
        if timing_event not in timing_events:
          timing_events[timing_event] = []
        timing_events[timing_event].append(line)
        debug("timing_event[{0}] captured: {1}".format(timing_event, line))

  process.terminate()
  return events, timing_events

def fetch_boottime_property():
  cmd = ADB_CMD + ' shell su root getprop'
  events = {}
  process = subprocess.Popen(cmd, shell=True, stdout=subprocess.PIPE)
  out = process.stdout
  pattern = re.compile(BOOT_PROP)
  pattern_bootloader = re.compile(BOOTLOADER_TIME_PROP)
  bootloader_time = 0.0
  for line in out:
    line = line.decode('utf-8', 'ignore')
    match = pattern.match(line)
    if match:
      if match.group(1).startswith("init."):
        events[match.group(1)] = float(match.group(2)) / 1000.0 #ms to s
      else:
        events[match.group(1)] = float(match.group(2)) / 1000000000.0 #ns to s
    match = pattern_bootloader.match(line)
    if match:
      items = match.group(1).split(",")
      for item in items:
        entry_pair = item.split(":")
        entry_name = entry_pair[0]
        time_spent = float(entry_pair[1]) / 1000 #ms to s
        if entry_name != "SW":
          bootloader_time = bootloader_time + time_spent
  ordered_event = collections.OrderedDict()
  if bootloader_time != 0.0:
    ordered_event["bootloader"] = bootloader_time
  for item in sorted(list(events.items()), key=operator.itemgetter(1)):
    ordered_event[item[0]] = item[1]
  return ordered_event


def get_boot_event(line, events):
  for event_key, event_pattern in events.items():
    if event_pattern.search(line):
      return event_key
  return None

def extract_a_time(line, pattern, date_transform_function):
    found = re.findall(pattern, line)
    if len(found) > 0:
      return date_transform_function(found[0])
    else:
      return None

def extract_time(events, pattern, date_transform_function):
  result = collections.OrderedDict()
  for event, data in events.items():
    time = extract_a_time(data, pattern, date_transform_function)
    if time is not None:
      result[event] = time
    else:
      print("Failed to find time for event: ", event, data)
  return result


def do_reboot(serial, use_adb_reboot):
  # do not update time
  run_adb_cmd('shell settings put global auto_time 0')
  run_adb_cmd('shell settings put global auto_time_zone 0')
  original_devices = subprocess.check_output("adb devices", shell=True).decode('utf-8', 'ignore')
  if use_adb_reboot:
    print('Rebooting the device using adb reboot')
    run_adb_cmd('reboot')
  else:
    print('Rebooting the device using svc power reboot')
    run_adb_shell_cmd_as_root('svc power reboot')
  # Wait for the device to go away
  retry = 0
  while retry < 20:
    current_devices = subprocess.check_output("adb devices", shell=True).decode('utf-8', 'ignore')
    if original_devices != current_devices:
      if not serial or (serial and current_devices.find(serial) < 0):
        return True
    time.sleep(1)
    retry += 1
  return False

def reboot(serial, use_stressfs, permissive, use_adb_reboot, adb_buffersize=None):
  if use_stressfs:
    print('Starting write to data partition')
    run_adb_shell_cmd('am start' +\
                      ' -n com.android.car.test.stressfs/.WritingActivity' +\
                      ' -a com.android.car.test.stressfs.START')
    # Give this app some time to start.
    time.sleep(1)
  if permissive:
    run_adb_shell_cmd_as_root('setenforce 0')

  retry = 0
  while retry < 5:
    if do_reboot(serial, use_adb_reboot):
      break
    retry += 1

  print('Waiting the device')
  run_adb_cmd('wait-for-device')
  print(' found a device')

  if adb_buffersize is not None:
    # increase the buffer size
    if run_adb_cmd('logcat -G {}'.format(adb_buffersize)) != 0:
      debug('Fail to set logcat buffer size as {}'.format(adb_buffersize))

'''
Runs adb command. If do_return_result is true then output of command is
returned otherwise an empty string is returned.
'''
def run_adb_cmd(cmd, do_return_result=False):
  if do_return_result:
    return subprocess.check_output(ADB_CMD + ' ' + cmd, shell=True).decode('utf-8', 'ignore').strip()
  subprocess.call(ADB_CMD + ' ' + cmd, shell=True)
  return ""

def run_adb_shell_cmd(cmd, do_return_result=False):
  return run_adb_cmd('shell ' + cmd, do_return_result)

def run_adb_shell_cmd_as_root(cmd, do_return_result=False):
  return run_adb_shell_cmd('su root ' + cmd, do_return_result)

def logcat_time_func(offset_year):
  def f(date_str):
    ndate = datetime.datetime.strptime(str(offset_year) + '-' +
                                 date_str, '%Y-%m-%d %H:%M:%S.%f')
    return datetime_to_unix_time(ndate)
  return f

def datetime_to_unix_time(ndate):
  return time.mktime(ndate.timetuple()) + ndate.microsecond/1000000.0

def stddev(data):
  items_count = len(data)
  avg = sum(data) / items_count
  sq_diffs_sum = sum([(v - avg) ** 2 for v in data])
  variance = sq_diffs_sum / items_count
  return math.sqrt(variance)

def grab_bootchart(boot_chart_file_path):
  subprocess.run("$ANDROID_BUILD_TOP/system/core/init/grab-bootchart.sh", shell=True,
                 stdout=subprocess.DEVNULL)
  print("Saving boot chart as " + boot_chart_file_path + ".tgz")
  subprocess.call('cp /tmp/android-bootchart/bootchart.tgz ' + boot_chart_file_path + '.tgz', \
                  shell=True)
  subprocess.call('cp ./bootchart.png ' + boot_chart_file_path + '.png', shell=True)

def grab_systrace(systrace_file_path_prefix):
  trace_file = systrace_file_path_prefix + "_trace.txt"
  with open(trace_file, 'w') as f:
    f.write("TRACE:\n")
  run_adb_shell_cmd_as_root("cat /d/tracing/trace >> " + trace_file)
  html_file = systrace_file_path_prefix + ".html"
  subprocess.call("$ANDROID_BUILD_TOP/external/chromium-trace/systrace.py --from-file=" + trace_file + " -o " +\
                  html_file, shell=True)

def capture_build_info(out_dir, build_info_file_name):
  fingerprint = run_adb_shell_cmd('getprop ro.build.fingerprint', True)
  brand = run_adb_shell_cmd('getprop ro.product.brand', True)
  product = run_adb_shell_cmd('getprop ro.product.name', True)
  device = run_adb_shell_cmd('getprop ro.product.device', True)
  version_release = run_adb_shell_cmd('getprop ro.build.version.release', True)
  id = run_adb_shell_cmd('getprop ro.build.id', True)
  version_incremental = run_adb_shell_cmd('getprop ro.build.version.incremental', True)
  type = run_adb_shell_cmd('getprop ro.build.type', True)
  tags = run_adb_shell_cmd('getprop ro.build.tags', True)
  sdk = run_adb_shell_cmd('getprop ro.build.version.sdk', True)
  platform_minor = run_adb_shell_cmd('getprop ro.android.car.version.platform_minor', True)
  codename = run_adb_shell_cmd('getprop ro.build.version.codename', True)
  carwatchdog_collection_interval = run_adb_shell_cmd('getprop ro.carwatchdog.system_event_collection_interval', True)
  carwatchdog_post_event_duration = run_adb_shell_cmd('getprop ro.carwatchdog.post_system_event_duration', True)
  carwatchdog_top_n_category = run_adb_shell_cmd('getprop ro.carwatchdog.top_n_stats_per_category', True)
  carwatchdog_top_n_subcategory = run_adb_shell_cmd('getprop ro.carwatchdog.top_n_stats_per_subcategory', True)

  # TODO: Change file format to JSON to avoid custom parser
  build_info = []
  build_info.append('Build information: ')
  build_info.append('-' * 20)
  build_info.append('fingerprint: ' + fingerprint)
  build_info.append('brand: ' + brand)
  build_info.append('product: ' + product)
  build_info.append('device: ' + device)
  build_info.append('version.release: ' + version_release)
  build_info.append('id: ' + id)
  build_info.append('version.incremental: ' + version_incremental)
  build_info.append('type: ' + type)
  build_info.append('tags: ' + tags)
  build_info.append('sdk: ' + sdk)
  build_info.append('platform minor version: ' + platform_minor)
  build_info.append('codename: ' + codename)
  build_info.append('carwatchdog collection interval (s): ' + carwatchdog_collection_interval)
  build_info.append('carwatchdog post event duration (s): ' + carwatchdog_post_event_duration)
  build_info.append('carwatchdog top N packages: ' + carwatchdog_top_n_category)
  build_info.append('carwatchdog top N processes: ' + carwatchdog_top_n_subcategory)

  build_info_str = '\n'.join(build_info)

  with open(out_dir + '/' + build_info_file_name, 'w') as f:
    f.write(build_info_str)

def generate_proto(dump_file, build_info_file, out_proto_file):
  subprocess.run("{} -f {} -b {} -d {}".format(CARWATCHDOG_PARSER_CMD,
                                               dump_file,
                                               build_info_file,
                                               out_proto_file),
                  shell=True, stdout=subprocess.DEVNULL)

def grab_carwatchdog_bootstats(result_dir):
  carwatchdog_state = run_adb_shell_cmd_as_root('getprop init.svc.carwatchdogd', True)
  if carwatchdog_state != "running":
    print('carwatchdog (-d) flag set but CarWatchdog is not running on device')
    return
  elif not result_dir:
    print('carwatchdog needs the output directory to be specified.')
    return
  print("Capturing carwatchdog stats")
  build_info_file_name = "device_build_info.txt"
  capture_build_info(result_dir, build_info_file_name)

  # Capture CW dump and save dump to txt
  dump_file_name = result_dir + '/carwatchdog_dump.txt'
  subprocess.call(CARWATCHDOG_DUMP_COMMAND + " > " + dump_file_name, shell=True)

  # Generate proto from dump
  build_info_file_path = result_dir + '/' + build_info_file_name
  out_proto_file_path = result_dir + '/carwatchdog_perf_stats_out.pb'
  generate_proto(dump_file_name, build_info_file_path, out_proto_file_path)


if __name__ == '__main__':
  main()