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

Commit 7ab5c4d6 authored by Igor Murashkin's avatar Igor Murashkin
Browse files

startop: Update app_startup_runner to work with iorapd

Script measures app startup times with/without iorapd-based
prefetching against a cold (or warm) baseline.

mlock/fadvise readahead options now use iorapd to exercise
real code to do prefetching.

Bug: 72170747
Change-Id: I28affac3470271e46febb0e22a6dc9543258b4a4
parent 8298ae00
Loading
Loading
Loading
Loading
+7 −0
Original line number Diff line number Diff line
@@ -104,6 +104,13 @@ class IIorapIntegrationTest {
        }
    }

    @Test
    fun testOnAppLaunchEvent() {
        testAnyMethod { requestId : RequestId ->
            // iorapService.onAppLaunchEvent(requestId, AppLaunchEvent.IntentStarted())
        }
    }

    @Test
    fun testOnSystemServiceEvent() {
        testAnyMethod { requestId: RequestId ->
+87 −16
Original line number Diff line number Diff line
@@ -27,12 +27,13 @@
#

import argparse
import asyncio
import csv
import itertools
import os
import subprocess
import sys
import tempfile
import time
from typing import Any, Callable, Dict, Generic, Iterable, List, NamedTuple, TextIO, Tuple, TypeVar, Optional, Union

# The following command line options participate in the combinatorial generation.
@@ -44,7 +45,7 @@ _RUN_SCRIPT=os.path.join(os.path.dirname(os.path.realpath(__file__)), 'run_app_w

RunCommandArgs = NamedTuple('RunCommandArgs', [('package', str), ('readahead', str), ('compiler_filter', Optional[str])])
CollectorPackageInfo = NamedTuple('CollectorPackageInfo', [('package', str), ('compiler_filter', str)])
_COLLECTOR_SCRIPT=os.path.join(os.path.dirname(os.path.realpath(__file__)), 'collector')
_COLLECTOR_SCRIPT=os.path.join(os.path.dirname(os.path.realpath(__file__)), '../iorap/collector')
_COLLECTOR_TIMEOUT_MULTIPLIER = 2 # take the regular --timeout and multiply by 2; systrace starts up slowly.

_UNLOCK_SCREEN_SCRIPT=os.path.join(os.path.dirname(os.path.realpath(__file__)), 'unlock_screen')
@@ -217,25 +218,95 @@ def make_script_command_with_temp_output(script: str, args: List[str], **kwargs)
  cmd = cmd + ["--output", tmp_output_file.name]
  return cmd, tmp_output_file

def execute_arbitrary_command(cmd: List[str], simulate: bool, timeout: int) -> Tuple[bool, str]:
async def _run_command(*args : List[str], timeout: Optional[int] = None) -> Tuple[int, bytes]:
  # start child process
  # NOTE: universal_newlines parameter is not supported
  process = await asyncio.create_subprocess_exec(*args,
      stdout=asyncio.subprocess.PIPE, stderr=asyncio.subprocess.STDOUT)

  script_output = b""

  _debug_print("[PID]", process.pid)

#hack
#  stdout, stderr = await process.communicate()
#  return (process.returncode, stdout)

  timeout_remaining = timeout
  time_started = time.time()

  # read line (sequence of bytes ending with b'\n') asynchronously
  while True:
    try:
      line = await asyncio.wait_for(process.stdout.readline(), timeout_remaining)
      _debug_print("[STDOUT]", line)
      script_output += line

      if timeout_remaining:
        time_elapsed = time.time() - time_started
        timeout_remaining = timeout - time_elapsed
    except asyncio.TimeoutError:
      _debug_print("[TIMEDOUT] Process ", process.pid)

#      if process.returncode is not None:
#        #_debug_print("[WTF] can-write-eof?", process.stdout.can_write_eof())
#
#        _debug_print("[TIMEDOUT] Process already terminated")
#        (remaining_stdout, remaining_stderr) = await process.communicate()
#        script_output += remaining_stdout
#
#        code = await process.wait()
#        return (code, script_output)

      _debug_print("[TIMEDOUT] Sending SIGTERM.")
      process.terminate()

      # 1 second timeout for process to handle SIGTERM nicely.
      try:
       (remaining_stdout, remaining_stderr) = await asyncio.wait_for(process.communicate(), 5)
       script_output += remaining_stdout
      except asyncio.TimeoutError:
        _debug_print("[TIMEDOUT] Sending SIGKILL.")
        process.kill()

      # 1 second timeout to finish with SIGKILL.
      try:
        (remaining_stdout, remaining_stderr) = await asyncio.wait_for(process.communicate(), 5)
        script_output += remaining_stdout
      except asyncio.TimeoutError:
        # give up, this will leave a zombie process.
        _debug_print("[TIMEDOUT] SIGKILL failed for process ", process.pid)
        time.sleep(100)
        #await process.wait()

      return (-1, script_output)
    else:
      if not line: # EOF
        break

      #if process.returncode is not None:
      #  _debug_print("[WTF] can-write-eof?", process.stdout.can_write_eof())
      #  process.stdout.write_eof()

      #if process.stdout.at_eof():
      #  break

  code = await process.wait() # wait for child process to exit
  return (code, script_output)

def execute_arbitrary_command(cmd: List[str], simulate: bool, timeout: Optional[int]) -> Tuple[bool, str]:
  if simulate:
    print(" ".join(cmd))
    return (True, "")
  else:
    _debug_print("[EXECUTE]", cmd)
    proc = subprocess.Popen(cmd,
                            stderr=subprocess.STDOUT,
                            stdout=subprocess.PIPE,
                            universal_newlines=True)
    try:
      script_output = proc.communicate(timeout=timeout)[0]
    except subprocess.TimeoutExpired:
      print("[TIMEDOUT]")
      proc.kill()
      script_output = proc.communicate()[0]

    _debug_print("[STDOUT]", script_output)
    return_code = proc.wait()

    # block until either command finishes or the timeout occurs.
    loop = asyncio.get_event_loop()
    (return_code, script_output) = loop.run_until_complete(_run_command(*cmd, timeout=timeout))

    script_output = script_output.decode() # convert bytes to str

    passed = (return_code == 0)
    _debug_print("[$?]", return_code)
    if not passed:
+18 −0
Original line number Diff line number Diff line
@@ -17,6 +17,19 @@
DIR="$( cd "$( dirname "${BASH_SOURCE[0]}" )" && pwd )"
source "$DIR/lib/common"

launch_application_usage() {
    cat <<EOF
Usage: $(basename $0) <package> <activity>

  Positional Arguments:
    <package>                   package of the app to test
    <activity>                  activity to use

  Named Arguments:
    -h, --help                  usage information (this)
EOF
}

launch_application() {
  local package="$1"
  local activity="$2"
@@ -44,4 +57,9 @@ launch_application() {
  echo "$total_time"
}

if [[ $# -lt 2 ]]; then
  launch_application_usage
  exit 1
fi

launch_application "$@"
+111 −0
Original line number Diff line number Diff line
#!/bin/bash
# Copyright 2018, 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.

if [[ -z $ANDROID_BUILD_TOP ]]; then
  echo "Please run source build/envsetup.sh first" >&2
@@ -49,5 +62,103 @@ get_activity_name() {
  local activity_line="$(adb shell cmd package query-activities --brief -a android.intent.action.MAIN -c android.intent.category.LAUNCHER | grep "$package/")"
  IFS="/" read -a array <<< "$activity_line"
  local activity_name="${array[1]}"

  # Activities starting with '.' are shorthand for having their package name prefixed.
  if [[ $activity_name == .* ]]; then
    activity_name="${package}${activity_name}"
  fi
  echo "$activity_name"
}

# Use with logcat_from_timestamp to skip all past log-lines.
logcat_save_timestamp() {
  adb shell 'date -u +"%Y-%m-%d %H:%M:%S.%N"'
}

# Roll forward logcat to only show events
# since the specified timestamp.
#
# i.e. don't look at historical logcat,
# only look at FUTURE logcat.
#
# First use 'logcat_save_timestamp'
# Then do whatever action you want.
# Then us 'logcat_from_timestamp $timestamp'
logcat_from_timestamp() {
  local timestamp="$1"
  shift # drop timestamp from args.
  echo "DONT CALL THIS FUNCTION" >&2
  exit 1

  verbose_print adb logcat -T \"$timestamp\" \"$@\"
  adb logcat -T "$timestamp" "$@"
}

logcat_from_timestamp_bg() {
  local timestamp="$1"
  shift # drop timestamp from args.
  verbose_print adb logcat -T \"$timestamp\" \"$@\"
  adb logcat -v UTC -T "$timestamp" "$@" &
  logcat_from_timestamp_pid=$!
}

# Starting at timestamp $2, wait until we seen pattern $3
# or until a timeout happens in $1 seconds.
#
# Set VERBOSE_LOGCAT=1 to debug every line of logcat it tries to parse.
logcat_wait_for_pattern() {
  local timeout="$1"
  local timestamp="$2"
  local pattern="$3"

  local logcat_fd

  coproc logcat_fd {
    kill_children_quietly() {
      kill "$logcat_pidd"
      wait "$logcat_pidd" 2>/dev/null
    }

    trap 'kill_children_quietly' EXIT # kill logcat when this coproc is killed.

    # run logcat in the background so it can be killed.
    logcat_from_timestamp_bg "$timestamp"
    logcat_pidd=$logcat_from_timestamp_pid
    wait "$logcat_pidd"
  }
  local logcat_pid="$!"
  verbose_print "[LOGCAT] Spawn pid $logcat_pid"

  local timeout_ts="$(date -d "now + ${timeout} seconds" '+%s')"
  local now_ts="0"

  local return_code=1

  verbose_print "logcat_wait_for_pattern begin"

  while read -t "$timeout" -r -u "${logcat_fd[0]}" logcat_output; do
    if (( $VERBOSE_LOGCAT )); then
      verbose_print "LOGCAT: $logcat_output"
    fi
    if [[ "$logcat_output:" == *"$pattern"* ]]; then
      verbose_print "LOGCAT: " "$logcat_output"
      verbose_print "WE DID SEE PATTERN" '<<' "$pattern" '>>.'
      return_code=0
      break
    fi
    now_ts="$(date -d "now" '+%s')"
    if (( now_ts >= timeout_ts )); then
      verbose_print "DID TIMEOUT BEFORE SEEING ANYTHING (timeout=$timeout seconds) " '<<' "$pattern" '>>.'
      break
    fi
  done

  # Don't leave logcat lying around since it will keep going.
  kill "$logcat_pid"
  # Suppress annoying 'Terminated...' message.
  wait "$logcat_pid" 2>/dev/null

  verbose_print "[LOGCAT] $logcat_pid should be killed"

  return $return_code
}
+32 −13
Original line number Diff line number Diff line
@@ -24,7 +24,7 @@ Usage: run_app_with_prefetch --package <name> [OPTIONS]...
    -v, --verbose               enable extra verbose printing
    -i, --input <file>          trace file protobuf (default 'TraceFile.pb')
    -r, --readahead <mode>      cold, warm, fadvise, mlock (default 'warm')
    -w, --when <when>           aot or jit (default 'aot')
    -w, --when <when>           aot or jit (default 'jit')
    -c, --count <count>         how many times to run (default 1)
    -s, --sleep <sec>           how long to sleep after readahead
    -t, --timeout <sec>         how many seconds to timeout in between each app run (default 10)
@@ -33,7 +33,7 @@ EOF
}

DIR="$( cd "$( dirname "${BASH_SOURCE[0]}" )" && pwd )"
source "$DIR/lib/common"
source "$DIR/../iorap/common"

needs_trace_file="n"
input_file=""
@@ -43,7 +43,7 @@ count=2
sleep_time=2
timeout=10
output="" # stdout by default
when="aot"
when="jit"
parse_arguments() {
  while [[ $# -gt 0 ]]; do
    case "$1" in
@@ -176,16 +176,19 @@ if [[ $? -ne 0 ]]; then
fi
verbose_print "Package was in path '$package_path'"

keep_application_trace_file=n
application_trace_file_path="$package_path/TraceFile.pb"
trace_file_directory="$package_path"
if [[ $needs_trace_file == y ]]; then
  # system server always passes down the package path in a hardcoded spot.
  if [[ $when == "jit" ]]; then
    verbose_print adb push "$input_file" "$application_trace_file_path"
    adb push "$input_file" "$application_trace_file_path"
    if ! iorapd_compiler_install_trace_file "$package" "$activity" "$input_file"; then
      echo "Error: Failed to install compiled TraceFile.pb for '$package/$activity'" >&2
      exit 1
    fi
    keep_application_trace_file="y"
  else
    echo "TODO: --readahead=aot is non-functional and needs to be fixed." >&2
    exit 1
    # otherwise use a temporary directory to get normal non-jit behavior.
    trace_file_directory="/data/local/tmp/prefetch/$package"
    adb shell mkdir -p "$trace_file_directory"
@@ -198,7 +201,7 @@ fi
# otherwise system server activity hints will kick in
# and the new just-in-time app pre-warmup will happen.
if [[ $keep_application_trace_file == "n" ]]; then
  adb shell "[[ -f '$application_trace_file_path' ]] && rm '$application_trace_file_path'"
  iorapd_compiler_purge_trace_file "$package" "$activity"
fi

# Perform AOT readahead/pinning/etc when an application is about to be launched.
@@ -242,12 +245,20 @@ perform_aot() {
  fi
}

perform_aot_cleanup() {
# Perform cleanup at the end of each loop iteration.
perform_post_launch_cleanup() {
  local the_when="$1" # user: aot, jit
  local the_mode="$2" # warm, cold, fadvise, mlock, etc.
  local logcat_timestamp="$3"  # timestamp from before am start.

  if [[ $the_when != "aot" ]]; then
    # TODO: just in time implementation.. should probably use system server.
    if [[ $the_mode != 'warm' && $the_mode != 'cold' ]]; then
      # Validate that readahead completes.
      # If this fails for some reason, then this will also discard the timing of the run.
      iorapd_readahead_wait_until_finished "$package" "$activity" "$logcat_timestamp" "$timeout"
      return $?
    fi
    # Don't need to do anything for warm or cold.
    return 0
  fi

@@ -321,6 +332,8 @@ for ((i=0;i<count;++i)) do

  verbose_print "Running with timeout $timeout"

  pre_launch_timestamp="$(logcat_save_timestamp)"

  # TODO: multiple metrics output.
  total_time="$(timeout $timeout $DIR/launch_application "$package" "$activity")"

@@ -330,7 +343,13 @@ for ((i=0;i<count;++i)) do
    continue
  fi

  perform_aot_cleanup "$when" "$mode"
  perform_post_launch_cleanup "$when" "$mode" "$pre_launch_timestamp"

  if [[ $? -ne 0 ]]; then
    echo "WARNING: Skip bad cleanup, try iteration again." >&2
    ((i=i-1))
    continue
  fi

  echo "Iteration $i. Total time was: $total_time"

@@ -354,9 +373,9 @@ if [[ x$output != x ]]; then
  echo " Saved results to '$output'"
fi

# Temporary hack around multiple activities being launched with different package paths (for same app):
# Clean up all left-over TraceFile.pb
adb shell 'for i in $(find /data/app -name TraceFile.pb); do rm \$i; done'
if [[ $needs_trace_file == y ]] ; then
  iorapd_compiler_purge_trace_file "$package" "$activity"
fi

# Kill the process to ensure AM isn't keeping it around.
remote_pkill "$package"
Loading