Add logblame and some log buffer tests.

A utility to read a logcat and print statistics about who is spamming the log.
And tests that use it

Bug: 37252687
Test: ./test_analyze.py ; test_logs.py ; test_ps.py
Change-Id: I811ba482b4be9779047f97c3f3b7ea5f996bd503

tools/logblame/analyze_logs.py

@@ -0,0 +1,262 @@
+#!/usr/bin/env python2.7
+
+import argparse
+import datetime
+import re
+import subprocess
+import sys
+
+import logs
+import ps
+
+DURATION_RE = re.compile("((\\d+)w)?((\\d+)d)?((\\d+)h)?((\\d+)m)?((\\d+)s)?")
+
+class Bucket(object):
+  """Bucket of stats for a particular key managed by the Stats object."""
+  def __init__(self):
+    self.count = 0
+    self.memory = 0
+    self.lines = []
+
+  def __str__(self):
+    return "(%s,%s)" % (self.count, self.memory)
+
+
+class Stats(object):
+  """A group of stats with a particular key, where both memory and count are tracked."""
+  def __init__(self):
+    self._data = dict()
+
+  def add(self, key, logLine):
+    bucket = self._data.get(key)
+    if not bucket:
+      bucket = Bucket()
+      self._data[key] = bucket
+    bucket.count += 1
+    bucket.memory += logLine.memory()
+    bucket.lines.append(logLine)
+
+  def __iter__(self):
+    return self._data.iteritems()
+
+  def data(self):
+    return [(key, bucket) for key, bucket in self._data.iteritems()]
+
+  def byCount(self):
+    result = self.data()
+    result.sort(lambda a, b: -cmp(a[1].count, b[1].count))
+    return result
+
+  def byMemory(self):
+    result = self.data()
+    result.sort(lambda a, b: -cmp(a[1].memory, b[1].memory))
+    return result
+
+
+def ParseDuration(s):
+  """Parse a date of the format .w.d.h.m.s into the number of seconds."""
+  def make_int(index):
+    val = m.group(index)
+    if val:
+      return int(val)
+    else:
+      return 0
+  m = DURATION_RE.match(s)
+  if m:
+    weeks = make_int(2)
+    days = make_int(4)
+    hours = make_int(6)
+    minutes = make_int(8)
+    seconds = make_int(10)
+    return (weeks * 604800) + (days * 86400) + (hours * 3600) + (minutes * 60) + seconds
+  return 0
+
+def FormatMemory(n):
+  """Prettify the number of bytes into gb, mb, etc."""
+  if n >= 1024 * 1024 * 1024:
+    return "%10d gb" % (n / (1024 * 1024 * 1024))
+  elif n >= 1024 * 1024:
+    return "%10d mb" % (n / (1024 * 1024))
+  elif n >= 1024:
+    return "%10d kb" % (n / 1024)
+  else:
+    return "%10d b " % n
+
+def FormateTimeDelta(td):
+  """Format a time duration into the same format we accept on the commandline."""
+  seconds = (td.days * 86400) + (td.seconds) + int(td.microseconds / 1000000)
+  if seconds == 0:
+    return "0s"
+  result = ""
+  if seconds >= 604800:
+    weeks = int(seconds / 604800)
+    seconds -= weeks * 604800
+    result += "%dw" % weeks
+  if seconds >= 86400:
+    days = int(seconds / 86400)
+    seconds -= days * 86400
+    result += "%dd" % days
+  if seconds >= 3600:
+    hours = int(seconds / 3600)
+    seconds -= hours * 3600
+    result += "%dd" % hours
+  if seconds >= 60:
+    minutes = int(seconds / 60)
+    seconds -= minutes * 60
+    result += "%dh" % minutes
+  if seconds > 0:
+    result += "%ds" % seconds
+  return result
+
+
+def WriteResult(totalCount, totalMemory, bucket, text):
+  """Write a bucket in the normalized format."""
+  print "%7d (%2d%%) %s (%2d%%)  %s" % (bucket.count, (100 * bucket.count / totalCount),
+      FormatMemory(bucket.memory), (100 * bucket.memory / totalMemory), text)
+  
+
+def ParseArgs(argv):
+  parser = argparse.ArgumentParser(description="Process some integers.")
+  parser.add_argument("input", type=str, nargs="?",
+                      help="the logs file to read")
+  parser.add_argument("--clear", action="store_true",
+                      help="clear the log buffer before running logcat")
+  parser.add_argument("--duration", type=str, nargs=1,
+                      help="how long to run for (XdXhXmXs)")
+  parser.add_argument("--rawlogs", type=str, nargs=1,
+                      help="file to put the rawlogs into")
+
+  args = parser.parse_args()
+
+  args.durationSec = ParseDuration(args.duration[0]) if args.duration else 0
+
+  return args
+
+
+def main(argv):
+  args = ParseArgs(argv)
+
+  processes = ps.ProcessSet()
+
+  if args.rawlogs:
+    rawlogs = file(args.rawlogs[0], "w")
+  else:
+    rawlogs = None
+
+  # Choose the input
+  if args.input:
+    # From a file of raw logs
+    try:
+      infile = file(args.input, "r")
+    except IOError:
+      sys.stderr.write("Error opening file for read: %s\n" % args.input[0])
+      sys.exit(1)
+  else:
+    # From running adb logcat on an attached device
+    if args.clear:
+      subprocess.check_call(["adb", "logcat", "-c"])
+    cmd = ["adb", "logcat", "-v", "long", "-D", "-v", "uid"]
+    if not args.durationSec:
+      cmd.append("-d")
+    logcat = subprocess.Popen(cmd, stdout=subprocess.PIPE)
+    infile = logcat.stdout
+
+    # Do one update because we know we'll need it, but then don't do it again
+    # if we're not streaming them.
+    processes.Update(True)
+    if args.durationSec:
+      processes.doUpdates = True
+
+  totalCount = 0
+  totalMemory = 0
+  byTag = Stats()
+  byPid = Stats()
+  byText = Stats()
+
+  startTime = datetime.datetime.now()
+
+  # Read the log lines from the parser and build a big mapping of everything
+  for logLine in logs.ParseLogcat(infile, processes, args.durationSec):
+    if rawlogs:
+      rawlogs.write("%-10s %s %-6s %-6s %-6s %s/%s: %s\n" %(logLine.buf, logLine.timestamp,
+          logLine.uid, logLine.pid, logLine.tid, logLine.level, logLine.tag, logLine.text))
+    
+    totalCount += 1
+    totalMemory += logLine.memory()
+    byTag.add(logLine.tag, logLine)
+    byPid.add(logLine.pid, logLine)
+    byText.add(logLine.text, logLine)
+
+  endTime = datetime.datetime.now()
+
+  # Print the log analysis
+
+  # At this point, everything is loaded, don't bother looking
+  # for new processes
+  processes.doUpdates = False
+
+  print "Top tags by count"
+  print "-----------------"
+  i = 0
+  for k,v in byTag.byCount():
+    WriteResult(totalCount, totalMemory, v, k)
+    if i >= 10:
+      break
+    i += 1
+
+  print
+  print "Top tags by memory"
+  print "------------------"
+  i = 0
+  for k,v in byTag.byMemory():
+    WriteResult(totalCount, totalMemory, v, k)
+    if i >= 10:
+      break
+    i += 1
+
+  print
+  print "Top Processes by memory"
+  print "-----------------------"
+  i = 0
+  for k,v in byPid.byMemory():
+    WriteResult(totalCount, totalMemory, v,
+        "%-8s %s" % (k, processes.FindPid(k).DisplayName()))
+    if i >= 10:
+      break
+    i += 1
+
+  print
+  print "Top Duplicates by count"
+  print "-----------------------"
+  i = 0
+  for k,v in byText.byCount():
+    logLine = v.lines[0]
+    WriteResult(totalCount, totalMemory, v,
+        "%s/%s: %s" % (logLine.level, logLine.tag, logLine.text))
+    if i >= 10:
+      break
+    i += 1
+
+  print
+  print "Top Duplicates by memory"
+  print "-----------------------"
+  i = 0
+  for k,v in byText.byCount():
+    logLine = v.lines[0]
+    WriteResult(totalCount, totalMemory, v,
+        "%s/%s: %s" % (logLine.level, logLine.tag, logLine.text))
+    if i >= 10:
+      break
+    i += 1
+
+  print
+  print "Totals"
+  print "------"
+  print "%7d  %s" % (totalCount, FormatMemory(totalMemory))
+
+  print "Actual duration: %s" % FormateTimeDelta(endTime-startTime)
+
+if __name__ == "__main__":
+  main(sys.argv)
+
+# vim: set ts=2 sw=2 sts=2 tw=100 nocindent autoindent smartindent expandtab:

