Merge "startop: Rewrite metrics parsing using python." (905932fc) · Commits · e / os / android_frameworks_base

startop/scripts/app_startup/lib/adb_utils.py

+40 −0

Original line number	Diff line number	Diff line
		@@ -16,13 +16,18 @@

		"""Helper util libraries for calling adb command line."""

		import datetime
		import os
		import re
		import sys
		import time
		from typing import Optional

		sys.path.append(os.path.dirname(os.path.dirname(os.path.dirname(
		os.path.abspath(__file__)))))
		import lib.cmd_utils as cmd_utils
		import lib.logcat_utils as logcat_utils


		def logcat_save_timestamp() -> str:
		"""Gets the current logcat timestamp.
		@@ -65,3 +70,38 @@ def pkill(procname: str):
		if pid:
		passed,_ = cmd_utils.run_adb_shell_command('kill {}'.format(pid))
		time.sleep(1)

		def parse_time_to_milliseconds(time: str) -> int:
		"""Parses the time string to milliseconds."""
		# Example: +1s56ms, +56ms
		regex = r'\+((?P<second>\d+?)s)?(?P<millisecond>\d+?)ms'
		result = re.search(regex, time)
		second = 0
		if result.group('second'):
		second = int(result.group('second'))
		ms = int(result.group('millisecond'))
		return second * 1000 + ms

		def blocking_wait_for_logcat_displayed_time(timestamp: datetime.datetime,
		package: str,
		timeout: int) -> Optional[int]:
		"""Parses the displayed time in the logcat.

		Returns:
		the displayed time.
		"""
		pattern = re.compile('.ActivityTaskManager: Displayed {}.'.format(package))
		# 2019-07-02 22:28:34.469453349 -> 2019-07-02 22:28:34.469453
		timestamp = datetime.datetime.strptime(timestamp[:-3],
		'%Y-%m-%d %H:%M:%S.%f')
		timeout_dt = timestamp + datetime.timedelta(0, timeout)
		# 2019-07-01 14:54:21.946 27365 27392 I ActivityTaskManager:
		# Displayed com.android.settings/.Settings: +927ms
		result = logcat_utils.blocking_wait_for_logcat_pattern(timestamp,
		pattern,
		timeout_dt)
		if not result or not '+' in result:
		return None
		displayed_time = result[result.rfind('+'):]

		return parse_time_to_milliseconds(displayed_time)
		No newline at end of file

startop/scripts/app_startup/lib/adb_utils_test.py

0 → 100644

+16 −0

Original line number	Diff line number	Diff line
		import adb_utils

		# pip imports
		import pytest

		def test_parse_time_to_milliseconds():
		# Act
		result1 = adb_utils.parse_time_to_milliseconds('+1s7ms')
		result2 = adb_utils.parse_time_to_milliseconds('+523ms')

		# Assert
		assert result1 == 1007
		assert result2 == 523

		if __name__ == '__main__':
		pytest.main()

startop/scripts/app_startup/run_app_with_prefetch.py

+47 −17

Original line number	Diff line number	Diff line
		@@ -30,7 +30,7 @@ import argparse
		import os
		import sys
		import time
		from typing import List, Tuple
		from typing import List, Tuple, Optional

		# local imports
		import lib.adb_utils as adb_utils
		@@ -39,6 +39,8 @@ import lib.adb_utils as adb_utils
		DIR = os.path.abspath(os.path.dirname(__file__))
		IORAP_COMMON_BASH_SCRIPT = os.path.realpath(os.path.join(DIR,
		'../iorap/common'))
		APP_STARTUP_COMMON_BASH_SCRIPT = os.path.realpath(os.path.join(DIR,
		'lib/common'))

		sys.path.append(os.path.dirname(DIR))
		import lib.print_utils as print_utils
		@@ -102,6 +104,9 @@ def validate_options(opts: argparse.Namespace) -> bool:
		print_utils.error_print('--input not specified!')
		return False

		if opts.simulate:
		opts.activity = 'act'

		if not opts.activity:
		_, opts.activity = cmd_utils.run_shell_func(IORAP_COMMON_BASH_SCRIPT,
		'get_activity_name',
		@@ -181,9 +186,6 @@ def parse_metrics_output(input: str,
		Returns:
		A list of tuples that including metric name, metric value and rest info.
		"""
		if simulate:
		return [('TotalTime', '123')]

		all_metrics = []
		for line in input.split('\n'):
		if not line:
		@@ -205,6 +207,33 @@ def parse_metrics_output(input: str,
		all_metrics.append((metric_name, metric_value))
		return all_metrics

		def _parse_total_time(am_start_output: str) -> Optional[str]:
		"""Parses the total time from 'adb shell am start pkg' output.

		Returns:
		the total time of app startup.
		"""
		for line in am_start_output.split('\n'):
		if 'TotalTime:' in line:
		return line[len('TotalTime:'):].strip()
		return None

		def blocking_parse_all_metrics(am_start_output: str, package: str,
		pre_launch_timestamp: str,
		timeout: int) -> str:
		"""Parses the metric after app startup by reading from logcat in a blocking
		manner until all metrics have been found".

		Returns:
		the total time and displayed time of app startup.
		For example: "TotalTime=123\nDisplayedTime=121
		"""
		total_time = _parse_total_time(am_start_output)
		displayed_time = adb_utils.blocking_wait_for_logcat_displayed_time(
		pre_launch_timestamp, package, timeout)

		return 'TotalTime={}\nDisplayedTime={}'.format(total_time, displayed_time)

		def run(readahead: str,
		package: str,
		activity: str,
		@@ -238,20 +267,21 @@ def run(readahead: str,
		passed, output = cmd_utils.run_shell_command('timeout {timeout} '
		'"{DIR}/launch_application" '
		'"{package}" '
		'"{activity}" \| '
		'"{DIR}/parse_metrics" '
		'--package {package} '
		'--activity {activity} '
		'--timestamp "{timestamp}"'
		'"{activity}"'
		.format(timeout=timeout,
		DIR=DIR,
		package=package,
		activity=activity,
		timestamp=pre_launch_timestamp))

		if not output and not simulate:
		activity=activity))
		if not passed and not simulate:
		return None

		if simulate:
		results = [('TotalTime', '123')]
		else:
		output = blocking_parse_all_metrics(output,
		package,
		pre_launch_timestamp,
		timeout)
		results = parse_metrics_output(output, simulate)

		passed = perform_post_launch_cleanup(

startop/scripts/app_startup/run_app_with_prefetch_test.py

+69 −65

Original line number	Diff line number	Diff line
		@@ -206,10 +206,13 @@ def _mocked_run_shell_command(args, *kwargs):
		else:
		return (True, 'a1=b1\nc1=d1=d2\ne1=f1')

		def test_run_no_vm_cache_drop():
		with patch('lib.cmd_utils.run_shell_command',
		new_callable=Mock) as mock_run_shell_command:
		@patch('lib.adb_utils.blocking_wait_for_logcat_displayed_time')
		@patch('lib.cmd_utils.run_shell_command')
		def test_run_no_vm_cache_drop(mock_run_shell_command,
		mock_blocking_wait_for_logcat_displayed_time):
		mock_run_shell_command.side_effect = _mocked_run_shell_command
		mock_blocking_wait_for_logcat_displayed_time.return_value = 123

		run.run('warm',
		'music',
		'MainActivity',
		@@ -221,9 +224,7 @@ def test_run_no_vm_cache_drop():
		call('adb shell "kill 9999"'),
		call('adb shell "date -u +\'%Y-%m-%d %H:%M:%S.%N\'"'),
		call(
		'timeout {timeout} "{DIR}/launch_application" "{package}" "{activity}" \| '
		'"{DIR}/parse_metrics" --package {package} --activity {activity} '
		'--timestamp "{timestamp}"'
		'timeout {timeout} "{DIR}/launch_application" "{package}" "{activity}"'
		.format(timeout=10,
		DIR=run.DIR,
		package='music',
		@@ -233,10 +234,14 @@ def test_run_no_vm_cache_drop():
		call('adb shell "kill 9999"')]
		mock_run_shell_command.assert_has_calls(calls)

		def test_run_with_vm_cache_drop_and_post_launch_cleanup():
		with patch('lib.cmd_utils.run_shell_command',
		new_callable=Mock) as mock_run_shell_command:
		@patch('lib.adb_utils.blocking_wait_for_logcat_displayed_time')
		@patch('lib.cmd_utils.run_shell_command')
		def test_run_with_vm_cache_drop_and_post_launch_cleanup(
		mock_run_shell_command,
		mock_blocking_wait_for_logcat_displayed_time):
		mock_run_shell_command.side_effect = _mocked_run_shell_command
		mock_blocking_wait_for_logcat_displayed_time.return_value = 123

		run.run('fadvise',
		'music',
		'MainActivity',
		@@ -251,9 +256,8 @@ def test_run_with_vm_cache_drop_and_post_launch_cleanup():
		format(run.IORAP_COMMON_BASH_SCRIPT)),
		call('adb shell "date -u +\'%Y-%m-%d %H:%M:%S.%N\'"'),
		call(
		'timeout {timeout} "{DIR}/launch_application" "{package}" "{activity}" \| '
		'"{DIR}/parse_metrics" --package {package} --activity {activity} '
		'--timestamp "{timestamp}"'
		'timeout {timeout} "{DIR}/launch_application" '
		'"{package}" "{activity}"'
		.format(timeout=10,
		DIR=run.DIR,
		package='music',

startop/scripts/lib/logcat_utils.py

0 → 100644

+104 −0

Original line number	Diff line number	Diff line
		#!/usr/bin/env python3
		#
		# Copyright 2019, 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.

		"""Helper util libraries for parsing logcat logs."""

		import asyncio
		import re
		from datetime import datetime
		from typing import Optional, Pattern

		# local import
		import print_utils

		def parse_logcat_datetime(timestamp: str) -> Optional[datetime]:
		"""Parses the timestamp of logcat.

		Params:
		timestamp: for example "2019-07-01 16:13:55.221".

		Returns:
		a datetime of timestamp with the year now.
		"""
		try:
		# Match the format of logcat. For example: "2019-07-01 16:13:55.221",
		# because it doesn't have year, set current year to it.
		timestamp = datetime.strptime(timestamp,
		'%Y-%m-%d %H:%M:%S.%f')
		return timestamp
		except ValueError as ve:
		print_utils.debug_print('Invalid line: ' + timestamp)
		return None

		def _is_time_out(timeout: datetime, line: str) -> bool:
		"""Checks if the timestamp of this line exceeds the timeout.

		Returns:
		true if the timestamp exceeds the timeout.
		"""
		# Get the timestampe string.
		cur_timestamp_str = ' '.join(re.split(r'\s+', line)[0:2])
		timestamp = parse_logcat_datetime(cur_timestamp_str)
		if not timestamp:
		return False

		return timestamp > timeout

		async def _blocking_wait_for_logcat_pattern(timestamp: datetime,
		pattern: Pattern,
		timeout: datetime) -> Optional[str]:
		# Show the year in the timestampe.
		logcat_cmd = 'adb logcat -v year -v threadtime -T'.split()
		logcat_cmd.append(str(timestamp))
		print_utils.debug_print('[LOGCAT]:' + ' '.join(logcat_cmd))

		# Create subprocess
		process = await asyncio.create_subprocess_exec(
		*logcat_cmd,
		# stdout must a pipe to be accessible as process.stdout
		stdout=asyncio.subprocess.PIPE)

		while (True):
		# Read one line of output.
		data = await process.stdout.readline()
		line = data.decode('utf-8').rstrip()

		# 2019-07-01 14:54:21.946 27365 27392 I ActivityTaskManager: Displayed
		# com.android.settings/.Settings: +927ms
		# TODO: Detect timeouts even when there is no logcat output.
		if _is_time_out(timeout, line):
		print_utils.debug_print('DID TIMEOUT BEFORE SEEING ANYTHING ('
		'timeout={timeout} seconds << {pattern} '
		'>>'.format(timeout=timeout, pattern=pattern))
		return None

		if pattern.match(line):
		print_utils.debug_print(
		'WE DID SEE PATTERN << "{}" >>.'.format(pattern))
		return line

		def blocking_wait_for_logcat_pattern(timestamp: datetime,
		pattern: Pattern,
		timeout: datetime) -> Optional[str]:
		"""Selects the line that matches the pattern and within the timeout.

		Returns:
		the line that matches the pattern and within the timeout.
		"""
		loop = asyncio.get_event_loop()
		result = loop.run_until_complete(
		_blocking_wait_for_logcat_pattern(timestamp, pattern, timeout))
		return result