Rework logcat handling
Only extract logs from dex2oat instances that were started by the
correct runtime. This is accomplished by getting pid of runtime
and then filtering logcat output based on dex2oat 'parent PID ='
messages.
Test: bisection_search.py -cp classes.dex --class Test
--expected-output out --device
Change-Id: Ib1a5da6fac1560c57af8245e3a921d10bf464f2a
diff --git a/tools/bisection_search/README.md b/tools/bisection_search/README.md
index 64ccb20..d641102 100644
--- a/tools/bisection_search/README.md
+++ b/tools/bisection_search/README.md
@@ -21,12 +21,14 @@
./bisection_search.py -cp classes.dex --expected-output out_int --class Test
-2. Raw-cmd invocation, dalvikvm command is accepted as an argument. The command
- has to start with an executable.
+2. Raw-cmd invocation, dalvikvm command is accepted as an argument.
Extra dalvikvm arguments will be placed on second position in the command
by default. {ARGS} tag can be used to specify a custom position.
+ If used in device mode, the command has to exec a dalvikvm instance. Bisection
+ will fail if pid of the process started by raw-cmd is different than pid of runtime.
+
./bisection_search.py --raw-cmd='run.sh -cp classes.dex Test' --expected-retcode SUCCESS
./bisection_search.py --raw-cmd='/bin/sh art {ARGS} -cp classes.dex Test' --expected-retcode SUCCESS
diff --git a/tools/bisection_search/bisection_search.py b/tools/bisection_search/bisection_search.py
index 0d36aa4..b7f1907 100755
--- a/tools/bisection_search/bisection_search.py
+++ b/tools/bisection_search/bisection_search.py
@@ -34,6 +34,7 @@
from common import FatalError
from common import GetEnvVariableOrError
from common import HostTestEnv
+from common import LogSeverity
from common import RetCode
@@ -57,6 +58,9 @@
# position in the command.
RAW_CMD_RUNTIME_ARGS_TAG = '{ARGS}'
+# Default core image path relative to ANDROID_HOST_OUT.
+DEFAULT_IMAGE_RELATIVE_PATH = '/framework/core.art'
+
class Dex2OatWrapperTestable(object):
"""Class representing a testable compilation.
@@ -104,10 +108,9 @@
print('Testing methods: {0} passes: {1}.'.format(
compiled_methods, passes_to_run))
cmd = self._PrepareCmd(compiled_methods=compiled_methods,
- passes_to_run=passes_to_run,
- verbose_compiler=False)
+ passes_to_run=passes_to_run)
(output, ret_code) = self._test_env.RunCommand(
- cmd, {'ANDROID_LOG_TAGS': '*:e'})
+ cmd, LogSeverity.ERROR)
res = True
if self._expected_retcode:
res = self._expected_retcode == ret_code
@@ -126,8 +129,8 @@
Raises:
FatalError: An error occurred when retrieving methods list.
"""
- cmd = self._PrepareCmd(verbose_compiler=True)
- (output, _) = self._test_env.RunCommand(cmd, {'ANDROID_LOG_TAGS': '*:i'})
+ cmd = self._PrepareCmd()
+ (output, _) = self._test_env.RunCommand(cmd, LogSeverity.INFO)
match_methods = re.findall(r'Building ([^\n]+)\n', output)
if not match_methods:
raise FatalError('Failed to retrieve methods list. '
@@ -146,9 +149,8 @@
Raises:
FatalError: An error occurred when retrieving passes list.
"""
- cmd = self._PrepareCmd(compiled_methods=[compiled_method],
- verbose_compiler=True)
- (output, _) = self._test_env.RunCommand(cmd, {'ANDROID_LOG_TAGS': '*:i'})
+ cmd = self._PrepareCmd(compiled_methods=[compiled_method])
+ (output, _) = self._test_env.RunCommand(cmd, LogSeverity.INFO)
match_passes = re.findall(r'Starting pass: ([^\n]+)\n', output)
if not match_passes:
raise FatalError('Failed to retrieve passes list. '
@@ -168,9 +170,8 @@
self._test_env.WriteLines(self._passes_to_run_path, passes_to_run)
cmd += ['-Xcompiler-option', '--run-passes={0}'.format(
self._passes_to_run_path)]
- if verbose_compiler:
- cmd += ['-Xcompiler-option', '--runtime-arg', '-Xcompiler-option',
- '-verbose:compiler', '-Xcompiler-option', '-j1']
+ cmd += ['-Xcompiler-option', '--runtime-arg', '-Xcompiler-option',
+ '-verbose:compiler', '-Xcompiler-option', '-j1']
cmd += self._base_cmd[self._arguments_position:]
return cmd
@@ -361,8 +362,8 @@
if not args.device:
base_cmd += ['-XXlib:{0}'.format(args.lib)]
if not args.image:
- image_path = '{0}/framework/core-optimizing-pic.art'.format(
- GetEnvVariableOrError('ANDROID_HOST_OUT'))
+ image_path = (GetEnvVariableOrError('ANDROID_HOST_OUT') +
+ DEFAULT_IMAGE_RELATIVE_PATH)
else:
image_path = args.image
base_cmd += ['-Ximage:{0}'.format(image_path)]
diff --git a/tools/bisection_search/common.py b/tools/bisection_search/common.py
index b69b606..3d92ee5 100755
--- a/tools/bisection_search/common.py
+++ b/tools/bisection_search/common.py
@@ -21,6 +21,7 @@
import signal
import shlex
import shutil
+import time
from subprocess import check_call
from subprocess import PIPE
@@ -51,6 +52,48 @@
NOTRUN = 4
+@unique
+class LogSeverity(Enum):
+ VERBOSE = 0
+ DEBUG = 1
+ INFO = 2
+ WARNING = 3
+ ERROR = 4
+ FATAL = 5
+ SILENT = 6
+
+ @property
+ def symbol(self):
+ return self.name[0]
+
+ @classmethod
+ def FromSymbol(cls, s):
+ for log_severity in LogSeverity:
+ if log_severity.symbol == s:
+ return log_severity
+ raise ValueError("{0} is not a valid log severity symbol".format(s))
+
+ def __ge__(self, other):
+ if self.__class__ is other.__class__:
+ return self.value >= other.value
+ return NotImplemented
+
+ def __gt__(self, other):
+ if self.__class__ is other.__class__:
+ return self.value > other.value
+ return NotImplemented
+
+ def __le__(self, other):
+ if self.__class__ is other.__class__:
+ return self.value <= other.value
+ return NotImplemented
+
+ def __lt__(self, other):
+ if self.__class__ is other.__class__:
+ return self.value < other.value
+ return NotImplemented
+
+
def GetEnvVariableOrError(variable_name):
"""Gets value of an environmental variable.
@@ -116,23 +159,17 @@
return (output, stderr_output, retcode)
-def _RunCommandForOutputAndLog(cmd, env, logfile, timeout=60):
- """Runs command and logs its output. Returns the output.
+def _LogCmdOutput(logfile, cmd, output, retcode):
+ """Logs output of a command.
Args:
- cmd: list of strings, command to run.
- env: shell environment to run the command with.
logfile: file handle to logfile.
- timeout: int, timeout in seconds.
-
- Returns:
- tuple (string, string, RetCode) stdout output, stderr output, normalized
- return code.
+ cmd: list of strings, command.
+ output: command output.
+ retcode: RetCode, normalized retcode.
"""
- (output, _, retcode) = RunCommandForOutput(cmd, env, PIPE, STDOUT, timeout)
logfile.write('Command:\n{0}\n{1}\nReturn code: {2}\n'.format(
CommandListToCommandString(cmd), output, retcode))
- return (output, retcode)
def CommandListToCommandString(cmd):
@@ -187,15 +224,14 @@
"""
@abc.abstractmethod
- def RunCommand(self, cmd, env_updates=None):
- """Runs command in environment with updated environmental variables.
+ def RunCommand(self, cmd, log_severity=LogSeverity.ERROR):
+ """Runs command in environment.
Args:
cmd: list of strings, command to run.
- env_updates: dict, string to string, maps names of variables to their
- updated values.
+ log_severity: LogSeverity, minimum severity of logs included in output.
Returns:
- tuple (string, string, int) stdout output, stderr output, return code.
+ tuple (string, int) output, return code.
"""
@abc.abstractproperty
@@ -262,13 +298,17 @@
f.writelines('{0}\n'.format(line) for line in lines)
return
- def RunCommand(self, cmd, env_updates=None):
- if not env_updates:
- env_updates = {}
+ def RunCommand(self, cmd, log_severity=LogSeverity.ERROR):
self._EmptyDexCache()
env = self._shell_env.copy()
- env.update(env_updates)
- return _RunCommandForOutputAndLog(cmd, env, self._logfile, self._timeout)
+ env.update({'ANDROID_LOG_TAGS':'*:' + log_severity.symbol.lower()})
+ (output, err_output, retcode) = RunCommandForOutput(
+ cmd, env, PIPE, PIPE, self._timeout)
+ # We append err_output to output to stay consistent with DeviceTestEnv
+ # implementation.
+ output += err_output
+ _LogCmdOutput(self._logfile, cmd, output, retcode)
+ return (output, retcode)
@property
def logfile(self):
@@ -341,26 +381,63 @@
self._AdbPush(temp_file.name, file_path)
return
- def RunCommand(self, cmd, env_updates=None):
- if not env_updates:
- env_updates = {}
+ def _ExtractPid(self, brief_log_line):
+ """Extracts PID from a single logcat line in brief format."""
+ pid_start_idx = brief_log_line.find('(') + 2
+ if pid_start_idx == -1:
+ return None
+ pid_end_idx = brief_log_line.find(')', pid_start_idx)
+ if pid_end_idx == -1:
+ return None
+ return brief_log_line[pid_start_idx:pid_end_idx]
+
+ def _ExtractSeverity(self, brief_log_line):
+ """Extracts LogSeverity from a single logcat line in brief format."""
+ if not brief_log_line:
+ return None
+ return LogSeverity.FromSymbol(brief_log_line[0])
+
+ def RunCommand(self, cmd, log_severity=LogSeverity.ERROR):
self._EmptyDexCache()
- if 'ANDROID_DATA' not in env_updates:
- env_updates['ANDROID_DATA'] = self._device_env_path
- env_updates_cmd = ' '.join(['{0}={1}'.format(var, val) for var, val
- in env_updates.items()])
- cmd = CommandListToCommandString(cmd)
- adb = 'adb'
+ env_vars_cmd = 'ANDROID_DATA={0} ANDROID_LOG_TAGS=*:i'.format(
+ self._device_env_path)
+ adb_cmd = ['adb']
if self._specific_device:
- adb += ' -s ' + self._specific_device
- cmd = '{0} shell "logcat -c && {1} {2}"'.format(
- adb, env_updates_cmd, cmd)
- (output, retcode) = _RunCommandForOutputAndLog(
- shlex.split(cmd), self._shell_env, self._logfile, self._timeout)
- logcat_cmd = 'adb shell "logcat -d -s -b main dex2oat:* dex2oatd:*"'
- (err_output, _) = _RunCommandForOutputAndLog(
- shlex.split(logcat_cmd), self._shell_env, self._logfile)
- return (output + err_output, retcode)
+ adb_cmd += ['-s', self._specific_device]
+ logcat_cmd = adb_cmd + ['logcat', '-v', 'brief', '-s', '-b', 'main',
+ '-T', '1', 'dex2oat:*', 'dex2oatd:*']
+ logcat_proc = Popen(logcat_cmd, stdout=PIPE, stderr=STDOUT,
+ universal_newlines=True)
+ cmd_str = CommandListToCommandString(cmd)
+ # Print PID of the shell and exec command. We later retrieve this PID and
+ # use it to filter dex2oat logs, keeping those with matching parent PID.
+ device_cmd = ('echo $$ && ' + env_vars_cmd + ' exec ' + cmd_str)
+ cmd = adb_cmd + ['shell', device_cmd]
+ (output, _, retcode) = RunCommandForOutput(cmd, self._shell_env, PIPE,
+ STDOUT, self._timeout)
+ # We need to make sure to only kill logcat once all relevant logs arrive.
+ # Sleep is used for simplicity.
+ time.sleep(0.5)
+ logcat_proc.kill()
+ end_of_first_line = output.find('\n')
+ if end_of_first_line != -1:
+ parent_pid = output[:end_of_first_line]
+ output = output[end_of_first_line + 1:]
+ logcat_output, _ = logcat_proc.communicate()
+ logcat_lines = logcat_output.splitlines(keepends=True)
+ dex2oat_pids = []
+ for line in logcat_lines:
+ # Dex2oat was started by our runtime instance.
+ if 'Running dex2oat (parent PID = ' + parent_pid in line:
+ dex2oat_pids.append(self._ExtractPid(line))
+ break
+ if dex2oat_pids:
+ for line in logcat_lines:
+ if (self._ExtractPid(line) in dex2oat_pids and
+ self._ExtractSeverity(line) >= log_severity):
+ output += line
+ _LogCmdOutput(self._logfile, cmd, output, retcode)
+ return (output, retcode)
@property
def logfile(self):