tools/logblame/app_switch_test

@@ -0,0 +1,72 @@
+#!/bin/bash
+
+# The intents to launch
+INTENTS="\
+     com.google.android.googlequicksearchbox/.SearchActivity \
+     com.android.settings/.Settings \
+     com.google.android.apps.messaging/.ui.ConversationListActivity \
+     com.google.android.calculator/com.android.calculator2.Calculator \
+     com.google.android.deskclock/com.android.deskclock.DeskClock \
+     com.google.android.contacts/com.android.contacts.activities.PeopleActivity \
+     com.google.android.talk/.SigningInActivity \
+     com.google.android.vr.home/com.google.android.apps.vr.home.app.MainActivity \
+     com.android.documentsui/.Launcher \
+     com.google.android.apps.nexuslauncher/.NexusLauncherActivity \
+  "
+#     com.google.android.GoogleCamera/com.android.camera.CameraActivity \
+
+# The files to save output to.
+RAWLOGS_FILE=app-switch-rawlogs.txt
+ANALYSIS_FILE=app-switch-analysis.txt
+
+
+# Turn on the screen and unlock the device
+# TODO: Power on
+adb shell wm dismiss-keyguard
+adb logcat -P ""
+
+# Turn on airplane mode (to reduce background noise caught by other tests)
+airplane_mode_was_on=$(adb shell settings get global airplane_mode_on)
+if [ $airplane_mode_was_on != 1 ] ; then
+    adb shell settings put global airplane_mode_on 1 > /dev/null
+    adb shell am broadcast -a android.intent.action.AIRPLANE_MODE > /dev/null
+    sleep 15
+fi
+
+# Start the analysis process
+$TOP/development/tools/logblame/analyze_logs.py --duration=10m --clear --rawlogs $RAWLOGS_FILE \
+    | tee $ANALYSIS_FILE &
+analyze_pid=$!
+
+# Launch the intents with a 3s gap between them
+for intent in $INTENTS
+do
+    echo Starting: $intent
+    adb shell am start -a android.intent.action.MAIN $intent
+    sleep 4
+done
+
+# Turn the screen off and on
+adb shell input keyevent 26
+adb shell input keyevent 26
+adb shell wm dismiss-keyguard
+
+echo
+echo
+
+# Kill adb to disconnect logcat
+adb kill-server
+
+# Wait for the pyton process to exit
+wait $analyze_pid
+
+# Turn airplane mode back off
+if [ $airplane_mode_was_on == 0 ] ; then
+    adb shell settings put global airplane_mode_on 0 > /dev/null
+    adb shell am broadcast -a android.intent.action.AIRPLANE_MODE > /dev/null
+fi
+
+echo "Wrote raw logs to $RAWLOGS_FILE"
+echo "Wrote analysis to $ANALYSIS_FILE"
+
+

