1#!/usr/bin/python
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 loga 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 sys
32import time
33import yaml
34
35from datetime import datetime, date
36
37
38TIME_DMESG = "\[\s*(\d+\.\d+)\]"
39TIME_LOGCAT = "[0-9]+\.?[0-9]*"
40KERNEL_TIME_KEY = "kernel"
41BOOT_ANIM_END_TIME_KEY = "BootAnimEnd"
42KERNEL_BOOT_COMPLETE = "BootComplete_kernel"
43LOGCAT_BOOT_COMPLETE = "BootComplete"
44LAUNCHER_START = "LauncherStart"
45BOOT_TIME_TOO_BIG = 200.0
46MAX_RETRIES = 5
47DEBUG = False
48ADB_CMD = "adb"
49TIMING_THRESHOLD = 5.0
50BOOT_PROP = "\[ro\.boottime\.([^\]]+)\]:\s+\[(\d+)\]"
51BOOTLOADER_TIME_PROP = "\[ro\.boot\.boottime\]:\s+\[([^\]]+)\]"
52
53max_wait_time = BOOT_TIME_TOO_BIG
54
55def main():
56  global ADB_CMD
57
58  args = init_arguments()
59
60  if args.iterate < 1:
61    raise Exception('Number of iteration must be >=1');
62
63  if args.iterate > 1 and not args.reboot:
64    print "Forcing reboot flag"
65    args.reboot = True
66
67  if args.serial:
68    ADB_CMD = "%s %s" % ("adb -s", args.serial)
69
70  error_time = BOOT_TIME_TOO_BIG * 10
71  if args.errortime:
72    error_time = float(args.errortime)
73  if args.maxwaittime:
74    global max_wait_time
75    max_wait_time = float(args.maxwaittime)
76
77  components_to_monitor = {}
78  if args.componentmonitor:
79    items = args.componentmonitor.split(",")
80    for item in items:
81      kv = item.split("=")
82      key = kv[0]
83      value = float(kv[1])
84      components_to_monitor[key] = value
85
86  cfg = yaml.load(args.config)
87
88  if args.stressfs:
89    if run_adb_cmd('install -r -g ' + args.stressfs) != 0:
90      raise Exception('StressFS APK not installed');
91
92  if args.iterate > 1 and args.bootchart:
93    run_adb_shell_cmd_as_root('touch /data/bootchart/enabled')
94
95  search_events = {key: re.compile(pattern)
96                   for key, pattern in cfg['events'].iteritems()}
97  timing_events = {key: re.compile(pattern)
98                   for key, pattern in cfg['timings'].iteritems()}
99
100  data_points = {}
101  kernel_timing_points = collections.OrderedDict()
102  logcat_timing_points = collections.OrderedDict()
103  boottime_points = collections.OrderedDict()
104  boot_chart_file_name_prefix = "bootchart-" + datetime.now().strftime("%Y-%m-%d-%H-%M-%S")
105  systrace_file_name_prefix = "systrace-" + datetime.now().strftime("%Y-%m-%d-%H-%M-%S")
106  for it in range(0, args.iterate):
107    if args.iterate > 1:
108      print "Run: {0}".format(it)
109    attempt = 1
110    processing_data = None
111    timings = None
112    boottime_events = None
113    while attempt <= MAX_RETRIES and processing_data is None:
114      attempt += 1
115      processing_data, kernel_timings, logcat_timings, boottime_events = iterate(
116        args, search_events, timing_events, cfg, error_time, components_to_monitor)
117
118    if not processing_data or not boottime_events:
119      # Processing error
120      print "Failed to collect valid samples for run {0}".format(it)
121      continue
122    if args.bootchart:
123      grab_bootchart(boot_chart_file_name_prefix + "_run_" + str(it))
124
125    if args.systrace:
126      grab_systrace(systrace_file_name_prefix + "_run_" + str(it))
127    for k, v in processing_data.iteritems():
128      if k not in data_points:
129        data_points[k] = []
130      data_points[k].append(v['value'])
131
132    if kernel_timings is not None:
133      for k, v in kernel_timings.iteritems():
134        if k not in kernel_timing_points:
135          kernel_timing_points[k] = []
136        kernel_timing_points[k].append(v)
137    if logcat_timings is not None:
138      for k, v in logcat_timings.iteritems():
139        if k not in logcat_timing_points:
140          logcat_timing_points[k] = []
141        logcat_timing_points[k].append(v)
142
143    for k, v in boottime_events.iteritems():
144      if not k in boottime_points:
145        boottime_points[k] = []
146      boottime_points[k].append(v)
147
148  if args.stressfs:
149    run_adb_cmd('uninstall com.android.car.test.stressfs')
150    run_adb_shell_cmd('"rm -rf /storage/emulated/0/stressfs_data*"')
151
152  if args.iterate > 1:
153    print "-----------------"
154    print "ro.boottime.* after {0} runs".format(args.iterate)
155    print '{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs")
156    for item in boottime_points.items():
157        num_runs = len(item[1])
158        print '{0:30}: {1:<7.5} {2:<7.5} {3} {4}'.format(
159          item[0], sum(item[1])/num_runs, stddev(item[1]),\
160          "*time taken" if item[0].startswith("init.") else "",\
161          num_runs if num_runs != args.iterate else "")
162
163    if args.timings:
164      dump_timings_points_summary("Kernel", kernel_timing_points, args)
165      dump_timings_points_summary("Logcat", logcat_timing_points, args)
166
167
168    print "-----------------"
169    print "Avg values after {0} runs".format(args.iterate)
170    print '{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs")
171
172    average_with_stddev = []
173    for item in data_points.items():
174      average_with_stddev.append((item[0], sum(item[1])/len(item[1]), stddev(item[1]),\
175                                  len(item[1])))
176    for item in sorted(average_with_stddev, key=lambda entry: entry[1]):
177      print '{0:30}: {1:<7.5} {2:<7.5} {3}'.format(
178        item[0], item[1], item[2], item[3] if item[3] != args.iterate else "")
179
180    run_adb_shell_cmd_as_root('rm /data/bootchart/enabled')
181
182
183def dump_timings_points_summary(msg_header, timing_points, args):
184      averaged_timing_points = []
185      for item in timing_points.items():
186        average = sum(item[1])/len(item[1])
187        std_dev = stddev(item[1])
188        averaged_timing_points.append((item[0], average, std_dev, len(item[1])))
189
190      print "-----------------"
191      print msg_header + " timing in order, Avg time values after {0} runs".format(args.iterate)
192      print '{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs")
193      for item in averaged_timing_points:
194        print '{0:30}: {1:<7.5} {2:<7.5} {3}'.format(
195          item[0], item[1], item[2], item[3] if item[3] != args.iterate else "")
196
197      print "-----------------"
198      print msg_header + " timing top items, Avg time values after {0} runs".format(args.iterate)
199      print '{0:30}: {1:<7} {2:<7} {3}'.format("Event", "Mean", "stddev", "#runs")
200      for item in sorted(averaged_timing_points, key=lambda entry: entry[1], reverse=True):
201        if item[1] < TIMING_THRESHOLD:
202          break
203        print '{0:30}: {1:<7.5} {2:<7.5} {3}'.format(
204          item[0], item[1], item[2], item[3] if item[3] != args.iterate else "")
205
206def capture_bugreport(bugreport_hint, boot_complete_time):
207    now = datetime.now()
208    bugreport_file = ("bugreport-%s-" + bugreport_hint + "-%s.zip") \
209        % (now.strftime("%Y-%m-%d-%H-%M-%S"), str(boot_complete_time))
210    print "Boot up time too big, will capture bugreport %s" % (bugreport_file)
211    os.system(ADB_CMD + " bugreport " + bugreport_file)
212
213def generate_timing_points(timing_events, timings):
214  timing_points = collections.OrderedDict()
215  for k, l in timing_events.iteritems():
216      for v in l:
217        name, time_v = extract_timing(v, timings)
218        if name and time_v:
219          if v.find("SystemServerTimingAsync") > 0:
220            name = "(" + name + ")"
221          new_name = name
222          name_index = 0
223          while timing_points.get(new_name): # if the name is already taken, append #digit
224            name_index += 1
225            new_name = name + "#" + str(name_index)
226          name = new_name
227          if k.endswith("_secs"):
228            timing_points[name] = time_v * 1000.0
229          else:
230            timing_points[name] = time_v
231  return timing_points
232
233def dump_timing_points(msg_header, timing_points):
234    print msg_header + " event timing in time order, key: time"
235    for item in timing_points.items():
236      print '{0:30}: {1:<7.5}'.format(item[0], item[1])
237    print "-----------------"
238    print msg_header + " event timing top items"
239    for item in sorted(timing_points.items(), key=operator.itemgetter(1), reverse = True):
240      if item[1] < TIMING_THRESHOLD:
241        break
242      print '{0:30}: {1:<7.5}'.format(
243        item[0], item[1])
244    print "-----------------"
245
246def iterate(args, search_events, timings, cfg, error_time, components_to_monitor):
247  if args.reboot:
248    reboot(args.serial, args.stressfs != '', args.permissive, args.adb_reboot)
249
250  dmesg_events, kernel_timing_events = collect_events(search_events, ADB_CMD +\
251                                                      ' shell su root dmesg -w', timings,\
252                                                      [ KERNEL_BOOT_COMPLETE ], True)
253
254  logcat_stop_events = [ LOGCAT_BOOT_COMPLETE, KERNEL_BOOT_COMPLETE, LAUNCHER_START]
255  if args.fs_check:
256    logcat_stop_events.append("FsStat")
257  logcat_events, logcat_timing_events = collect_events(
258    search_events, ADB_CMD + ' logcat -b all -v epoch', timings, logcat_stop_events, False)
259  logcat_event_time = extract_time(
260    logcat_events, TIME_LOGCAT, float);
261  logcat_original_time = extract_time(
262    logcat_events, TIME_LOGCAT, str);
263  dmesg_event_time = extract_time(
264    dmesg_events, TIME_DMESG, float);
265  boottime_events = fetch_boottime_property()
266  events = {}
267  diff_time = 0
268  max_time = 0
269  events_to_correct = []
270  replaced_from_dmesg = set()
271
272  time_correction_delta = 0
273  time_correction_time = 0
274  if ('time_correction_key' in cfg
275      and cfg['time_correction_key'] in logcat_events):
276    match = search_events[cfg['time_correction_key']].search(
277      logcat_events[cfg['time_correction_key']])
278    if match and logcat_event_time[cfg['time_correction_key']]:
279      time_correction_delta = float(match.group(1))
280      time_correction_time = logcat_event_time[cfg['time_correction_key']]
281
282  debug("time_correction_delta = {0}, time_correction_time = {1}".format(
283    time_correction_delta, time_correction_time))
284
285  for k, v in logcat_event_time.iteritems():
286    if v <= time_correction_time:
287      logcat_event_time[k] += time_correction_delta
288      v = v + time_correction_delta
289      debug("correcting event to event[{0}, {1}]".format(k, v))
290
291  if not logcat_event_time.get(KERNEL_TIME_KEY):
292    print "kernel time not captured in logcat, cannot get time diff"
293    return None, None, None, None
294  diffs = []
295  diffs.append((logcat_event_time[KERNEL_TIME_KEY], logcat_event_time[KERNEL_TIME_KEY]))
296  if logcat_event_time.get(BOOT_ANIM_END_TIME_KEY) and dmesg_event_time.get(BOOT_ANIM_END_TIME_KEY):
297      diffs.append((logcat_event_time[BOOT_ANIM_END_TIME_KEY],\
298                    logcat_event_time[BOOT_ANIM_END_TIME_KEY] -\
299                      dmesg_event_time[BOOT_ANIM_END_TIME_KEY]))
300  if not dmesg_event_time.get(KERNEL_BOOT_COMPLETE):
301      print "BootAnimEnd time or BootComplete-kernel not captured in both log" +\
302        ", cannot get time diff"
303      return None, None, None, None
304  diffs.append((logcat_event_time[KERNEL_BOOT_COMPLETE],\
305                logcat_event_time[KERNEL_BOOT_COMPLETE] - dmesg_event_time[KERNEL_BOOT_COMPLETE]))
306
307  for k, v in logcat_event_time.iteritems():
308    debug("event[{0}, {1}]".format(k, v))
309    events[k] = v
310    if k in dmesg_event_time:
311      debug("{0} is in dmesg".format(k))
312      events[k] = dmesg_event_time[k]
313      replaced_from_dmesg.add(k)
314    else:
315      events_to_correct.append(k)
316
317  diff_prev = diffs[0]
318  for k in events_to_correct:
319    diff = diffs[0]
320    while diff[0] < events[k] and len(diffs) > 1:
321      diffs.pop(0)
322      diff_prev = diff
323      diff = diffs[0]
324    events[k] = events[k] - diff[1]
325    if events[k] < 0.0:
326        if events[k] < -0.1: # maybe previous one is better fit
327          events[k] = events[k] + diff[1] - diff_prev[1]
328        else:
329          events[k] = 0.0
330
331  data_points = collections.OrderedDict()
332
333  print "-----------------"
334  print "ro.boottime.*: time"
335  for item in boottime_events.items():
336    print '{0:30}: {1:<7.5} {2}'.format(item[0], item[1],\
337      "*time taken" if item[0].startswith("init.") else "")
338  print "-----------------"
339
340  if args.timings:
341    kernel_timing_points = generate_timing_points(kernel_timing_events, timings)
342    logcat_timing_points = generate_timing_points(logcat_timing_events, timings)
343    dump_timing_points("Kernel", kernel_timing_points)
344    dump_timing_points("Logcat", logcat_timing_points)
345
346  for item in sorted(events.items(), key=operator.itemgetter(1)):
347    data_points[item[0]] = {
348      'value': item[1],
349      'from_dmesg': item[0] in replaced_from_dmesg,
350      'logcat_value': logcat_original_time[item[0]]
351    }
352  # add times with bootloader
353  if events.get("BootComplete") and boottime_events.get("bootloader"):
354    total = events["BootComplete"] + boottime_events["bootloader"]
355    data_points["*BootComplete+Bootloader"] = {
356      'value': total,
357      'from_dmesg': False,
358      'logcat_value': 0.0
359    }
360  if events.get("LauncherStart") and boottime_events.get("bootloader"):
361    total = events["LauncherStart"] + boottime_events["bootloader"]
362    data_points["*LauncherStart+Bootloader"] = {
363      'value': total,
364      'from_dmesg': False,
365      'logcat_value': 0.0
366    }
367  for k, v in data_points.iteritems():
368    print '{0:30}: {1:<7.5} {2:1} ({3})'.format(
369      k, v['value'], '*' if v['from_dmesg'] else '', v['logcat_value'])
370
371  print '\n* - event time was obtained from dmesg log\n'
372
373  if events[LOGCAT_BOOT_COMPLETE] > error_time and not args.ignore:
374    capture_bugreport("bootuptoolong", events[LOGCAT_BOOT_COMPLETE])
375
376  for k, v in components_to_monitor.iteritems():
377    logcat_value_measured = logcat_timing_points.get(k)
378    kernel_value_measured = kernel_timing_points.get(k)
379    data_from_data_points = data_points.get(k)
380    if logcat_value_measured and logcat_value_measured > v:
381      capture_bugreport(k + "-" + str(logcat_value_measured), events[LOGCAT_BOOT_COMPLETE])
382      break
383    elif kernel_value_measured and kernel_value_measured > v:
384      capture_bugreport(k + "-" + str(kernel_value_measured), events[LOGCAT_BOOT_COMPLETE])
385      break
386    elif data_from_data_points and data_from_data_points['value'] * 1000.0 > v:
387      capture_bugreport(k + "-" + str(data_from_data_points['value']), events[LOGCAT_BOOT_COMPLETE])
388      break
389
390  if args.fs_check:
391    fs_stat = None
392    if logcat_events.get("FsStat"):
393      fs_stat_pattern = cfg["events"]["FsStat"]
394      m = re.search(fs_stat_pattern, logcat_events.get("FsStat"))
395      if m:
396        fs_stat = m.group(1)
397    print 'fs_stat:', fs_stat
398
399    if fs_stat:
400      fs_stat_val = int(fs_stat, 0)
401      if (fs_stat_val & ~0x17) != 0:
402        capture_bugreport("fs_stat_" + fs_stat, events[LOGCAT_BOOT_COMPLETE])
403
404  return data_points, kernel_timing_points, logcat_timing_points, boottime_events
405
406def debug(string):
407  if DEBUG:
408    print string
409
410def extract_timing(s, patterns):
411  for k, p in patterns.iteritems():
412    m = p.search(s)
413    if m:
414      g_dict = m.groupdict()
415      return g_dict['name'], float(g_dict['time'])
416  return None, None
417
418def init_arguments():
419  parser = argparse.ArgumentParser(description='Measures boot time.')
420  parser.add_argument('-r', '--reboot', dest='reboot',
421                      action='store_true',
422                      help='reboot device for measurement', )
423  parser.add_argument('-c', '--config', dest='config',
424                      default='config.yaml', type=argparse.FileType('r'),
425                      help='config file for the tool', )
426  parser.add_argument('-s', '--stressfs', dest='stressfs',
427                      default='', type=str,
428                      help='APK file for the stressfs tool used to write to the data partition ' +\
429                           'during shutdown')
430  parser.add_argument('-n', '--iterate', dest='iterate', type=int, default=1,
431                      help='number of time to repeat the measurement', )
432  parser.add_argument('-g', '--ignore', dest='ignore', action='store_true',
433                      help='ignore too big values error', )
434  parser.add_argument('-t', '--timings', dest='timings', action='store_true',
435                      help='print individual component times', default=True, )
436  parser.add_argument('-p', '--serial', dest='serial', action='store',
437                      help='android device serial number')
438  parser.add_argument('-e', '--errortime', dest='errortime', action='store',
439                      help='handle bootup time bigger than this as error')
440  parser.add_argument('-w', '--maxwaittime', dest='maxwaittime', action='store',
441                      help='wait for up to this time to collect logs. Retry after this time.' +\
442                           ' Default is 200 sec.')
443  parser.add_argument('-f', '--fs_check', dest='fs_check',
444                      action='store_true',
445                      help='check fs_stat after reboot', )
446  parser.add_argument('-a', '--adb_reboot', dest='adb_reboot',
447                      action='store_true',
448                      help='reboot with adb reboot', )
449  parser.add_argument('-v', '--permissive', dest='permissive',
450                      action='store_true',
451                      help='set selinux into permissive before reboot', )
452  parser.add_argument('-m', '--componentmonitor', dest='componentmonitor', action='store',
453                      help='capture bugreport if specified timing component is taking more than ' +\
454                           'certain time. Unlike errortime, the result will not be rejected in' +\
455                           'averaging. Format is key1=time1,key2=time2...')
456  parser.add_argument('-b', '--bootchart', dest='bootchart',
457                      action='store_true',
458                      help='collect bootchart from the device.', )
459  parser.add_argument('-y', '--systrace', dest='systrace',
460                      action='store_true',
461                      help='collect systrace from the device. kernel trace should be already enabled', )
462  return parser.parse_args()
463
464def handle_zygote_event(zygote_pids, events, event, line):
465  words = line.split()
466  if len(words) > 1:
467    pid = int(words[1])
468    if len(zygote_pids) == 2:
469      if pid == zygote_pids[1]: # secondary
470        event = event + "-secondary"
471    elif len(zygote_pids) == 1:
472      if zygote_pids[0] != pid: # new pid, need to decide if old ones were secondary
473        primary_pid = min(pid, zygote_pids[0])
474        secondary_pid = max(pid, zygote_pids[0])
475        zygote_pids.pop()
476        zygote_pids.append(primary_pid)
477        zygote_pids.append(secondary_pid)
478        if pid == primary_pid: # old one was secondary:
479          move_to_secondary = []
480          for k, l in events.iteritems():
481            if k.startswith("zygote"):
482              move_to_secondary.append((k, l))
483          for item in move_to_secondary:
484            del events[item[0]]
485            if item[0].endswith("-secondary"):
486              print "Secondary already exists for event %s  while found new pid %d, primary %d "\
487                % (item[0], secondary_pid, primary_pid)
488            else:
489              events[item[0] + "-secondary"] = item[1]
490        else:
491          event = event + "-secondary"
492    else:
493      zygote_pids.append(pid)
494  events[event] = line
495
496def update_name_if_already_exist(events, name):
497  existing_event = events.get(name)
498  i = 0
499  new_name = name
500  while existing_event:
501    i += 1
502    new_name = name + "_" + str(i)
503    existing_event = events.get(new_name)
504  return new_name
505
506def collect_events(search_events, command, timings, stop_events, disable_timing_after_zygote):
507  events = collections.OrderedDict()
508  timing_events = {}
509  process = subprocess.Popen(command, shell=True,
510                             stdout=subprocess.PIPE);
511  data_available = stop_events is None
512  zygote_pids = []
513  start_time = time.time()
514  zygote_found = False
515
516  line = None
517  read_poll = select.poll()
518  read_poll.register(process.stdout, select.POLLIN)
519  while True:
520    time_left = start_time + max_wait_time - time.time()
521    if time_left <= 0:
522      print "timeout waiting for event, continue", time_left
523      break
524    read_r = read_poll.poll(time_left * 1000.0)
525    if read_r:
526        line = process.stdout.readline()
527    else:
528      print "poll timeout waiting for event, continue", time_left
529      break
530    if not data_available:
531      print "Collecting data samples from '%s'. Please wait...\n" % command
532      data_available = True
533    event = get_boot_event(line, search_events);
534    if event:
535      debug("event[{0}] captured: {1}".format(event, line))
536      if event == "starting_zygote":
537        events[event] = line
538        zygote_found = True
539      elif event.startswith("zygote"):
540        handle_zygote_event(zygote_pids, events, event, line)
541      else:
542        new_event = update_name_if_already_exist(events, event)
543        events[new_event] = line
544      if event in stop_events:
545        stop_events.remove(event)
546        print "remaining stop_events:", stop_events
547        if len(stop_events) == 0:
548          break;
549
550    timing_event = get_boot_event(line, timings);
551    if timing_event and (not disable_timing_after_zygote or not zygote_found):
552      if timing_event not in timing_events:
553        timing_events[timing_event] = []
554      timing_events[timing_event].append(line)
555      debug("timing_event[{0}] captured: {1}".format(timing_event, line))
556
557  process.terminate()
558  return events, timing_events
559
560def fetch_boottime_property():
561  cmd = ADB_CMD + ' shell su root getprop'
562  events = {}
563  process = subprocess.Popen(cmd, shell=True,
564                             stdout=subprocess.PIPE);
565  out = process.stdout
566  pattern = re.compile(BOOT_PROP)
567  pattern_bootloader = re.compile(BOOTLOADER_TIME_PROP)
568  bootloader_time = 0.0
569  for line in out:
570    match = pattern.match(line)
571    if match:
572      if match.group(1).startswith("init."):
573        events[match.group(1)] = float(match.group(2)) / 1000.0 #ms to s
574      else:
575        events[match.group(1)] = float(match.group(2)) / 1000000000.0 #ns to s
576    match = pattern_bootloader.match(line)
577    if match:
578      items = match.group(1).split(",")
579      for item in items:
580        entry_pair = item.split(":")
581        entry_name = entry_pair[0]
582        time_spent = float(entry_pair[1]) / 1000 #ms to s
583        if entry_name != "SW":
584          bootloader_time = bootloader_time + time_spent
585  ordered_event = collections.OrderedDict()
586  if bootloader_time != 0.0:
587    ordered_event["bootloader"] = bootloader_time;
588  for item in sorted(events.items(), key=operator.itemgetter(1)):
589    ordered_event[item[0]] = item[1]
590  return ordered_event
591
592
593def get_boot_event(line, events):
594  for event_key, event_pattern in events.iteritems():
595    if event_pattern.search(line):
596      return event_key
597  return None
598
599def extract_a_time(line, pattern, date_transform_function):
600    found = re.findall(pattern, line)
601    if len(found) > 0:
602      return date_transform_function(found[0])
603    else:
604      return None
605
606def extract_time(events, pattern, date_transform_function):
607  result = collections.OrderedDict()
608  for event, data in events.iteritems():
609    time = extract_a_time(data, pattern, date_transform_function)
610    if time:
611      result[event] = time
612    else:
613      print "Failed to find time for event: ", event, data
614  return result
615
616
617def do_reboot(serial, use_adb_reboot):
618  original_devices = subprocess.check_output("adb devices", shell=True)
619  if use_adb_reboot:
620    print 'Rebooting the device using adb reboot'
621    run_adb_cmd('reboot')
622  else:
623    print 'Rebooting the device using svc power reboot'
624    run_adb_shell_cmd_as_root('svc power reboot')
625  # Wait for the device to go away
626  retry = 0
627  while retry < 20:
628    current_devices = subprocess.check_output("adb devices", shell=True)
629    if original_devices != current_devices:
630      if not serial or (serial and current_devices.find(serial) < 0):
631        return True
632    time.sleep(1)
633    retry += 1
634  return False
635
636def reboot(serial, use_stressfs, permissive, use_adb_reboot):
637  if use_stressfs:
638    print 'Starting write to data partition'
639    run_adb_shell_cmd('am start' +\
640                      ' -n com.android.car.test.stressfs/.WritingActivity' +\
641                      ' -a com.android.car.test.stressfs.START')
642    # Give this app some time to start.
643    time.sleep(1)
644  if permissive:
645    run_adb_shell_cmd_as_root('setenforce 0')
646
647  retry = 0
648  while retry < 5:
649    if do_reboot(serial, use_adb_reboot):
650      break
651    retry += 1
652
653  print 'Waiting the device'
654  run_adb_cmd('wait-for-device')
655
656def run_adb_cmd(cmd):
657  return subprocess.call(ADB_CMD + ' ' + cmd, shell=True)
658
659def run_adb_shell_cmd(cmd):
660  return subprocess.call(ADB_CMD + ' shell ' + cmd, shell=True)
661
662def run_adb_shell_cmd_as_root(cmd):
663  return subprocess.call(ADB_CMD + ' shell su root ' + cmd, shell=True)
664
665def logcat_time_func(offset_year):
666  def f(date_str):
667    ndate = datetime.datetime.strptime(str(offset_year) + '-' +
668                                 date_str, '%Y-%m-%d %H:%M:%S.%f')
669    return datetime_to_unix_time(ndate)
670  return f
671
672def datetime_to_unix_time(ndate):
673  return time.mktime(ndate.timetuple()) + ndate.microsecond/1000000.0
674
675def stddev(data):
676  items_count = len(data)
677  avg = sum(data) / items_count
678  sq_diffs_sum = sum([(v - avg) ** 2 for v in data])
679  variance = sq_diffs_sum / items_count
680  return math.sqrt(variance)
681
682def grab_bootchart(boot_chart_file_name):
683  subprocess.call("./system/core/init/grab-bootchart.sh", shell=True)
684  print "Saving boot chart as " + boot_chart_file_name + ".tgz"
685  subprocess.call('cp /tmp/android-bootchart/bootchart.tgz ./' + boot_chart_file_name + '.tgz',\
686                  shell=True)
687  subprocess.call('cp ./bootchart.png ./' + boot_chart_file_name + '.png', shell=True)
688
689def grab_systrace(systrace_file_name):
690  trace_file = systrace_file_name + "_trace.txt"
691  with open(trace_file, 'w') as f:
692    f.write("TRACE:\n")
693  run_adb_shell_cmd_as_root("cat /d/tracing/trace >> " + trace_file)
694  html_file = systrace_file_name + ".html"
695  subprocess.call("./external/chromium-trace/systrace.py --from-file=" + trace_file + " -o " +\
696                  html_file, shell=True)
697
698if __name__ == '__main__':
699  main()
700