Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 3fb2816c authored by Yan Wang's avatar Yan Wang
Browse files

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
parent 34e2dabc

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