tools/logblame/connectivity_log_test

@@ -0,0 +1,58 @@
+#!/bin/bash
+
+# The files to save output to.
+RAWLOGS_FILE=connectivity-rawlogs.txt
+ANALYSIS_FILE=connectivity-analysis.txt
+
+# Turn on the screen and unlock the device
+# TODO: Power on
+adb shell wm dismiss-keyguard
+adb logcat -P ""
+
+airplane_mode_was_on=$(adb shell settings get global airplane_mode_on)
+if [ $airplane_mode_was_on == 1 ] ; then
+    adb shell settings put global airplane_mode_on 0 > /dev/null
+    adb shell am broadcast -a android.intent.action.AIRPLANE_MODE > /dev/null
+    sleep 30
+fi
+
+# Start the analysis process
+$TOP/development/tools/logblame/analyze_logs.py --duration=10m --clear --rawlogs $RAWLOGS_FILE \
+    | tee $ANALYSIS_FILE &
+analyze_pid=$!
+
+# Turn on airplane mode and wait for it to settle
+echo "Turning on airplane mode."
+adb shell settings put global airplane_mode_on 1 > /dev/null
+adb shell am broadcast -a android.intent.action.AIRPLANE_MODE > /dev/null
+sleep 15
+
+# Turn off airplane mode and wait for it to settle
+echo "Turning off airplane mode."
+adb shell settings put global airplane_mode_on 0 > /dev/null
+adb shell am broadcast -a android.intent.action.AIRPLANE_MODE > /dev/null
+sleep 45
+
+# Turn off wifi and then back on
+echo "Turning wifi off"
+adb shell svc wifi disable
+sleep 15
+
+echo "Turning wifi on"
+adb shell svc wifi enable
+sleep 15
+
+
+echo
+echo
+
+# Kill adb to disconnect logcat
+adb kill-server
+
+# Wait for the pyton process to exit
+wait $analyze_pid
+
+echo "Wrote raw logs to $RAWLOGS_FILE"
+echo "Wrote analysis to $ANALYSIS_FILE"
+
+

tools/logblame/logs.py

