diff options
| -rw-r--r-- | startop/scripts/app_startup/lib/adb_utils.py | 40 | ||||
| -rw-r--r-- | startop/scripts/app_startup/lib/adb_utils_test.py | 16 | ||||
| -rw-r--r-- | startop/scripts/app_startup/run_app_with_prefetch.py | 64 | ||||
| -rw-r--r-- | startop/scripts/app_startup/run_app_with_prefetch_test.py | 134 | ||||
| -rw-r--r-- | startop/scripts/lib/logcat_utils.py | 104 | ||||
| -rw-r--r-- | startop/scripts/lib/logcat_utils_test.py | 88 |
6 files changed, 364 insertions, 82 deletions
diff --git a/startop/scripts/app_startup/lib/adb_utils.py b/startop/scripts/app_startup/lib/adb_utils.py index 761dc2e82204..0e0065defd7f 100644 --- a/startop/scripts/app_startup/lib/adb_utils.py +++ b/startop/scripts/app_startup/lib/adb_utils.py @@ -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 diff --git a/startop/scripts/app_startup/lib/adb_utils_test.py b/startop/scripts/app_startup/lib/adb_utils_test.py new file mode 100644 index 000000000000..e590fed568e3 --- /dev/null +++ b/startop/scripts/app_startup/lib/adb_utils_test.py @@ -0,0 +1,16 @@ +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() diff --git a/startop/scripts/app_startup/run_app_with_prefetch.py b/startop/scripts/app_startup/run_app_with_prefetch.py index df9f1f3b309e..052db9d6f5ea 100644 --- a/startop/scripts/app_startup/run_app_with_prefetch.py +++ b/startop/scripts/app_startup/run_app_with_prefetch.py @@ -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,21 +267,22 @@ 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}"' - .format(timeout=timeout, - DIR=DIR, - package=package, - activity=activity, - timestamp=pre_launch_timestamp)) - - if not output and not simulate: + '"{activity}"' + .format(timeout=timeout, + DIR=DIR, + package=package, + activity=activity)) + if not passed and not simulate: return None - results = parse_metrics_output(output, simulate) + 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( readahead, package, activity, timeout, debug, pre_launch_timestamp) diff --git a/startop/scripts/app_startup/run_app_with_prefetch_test.py b/startop/scripts/app_startup/run_app_with_prefetch_test.py index a33d5d0faa16..a642385b37d7 100644 --- a/startop/scripts/app_startup/run_app_with_prefetch_test.py +++ b/startop/scripts/app_startup/run_app_with_prefetch_test.py @@ -206,72 +206,76 @@ 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: - mock_run_shell_command.side_effect = _mocked_run_shell_command - run.run('warm', - 'music', - 'MainActivity', - timeout=10, - simulate=False, - debug=False) - - calls = [call('adb shell ps | grep "music" | awk \'{print $2;}\''), - 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}"' - .format(timeout=10, - DIR=run.DIR, - package='music', - activity='MainActivity', - timestamp='2019-07-02 23:20:06.972674825')), - call('adb shell ps | grep "music" | awk \'{print $2;}\''), - call('adb shell "kill 9999"')] - mock_run_shell_command.assert_has_calls(calls) +@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', + timeout=10, + simulate=False, + debug=False) + + calls = [call('adb shell ps | grep "music" | awk \'{print $2;}\''), + 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}"' + .format(timeout=10, + DIR=run.DIR, + package='music', + activity='MainActivity', + timestamp='2019-07-02 23:20:06.972674825')), + call('adb shell ps | grep "music" | awk \'{print $2;}\''), + 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: - mock_run_shell_command.side_effect = _mocked_run_shell_command - run.run('fadvise', - 'music', - 'MainActivity', - timeout=10, - simulate=False, - debug=False) - - calls = [call('adb shell ps | grep "music" | awk \'{print $2;}\''), - call('adb shell "kill 9999"'), - call('adb shell "echo 3 > /proc/sys/vm/drop_caches"'), - call('bash -c "source {}; iorapd_readahead_enable"'. - 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}"' - .format(timeout=10, - DIR=run.DIR, - package='music', - activity='MainActivity', - timestamp='2019-07-02 23:20:06.972674825')), - call( - 'bash -c "source {script_path}; ' - 'iorapd_readahead_wait_until_finished ' - '\'{package}\' \'{activity}\' \'{timestamp}\' \'{timeout}\'"'. - format(timeout=10, - package='music', - activity='MainActivity', - timestamp='2019-07-02 23:20:06.972674825', - script_path=run.IORAP_COMMON_BASH_SCRIPT)), - call('bash -c "source {}; iorapd_readahead_disable"'. - format(run.IORAP_COMMON_BASH_SCRIPT)), - call('adb shell ps | grep "music" | awk \'{print $2;}\''), - call('adb shell "kill 9999"')] +@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', + timeout=10, + simulate=False, + debug=False) + + calls = [call('adb shell ps | grep "music" | awk \'{print $2;}\''), + call('adb shell "kill 9999"'), + call('adb shell "echo 3 > /proc/sys/vm/drop_caches"'), + call('bash -c "source {}; iorapd_readahead_enable"'. + 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}"' + .format(timeout=10, + DIR=run.DIR, + package='music', + activity='MainActivity', + timestamp='2019-07-02 23:20:06.972674825')), + call( + 'bash -c "source {script_path}; ' + 'iorapd_readahead_wait_until_finished ' + '\'{package}\' \'{activity}\' \'{timestamp}\' \'{timeout}\'"'. + format(timeout=10, + package='music', + activity='MainActivity', + timestamp='2019-07-02 23:20:06.972674825', + script_path=run.IORAP_COMMON_BASH_SCRIPT)), + call('bash -c "source {}; iorapd_readahead_disable"'. + format(run.IORAP_COMMON_BASH_SCRIPT)), + call('adb shell ps | grep "music" | awk \'{print $2;}\''), + call('adb shell "kill 9999"')] mock_run_shell_command.assert_has_calls(calls) if __name__ == '__main__': diff --git a/startop/scripts/lib/logcat_utils.py b/startop/scripts/lib/logcat_utils.py new file mode 100644 index 000000000000..13b1c3a5cff7 --- /dev/null +++ b/startop/scripts/lib/logcat_utils.py @@ -0,0 +1,104 @@ +#!/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 diff --git a/startop/scripts/lib/logcat_utils_test.py b/startop/scripts/lib/logcat_utils_test.py new file mode 100644 index 000000000000..ab82515bc4fa --- /dev/null +++ b/startop/scripts/lib/logcat_utils_test.py @@ -0,0 +1,88 @@ +#!/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. +# +"""Unit tests for the logcat_utils.py script.""" + +import asyncio +import datetime +import re + +import logcat_utils +from mock import MagicMock, patch + +def test_parse_logcat_datatime(): + # Act + result = logcat_utils.parse_logcat_datetime('2019-07-01 16:13:55.221') + + # Assert + assert result == datetime.datetime(2019, 7, 1, 16, 13, 55, 221000) + +class AsyncMock(MagicMock): + async def __call__(self, *args, **kwargs): + return super(AsyncMock, self).__call__(*args, **kwargs) + +def _async_return(): + f = asyncio.Future() + f.set_result( + b'2019-07-01 15:51:53.290 27365 27392 I ActivityTaskManager: ' + b'Displayed com.google.android.music/com.android.music.activitymanagement.' + b'TopLevelActivity: +1s7ms') + return f + +def test_parse_displayed_time_succeed(): + # Act + with patch('asyncio.create_subprocess_exec', + new_callable=AsyncMock) as asyncio_mock: + asyncio_mock.return_value.stdout.readline = _async_return + timestamp = datetime.datetime(datetime.datetime.now().year, 7, 1, 16, 13, + 55, 221000) + timeout_dt = timestamp + datetime.timedelta(0, 10) + pattern = re.compile('.*ActivityTaskManager: Displayed ' + 'com.google.android.music/com.android.music.*') + result = logcat_utils.blocking_wait_for_logcat_pattern(timestamp, + pattern, + timeout_dt) + + # Assert + assert result == '2019-07-01 15:51:53.290 27365 27392 I ' \ + 'ActivityTaskManager: ' \ + 'Displayed com.google.android.music/com.android.music.' \ + 'activitymanagement.TopLevelActivity: +1s7ms' + +def _async_timeout_return(): + f = asyncio.Future() + f.set_result( + b'2019-07-01 17:51:53.290 27365 27392 I ActivityTaskManager: ' + b'Displayed com.google.android.music/com.android.music.activitymanagement.' + b'TopLevelActivity: +1s7ms') + return f + +def test_parse_displayed_time_timeout(): + # Act + with patch('asyncio.create_subprocess_exec', + new_callable=AsyncMock) as asyncio_mock: + asyncio_mock.return_value.stdout.readline = _async_timeout_return + timestamp = datetime.datetime(datetime.datetime.now().year, + 7, 1, 16, 13, 55, 221000) + timeout_dt = timestamp + datetime.timedelta(0, 10) + pattern = re.compile('.*ActivityTaskManager: Displayed ' + 'com.google.android.music/com.android.music.*') + result = logcat_utils.blocking_wait_for_logcat_pattern(timestamp, + pattern, + timeout_dt) + + # Assert + assert result == None |