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

4 files changed, 172 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__':