@@ -0,0 +1,162 @@
+
+import datetime
+import re
+
+BUFFER_BEGIN = re.compile("^--------- beginning of (.*)$")
+BUFFER_SWITCH = re.compile("^--------- switch to (.*)$")
+HEADER = re.compile("^\\[ (\\d\\d-\\d\\d \\d\\d:\\d\\d:\\d\\d.\\d\\d\\d) +(.+?): *(\\d+): *(\\d+) *([EWIDV])/(.*?) *\\]$")
+CHATTY_IDENTICAL = re.compile("^.* identical (\\d+) lines$")
+
+STATE_BEGIN = 0
+STATE_BUFFER = 1
+STATE_HEADER = 2
+STATE_TEXT = 3
+STATE_BLANK = 4
+
+class LogLine(object):
+  """Represents a line of android logs."""
+  def __init__(self, buf=None, timestamp=None, uid=None, pid=None, tid=None, level=None,
+      tag=None, text=""):
+    self.buf = buf
+    self.timestamp = timestamp
+    self.uid = uid
+    self.pid = pid
+    self.tid = tid
+    self.level = level
+    self.tag = tag
+    self.text = text
+    self.process = None
+
+  def __str__(self):
+    return "{%s} {%s} {%s} {%s} {%s} {%s}/{%s}: {%s}" % (self.buf, self.timestamp, self.uid,
+        self.pid, self.tid, self.level, self.tag, self.text)
+
+  def __eq__(self, other):
+      return (
+            self.buf == other.buf
+            and self.timestamp == other.timestamp 
+            and self.uid == other.uid 
+            and self.pid == other.pid 
+            and self.tid == other.tid 
+            and self.level == other.level 
+            and self.tag == other.tag 
+            and self.text == other.text 
+          )
+
+  def clone(self):
+    logLine = LogLine(self.buf, self.timestamp, self.uid, self.pid, self.tid, self.level,
+        self.tag, self.text)
+    logLine.process = self.process
+    return logLine
+
+  def memory(self):
+    """Return an estimate of how much memory is used for the log.
+      32 bytes of header + 8 bytes for the pointer + the length of the tag and the text.
+      This ignores the overhead of the list of log lines itself."""
+    return 32 + 8 + len(self.tag) + 1 + len(self.text) + 1
+
+
+def ParseLogcat(f, processes, duration=None):
+  previous = None
+  for logLine in ParseLogcatInner(f, processes, duration):
+    if logLine.tag == "chatty" and logLine.level == "I":
+      m = CHATTY_IDENTICAL.match(logLine.text)
+      if m:
+        for i in range(int(m.group(1))):
+          clone = previous.clone()
+          clone.timestamp = logLine.timestamp
+          yield clone
+        continue
+    previous = logLine
+    yield logLine
+
+
+def ParseLogcatInner(f, processes, duration=None):
+  """Parses a file object containing log text and returns a list of LogLine objects."""
+  result = []
+
+  buf = None
+  timestamp = None
+  uid = None
+  pid = None
+  tid = None
+  level = None
+  tag = None
+
+  state = STATE_BEGIN
+  logLine = None
+  previous = None
+
+  if duration:
+    endTime = datetime.datetime.now() + datetime.timedelta(seconds=duration)
+
+  # TODO: use a nonblocking / timeout read so we stop if there are
+  # no logs coming out (haha joke, right!)
+  for line in f:
+    if duration and endTime <= datetime.datetime.now():
+      break
+
+    if len(line) > 0 and line[-1] == '\n':
+      line = line[0:-1]
+
+    m = BUFFER_BEGIN.match(line)
+    if m:
+      if logLine:
+        yield logLine
+        logLine = None
+      buf = m.group(1)
+      state = STATE_BUFFER
+      continue
+
+    m = BUFFER_SWITCH.match(line)
+    if m:
+      if logLine:
+        yield logLine
+        logLine = None
+      buf = m.group(1)
+      state = STATE_BUFFER
+      continue
+
+    m = HEADER.match(line)
+    if m:
+      if logLine:
+        yield logLine
+      logLine = LogLine(
+            buf=buf,
+            timestamp=m.group(1),
+            uid=m.group(2),
+            pid=m.group(3),
+            tid=m.group(4),
+            level=m.group(5),
+            tag=m.group(6)
+          )
+      previous = logLine
+      logLine.process = processes.FindPid(logLine.pid, logLine.uid)
+      state = STATE_HEADER
+      continue
+
+    if not len(line):
+      if state == STATE_BLANK:
+        if logLine:
+          logLine.text += "\n"
+      state = STATE_BLANK
+      continue
+
+    if logLine:
+      if state == STATE_HEADER:
+        logLine.text += line
+      elif state == STATE_TEXT:
+        logLine.text += "\n"
+        logLine.text += line
+      elif state == STATE_BLANK:
+        if len(logLine.text):
+          logLine.text += "\n"
+        logLine.text += "\n"
+        logLine.text += line
+    state = STATE_TEXT
+
+  if logLine:
+    yield logLine
+
+
+# vim: set ts=2 sw=2 sts=2 tw=100 nocindent autoindent smartindent expandtab:

tools/logblame/medium_idle_test

