startop: Rewrite metrics parsing using python.

Shell version metrics parser generates some strange results when called
from Python.

Test: pytest logcat_utils_test.py
Test: pytest adb_utils_test.py
Test: pytest run_app_with_prefetch_test.py
Change-Id: I44a464f7e87f35ecc283c5108577eb33ad394fc6

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