@@ -0,0 +1,23 @@
+#!/bin/bash
+
+# The files to save output to.
+RAWLOGS_FILE=medium-idle-rawlogs.txt
+ANALYSIS_FILE=medium-idle-analysis.txt
+
+# Turn on the screen and unlock the device
+# TODO: Power on
+adb shell wm dismiss-keyguard
+
+# Start the analysis process
+$TOP/development/tools/logblame/analyze_logs.py --duration=4h --clear --rawlogs $RAWLOGS_FILE \
+    | tee $ANALYSIS_FILE &
+analyze_pid=$!
+
+# Wait for the pyton process to exit
+echo "waiting... analyze_pid" $analyze_pid
+wait $analyze_pid
+
+echo "Wrote raw logs to $RAWLOGS_FILE"
+echo "Wrote analysis to $ANALYSIS_FILE"
+
+

tools/logblame/power_toggle_test

@@ -0,0 +1,35 @@
+#!/bin/bash
+
+# The files to save output to.
+RAWLOGS_FILE=power-toggle-rawlogs.txt
+ANALYSIS_FILE=power-toggle-analysis.txt
+
+
+# Turn on the screen and unlock the device
+# TODO: Power on
+adb shell wm dismiss-keyguard
+adb logcat -P ""
+
+# Start the analysis process
+$TOP/development/tools/logblame/analyze_logs.py --duration=10m --clear --rawlogs $RAWLOGS_FILE \
+    | tee $ANALYSIS_FILE &
+analyze_pid=$!
+
+sleep 5
+for i in {0..10..1}; do
+    adb shell input keyevent KEYCODE_POWER
+    sleep 5
+    adb shell wm dismiss-keyguard
+    sleep 5
+done
+
+# Kill adb to disconnect logcat
+adb kill-server
+
+# Wait for the pyton process to exit
+wait $analyze_pid
+
+echo "Wrote raw logs to $RAWLOGS_FILE"
+echo "Wrote analysis to $ANALYSIS_FILE"
+
+

tools/logblame/ps.py

@@ -0,0 +1,142 @@
+import csv
+import re
+import subprocess
+
+HEADER_RE = re.compile("USER\\s*PID\\s*PPID\\s*VSIZE\\s*RSS\\s*WCHAN\\s*PC\\s*NAME")
+PROCESS_RE = re.compile("(\\S+)\\s+(\\d+)\\s+(\\d+)\\s+\\d+\\s+\\d+\\s+\\S+\\s+.\\S+\\s+\\S+\\s+(.*)")
+
+ANDROID_UID_RE = re.compile("u(\\d)+_([0-9a-fA-F]+)")
+UID_RE = re.compile("(\\d)+")
+
+class Process(object):
+  def __init__(self, uid, pid, ppid, name):
+    self.uid = uid
+    self.pid = pid
+    self.ppid = ppid
+    self.name = name
+
+  def DisplayName(self):
+    if self.name:
+      return self.name
+    if self.uid:
+      return self.uid.name
+    return self.pid
+
+  def __str__(self):
+    return "Process(uid=%s, pid=%s, name=%s)" % (self.uid, self.pid, self.name)
+
+class Uid(object):
+  def __init__(self, uid, name):
+    self.uid = uid
+    self.name = name
+
+  def __str__(self):
+    return "Uid(id=%s, name=%s)" % (self.uid, self.name)
+
+class ProcessSet(object):
+  def __init__(self):
+    self._processes = dict()
+    self._uids = dict()
+    self._pidUpdateCount = 0
+    self._uidUpdateCount = 0
+    self.doUpdates = False
+
+  def Update(self, force=False):
+    self.UpdateUids(force)
+    self.UpdateProcesses(force)
+
+  def UpdateProcesses(self, force=False):
+    if not (self.doUpdates or force):
+      return
+    self._pidUpdateCount += 1
+    try:
+      text = subprocess.check_output(["adb", "shell", "ps"])
+    except subprocess.CalledProcessError:
+      return # oh well. we won't get the pid
+    lines = ParsePs(text)
+    for line in lines:
+      if not self._processes.has_key(line[1]):
+        uid = self.FindUid(ParseUid(line[0]))
+        self._processes[line[1]] = Process(uid, line[1], line[2], line[3])
+
+  def UpdateUids(self, force=False):
+    if not (self.doUpdates or force):
+      return
+    self._uidUpdateCount += 1
+    try:
+      text = subprocess.check_output(["adb", "shell", "dumpsys", "package", "--checkin"])
+    except subprocess.CalledProcessError:
+      return # oh well. we won't get the pid
+    lines = ParseUids(text)
+    for line in lines:
+      if not self._uids.has_key(line[0]):
+        self._uids[line[1]] = Uid(*line)
+
+  def FindPid(self, pid, uid=None):
+    """Try to find the Process object for the given pid.
+    If it can't be found, do an update. If it still can't be found after that,
+    create a syntheitc Process object, add that to the list, and return that.
+    That can only happen after the process has died, and we just missed our
+    chance to find it.  The pid won't come back.
+    """
+    result = self._processes.get(pid)
+    if not result:
+      self.UpdateProcesses()
+      result = self._processes.get(pid)
+      if not result:
+        if uid:
+          uid = self._uids.get(uid)
+        result = Process(uid, pid, None, None)
+        self._processes[pid] = result
+    return result
+
+  def FindUid(self, uid):
+    result = self._uids.get(uid)
+    if not result:
+      self.UpdateUids()
+      result = self._uids.get(uid)
+      if not result:
+        result = Uid(uid, uid)
+        self._uids[uid] = result
+    return result
+
+  def UpdateCount(self):
+    return (self._pidUpdateCount, self._uidUpdateCount)
+
+  def Print(self):
+    for process in self._processes:
+      print process
+    for uid in self._uids:
+      print uid
+
+def ParsePs(text):
+  """Parses the output of ps, and returns it as a list of tuples of (user, pid, ppid, name)"""
+  result = []
+  for line in text.splitlines():
+    m = HEADER_RE.match(line)
+    if m:
+      continue
+    m = PROCESS_RE.match(line)
+    if m:
+      result.append((m.group(1), m.group(2), m.group(3), m.group(4)))
+      continue
+  return result
+
+
+def ParseUids(text):
+  """Parses the output of dumpsys package --checkin and returns the uids as a list of
+  tuples of (uid, name)"""
+  return [(x[2], x[1]) for x in csv.reader(text.split("\n")) if len(x) and x[0] == "pkg"]
+
+
+def ParseUid(text):
+  m = ANDROID_UID_RE.match(text)
+  if m:
+    result = int("0x" + m.group(2), 16)
+    return "(%s/%s/%s)" % (m.group(1), m.group(2), result)
+  m = UID_RE.match(text)
+  if m:
+    return "[%s]" % m.group(1)
+  return text
+
+# vim: set ts=2 sw=2 sts=2 tw=100 nocindent autoindent smartindent expandtab:

tools/logblame/short_idle_test

@@ -0,0 +1,23 @@
+#!/bin/bash
+
+# The files to save output to.
+RAWLOGS_FILE=short-idle-rawlogs.txt
+ANALYSIS_FILE=short-idle-analysis.txt
+
+# Turn on the screen and unlock the device
+# TODO: Power on
+adb shell wm dismiss-keyguard
+
+# Start the analysis process
+$TOP/development/tools/logblame/analyze_logs.py --duration=5m --clear --rawlogs $RAWLOGS_FILE \
+    | tee $ANALYSIS_FILE &
+analyze_pid=$!
+
+# Wait for the pyton process to exit
+echo "waiting... analyze_pid" $analyze_pid
+wait $analyze_pid
+
+echo "Wrote raw logs to $RAWLOGS_FILE"
+echo "Wrote analysis to $ANALYSIS_FILE"
+
+

tools/logblame/test_analyze.py

@@ -0,0 +1,24 @@
+#!/usr/bin/env python2.7 -B
+
+import analyze_logs
+
+
+def test_ParseDuration(s, expected):
+  actual = analyze_logs.ParseDuration(s)
+  if actual != expected:
+    raise Exception("expected %s, actual %s" % (expected, actual))
+
+def main():
+  test_ParseDuration("1w", 604800)
+  test_ParseDuration("1d", 86400)
+  test_ParseDuration("1h", 3600)
+  test_ParseDuration("1m", 60)
+  test_ParseDuration("1s", 1)
+  test_ParseDuration("1w1d1h1m1s", 694861)
+
+
+if __name__ == "__main__":
+  main()
+
+
+# vim: set ts=2 sw=2 sts=2 tw=100 nocindent autoindent smartindent expandtab :

tools/logblame/test_logs.py

@@ -0,0 +1,179 @@
+#!/usr/bin/env python2.7 -B
+
+import logs
+import ps
+
+import datetime
+import StringIO
+
+def test_empty():
+  """Test parsing no tag and no text, not well formed."""
+  expected = [ logs.LogLine(None, "03-29 00:46:58.872", "1000", "1815", "1816", "I", "",
+      "") ]
+  text = """[ 03-29 00:46:58.872  1000: 1815: 1816 I/ ]
+
+"""
+  check_parsing(expected, text)
+
+
+def test_none():
+  """Test parsing no tag and no text."""
+  expected = [ logs.LogLine(None, "03-29 00:46:58.872", "1000", "1815", "1816", "I", "",
+      "") ]
+  text = """[ 03-29 00:46:58.872  1000: 1815: 1816 I/ ]
+"""
+  check_parsing(expected, text)
+
+
+
+def test_trailing_blank():
+  """Test parsing text containing an extra intended newline at the end."""
+  expected = [ logs.LogLine(None, "03-29 00:46:58.872", "1000", "1815", "1816", "I", "abcd",
+      "Newline after\n") ]
+  text = """[ 03-29 00:46:58.872  1000: 1815: 1816 I/abcd ]
+Newline after
+
+
+"""
+  check_parsing(expected, text)
+
+
+def test_blank_between():
+  """Test parsing text containing a newline in the middle."""
+  expected = [ logs.LogLine(None, "03-29 00:46:58.872", "1000", "1815", "1816", "I", "abcd",
+      "Message\n\nNewline between") ]
+  text = """[ 03-29 00:46:58.872  1000: 1815: 1816 I/abcd ]
+Message
+
+Newline between
+
+"""
+  check_parsing(expected, text)
+
+
+def test_preceeding_blank():
+  """Test parsing text containing a newline then text."""
+  expected = [ logs.LogLine(None, "03-29 00:46:58.872", "1000", "1815", "1816", "I", "abcd",
+      "\nNewline before") ]
+  text = """[ 03-29 00:46:58.872  1000: 1815: 1816 I/abcd ]
+
+Newline before
+
+"""
+  check_parsing(expected, text)
+
+
+def test_one_blank():
+  """Test parsing text one blank line."""
+  expected = [ logs.LogLine(None, "03-29 00:46:58.872", "1000", "1815", "1816", "I", "abcd",
+      "\n") ]
+  text = """[ 03-29 00:46:58.872  1000: 1815: 1816 I/abcd ]
+
+
+"""
+  check_parsing(expected, text)
+
+
+def test_two_blanks():
+  """Test parsing text two blank lines."""
+  expected = [ logs.LogLine(None, "03-29 00:46:58.872", "1000", "1815", "1816", "I", "abcd",
+      "\n\n") ]
+  text = """[ 03-29 00:46:58.872  1000: 1815: 1816 I/abcd ]
+
+
+
+"""
+  check_parsing(expected, text)
+
+
+def test_two_lines_noblanks():
+  """Test parsing two lines of text with no blank lines."""
+  expected = [ logs.LogLine(None, "03-29 00:46:58.872", "1000", "1815", "1816", "I", "abcd",
+      "One\nTwo") ]
+  text = """[ 03-29 00:46:58.872  1000: 1815: 1816 I/abcd ]
+One
+Two
+
+"""
+  check_parsing(expected, text)
+
+
+def test_chatty():
+  """Test a log with chatty identical messages."""
+
+  expected = [
+      logs.LogLine("system", "03-29 00:46:58.857", "1000", "1815", "1816", "I", "Noisy", "Message"),
+      logs.LogLine("system", "03-29 00:46:58.858", "1000", "1815", "1816", "I", "Noisy", "Message"),
+      logs.LogLine("system", "03-29 00:46:58.858", "1000", "1815", "1816", "I", "Noisy", "Message"),
+      logs.LogLine("system", "03-29 00:46:58.858", "1000", "1815", "1816", "I", "Noisy", "Message"),
+      logs.LogLine("system", "03-29 00:46:58.859", "1000", "1815", "1816", "I", "Noisy", "Message"),
+      ]
+  text = """--------- beginning of system
+[ 03-29 00:46:58.857  1000: 1815: 1816 I/Noisy ]
+Message
+
+[ 03-29 00:46:58.858  1000: 1815: 1816 I/chatty ]
+uid=1000(system) Thread-6 identical 3 lines
+
+[ 03-29 00:46:58.859  1000: 1815: 1816 I/Noisy ]
+Message
+
+"""
+  check_parsing(expected, text)
+
+
+
+def test_normal():
+  """Test a realistic (albeit short) log."""
+  expected = [
+      logs.LogLine("system", "03-29 00:46:58.857", "1000", "1815", "1816", "I", "Package: ]Manager",
+        "/system/app/KeyChain changed; collecting certs"),
+      logs.LogLine("system", "03-29 00:46:58.872", "1000", "1815", "1816", "I", "PackageManager",
+        "/system/app/HiddenMenu changed; collecting certs"),
+      logs.LogLine("main", "03-29 00:46:58.872", "1000", "1815", "1816", "I", "PackageManager",
+        "/system/app/HiddenMenu changed; collecting certs"),
+  ]
+  
+  text = """--------- beginning of system
+[ 03-29 00:46:58.857  1000: 1815: 1816 I/Package: ]Manager ]
+/system/app/KeyChain changed; collecting certs
+
+[ 03-29 00:46:58.872  1000: 1815: 1816 I/PackageManager ]
+/system/app/HiddenMenu changed; collecting certs
+
+--------- switch to main
+[ 03-29 00:46:58.872  1000: 1815: 1816 I/PackageManager ]
+/system/app/HiddenMenu changed; collecting certs
+
+"""
+  check_parsing(expected, text)
+
+
+
+def check_parsing(expected, text):
+  """Parse the text and see if it parsed as expected."""
+  processes = ps.ProcessSet()
+  result = [x for x in logs.ParseLogcat(StringIO.StringIO(text), processes)]
+  if result != expected:
+    raise Exception("test failed.\nexpected:\n[%s]\nactual\n[%s]" % (
+        ", ".join([str(r) for r in expected]),
+        ", ".join([str(r) for r in result])))
+
+
+def main():
+  test_empty()
+  test_none()
+  test_trailing_blank()
+  test_blank_between()
+  test_preceeding_blank()
+  test_one_blank()
+  test_two_blanks()
+  test_chatty()
+  test_normal()
+
+
+if __name__ == "__main__":
+    main()
+
+
+# vim: set ts=2 sw=2 sts=2 tw=100 nocindent autoindent smartindent expandtab:

tools/logblame/test_ps.py

@@ -0,0 +1,97 @@
+#!/usr/bin/env python2.7 -B
+
+import ps
+
+
+def test_pids():
+  text = """USER      PID   PPID  VSIZE  RSS   WCHAN              PC  NAME
+root      1     0     10632  776   SyS_epoll_ 0000000000 S /init
+root      2     0     0      0       kthreadd 0000000000 S kthreadd
+u0_a22    7308  633   1808572 79760 SyS_epoll_ 0000000000 S com.google.android.dialer
+u0_a19    7370  633   1841228 37828 SyS_epoll_ 0000000000 S com.google.android.gms.feedback
+u0_a136   7846  634   1320656 119964 SyS_epoll_ 0000000000 S com.sonos.acr
+"""
+
+  actual = ps.ParsePs(text)
+
+  expected = [
+      ('root', '1', '0', '/init'),
+      ('root', '2', '0', 'kthreadd'),
+      ('u0_a22', '7308', '633', 'com.google.android.dialer'),
+      ('u0_a19', '7370', '633', 'com.google.android.gms.feedback'),
+      ('u0_a136', '7846', '634', 'com.sonos.acr')
+    ]
+
+  if actual != expected:
+    print "Expected:"
+    print expected
+    print
+    print "Actual:"
+    print actual
+    raise Exception("test failed")
+
+
+def test_uids():
+  text = """vers,1
+vrfy,com.android.vending,10035
+ifv,com.google.android.gms,10019
+lib,com.vzw.apnlib,jar,/system/app/VZWAPNLib/VZWAPNLib.apk
+lib,com.google.android.media.effects,jar,/system/framework/com.google.android.media.effects.jar
+pkg,com.amazon.mShop.android.shopping,10118,116434610,1486361139496,1491403362196,com.android.vending
+pkg-splt,base,0
+pkg-usr,0,IbsusL,0,com.android.vending
+pkg,com.getgoodcode.bart,10129,21,1486361637815,1486361637815,com.android.vending
+pkg-splt,base,0
+pkg-usr,0,IbsuSl,0,?
+pkg,com.flightaware.android.liveFlightTracker,10115,138,1486361042695,1486361042695,com.android.vending
+pkg-splt,base,0
+pkg-usr,0,IbsuSl,0,?
+pkg,com.android.cts.priv.ctsshim,10010,24,1230796800000,1230796800000,?
+pkg-splt,base,0
+pkg-usr,0,IbsusL,0,?
+"""
+  actual = ps.ParseUids(text)
+
+  expected = [
+    ('10118', 'com.amazon.mShop.android.shopping'),
+    ('10129', 'com.getgoodcode.bart'),
+    ('10115', 'com.flightaware.android.liveFlightTracker'),
+    ('10010', 'com.android.cts.priv.ctsshim')
+  ]
+
+  if actual != expected:
+    print "Expected:"
+    print expected
+    print
+    print "Actual:"
+    print actual
+    raise Exception("test failed")
+
+
+def test_update():
+  """Requires an attached device."""
+  processes = ps.ProcessSet()
+  processes.Update()
+  processes.Update()
+  processes.Print()
+  process = processes.FindPid("0", "0")
+  print "process:", process
+  print "uid:", process.uid.uid
+  print "username:", process.uid.name
+  print "pid:", process.pid
+  print "ppid:", process.ppid
+  print "name:", process.name
+  print "displayName:", process.DisplayName()
+
+
+def main():
+  #test_uids()
+  #test_pids()
+  test_update()
+
+
+if __name__ == "__main__":
+    main()
+
+
+# vim: set ts=2 sw=2 sts=2 tw=100 nocindent autoindent smartindent expandtab: