diff options
| -rwxr-xr-x | startop/scripts/app_startup/app_startup_runner.py | 269 | ||||
| -rwxr-xr-x | startop/scripts/app_startup/app_startup_runner_test.py | 129 | ||||
| -rwxr-xr-x | startop/scripts/app_startup/launch_application | 17 | ||||
| -rwxr-xr-x | startop/scripts/app_startup/lib/common | 58 | ||||
| -rwxr-xr-x | startop/scripts/app_startup/metrics/com.google.android.GoogleCamera | 25 | ||||
| -rwxr-xr-x | startop/scripts/app_startup/parse_metrics | 181 | ||||
| -rwxr-xr-x | startop/scripts/app_startup/run_app_with_prefetch | 79 | ||||
| -rwxr-xr-x | startop/scripts/iorap/collector | 13 | ||||
| -rwxr-xr-x | startop/scripts/iorap/common | 23 |
9 files changed, 748 insertions, 46 deletions
diff --git a/startop/scripts/app_startup/app_startup_runner.py b/startop/scripts/app_startup/app_startup_runner.py index adf2ad808ea8..9a608af346d0 100755 --- a/startop/scripts/app_startup/app_startup_runner.py +++ b/startop/scripts/app_startup/app_startup_runner.py @@ -192,7 +192,206 @@ def generate_group_run_combinations(run_combinations: Iterable[NamedTuple], dst_ (group_key_value, args_it) = args_list_it yield (group_key_value, args_it) -def parse_run_script_csv_file(csv_file: TextIO) -> List[int]: +class DataFrame: + """Table-like class for storing a 2D cells table with named columns.""" + def __init__(self, data: Dict[str, List[object]] = {}): + """ + Create a new DataFrame from a dictionary (keys = headers, + values = columns). + """ + self._headers = [i for i in data.keys()] + self._rows = [] + + row_num = 0 + + def get_data_row(idx): + r = {} + for header, header_data in data.items(): + + if not len(header_data) > idx: + continue + + r[header] = header_data[idx] + + return r + + while True: + row_dict = get_data_row(row_num) + if len(row_dict) == 0: + break + + self._append_row(row_dict.keys(), row_dict.values()) + row_num = row_num + 1 + + def concat_rows(self, other: 'DataFrame') -> None: + """ + In-place concatenate rows of other into the rows of the + current DataFrame. + + None is added in pre-existing cells if new headers + are introduced. + """ + other_datas = other._data_only() + + other_headers = other.headers + + for d in other_datas: + self._append_row(other_headers, d) + + def _append_row(self, headers: List[str], data: List[object]): + new_row = {k:v for k,v in zip(headers, data)} + self._rows.append(new_row) + + for header in headers: + if not header in self._headers: + self._headers.append(header) + + def __repr__(self): +# return repr(self._rows) + repr = "" + + header_list = self._headers_only() + + row_format = u"" + for header in header_list: + row_format = row_format + u"{:>%d}" %(len(header) + 1) + + repr = row_format.format(*header_list) + "\n" + + for v in self._data_only(): + repr = repr + row_format.format(*v) + "\n" + + return repr + + def __eq__(self, other): + if isinstance(other, self.__class__): + return self.headers == other.headers and self.data_table == other.data_table + else: + print("wrong instance", other.__class__) + return False + + @property + def headers(self) -> List[str]: + return [i for i in self._headers_only()] + + @property + def data_table(self) -> List[List[object]]: + return list(self._data_only()) + + @property + def data_table_transposed(self) -> List[List[object]]: + return list(self._transposed_data()) + + @property + def data_row_len(self) -> int: + return len(self._rows) + + def data_row_at(self, idx) -> List[object]: + """ + Return a single data row at the specified index (0th based). + + Accepts negative indices, e.g. -1 is last row. + """ + row_dict = self._rows[idx] + l = [] + + for h in self._headers_only(): + l.append(row_dict.get(h)) # Adds None in blank spots. + + return l + + def copy(self) -> 'DataFrame': + """ + Shallow copy of this DataFrame. + """ + return self.repeat(count=0) + + def repeat(self, count: int) -> 'DataFrame': + """ + Returns a new DataFrame where each row of this dataframe is repeated count times. + A repeat of a row is adjacent to other repeats of that same row. + """ + df = DataFrame() + df._headers = self._headers.copy() + + rows = [] + for row in self._rows: + for i in range(count): + rows.append(row.copy()) + + df._rows = rows + + return df + + def merge_data_columns(self, other: 'DataFrame'): + """ + Merge self and another DataFrame by adding the data from other column-wise. + For any headers that are the same, data from 'other' is preferred. + """ + for h in other._headers: + if not h in self._headers: + self._headers.append(h) + + append_rows = [] + + for self_dict, other_dict in itertools.zip_longest(self._rows, other._rows): + if not self_dict: + d = {} + append_rows.append(d) + else: + d = self_dict + + d_other = other_dict + if d_other: + for k,v in d_other.items(): + d[k] = v + + for r in append_rows: + self._rows.append(r) + + def data_row_reduce(self, fnc) -> 'DataFrame': + """ + Reduces the data row-wise by applying the fnc to each row (column-wise). + Empty cells are skipped. + + fnc(Iterable[object]) -> object + fnc is applied over every non-empty cell in that column (descending row-wise). + + Example: + DataFrame({'a':[1,2,3]}).data_row_reduce(sum) == DataFrame({'a':[6]}) + + Returns a new single-row DataFrame. + """ + df = DataFrame() + df._headers = self._headers.copy() + + def yield_by_column(header_key): + for row_dict in self._rows: + val = row_dict.get(header_key) + if val: + yield val + + new_row_dict = {} + for h in df._headers: + cell_value = fnc(yield_by_column(h)) + new_row_dict[h] = cell_value + + df._rows = [new_row_dict] + return df + + def _headers_only(self): + return self._headers + + def _data_only(self): + row_len = len(self._rows) + + for i in range(row_len): + yield self.data_row_at(i) + + def _transposed_data(self): + return zip(*self._data_only()) + +def parse_run_script_csv_file_flat(csv_file: TextIO) -> List[int]: """Parse a CSV file full of integers into a flat int list.""" csv_reader = csv.reader(csv_file) arr = [] @@ -202,6 +401,38 @@ def parse_run_script_csv_file(csv_file: TextIO) -> List[int]: arr.append(int(i)) return arr +def parse_run_script_csv_file(csv_file: TextIO) -> DataFrame: + """Parse a CSV file full of integers into a DataFrame.""" + csv_reader = csv.reader(csv_file) + + try: + header_list = next(csv_reader) + except StopIteration: + header_list = [] + + if not header_list: + return None + + headers = [i for i in header_list] + + d = {} + for row in csv_reader: + header_idx = 0 + + for i in row: + v = i + if i: + v = int(i) + + header_key = headers[header_idx] + l = d.get(header_key, []) + l.append(v) + d[header_key] = l + + header_idx = header_idx + 1 + + return DataFrame(d) + def make_script_command_with_temp_output(script: str, args: List[str], **kwargs)\ -> Tuple[str, TextIO]: """ @@ -338,27 +569,49 @@ def execute_run_combos(grouped_run_combos: Iterable[Tuple[CollectorPackageInfo, cmd, tmp_output_file = make_script_command_with_temp_output(_RUN_SCRIPT, args, count=loop_count, input=collector_tmp_output_file.name) with tmp_output_file: (passed, script_output) = execute_arbitrary_command(cmd, simulate, timeout) - parsed_output = simulate and [1,2,3] or parse_run_script_csv_file(tmp_output_file) + parsed_output = simulate and DataFrame({'fake_ms':[1,2,3]}) or parse_run_script_csv_file(tmp_output_file) yield (passed, script_output, parsed_output) -def gather_results(commands: Iterable[Tuple[bool, str, List[int]]], key_list: List[str], value_list: List[Tuple[str, ...]]): +def gather_results(commands: Iterable[Tuple[bool, str, DataFrame]], key_list: List[str], value_list: List[Tuple[str, ...]]): _debug_print("gather_results: key_list = ", key_list) - yield key_list + ["time(ms)"] +# yield key_list + ["time(ms)"] stringify_none = lambda s: s is None and "<none>" or s for ((passed, script_output, run_result_list), values) in itertools.zip_longest(commands, value_list): + _debug_print("run_result_list = ", run_result_list) + _debug_print("values = ", values) if not passed: continue - for result in run_result_list: - yield [stringify_none(i) for i in values] + [result] - yield ["; avg(%s), min(%s), max(%s), count(%s)" %(sum(run_result_list, 0.0) / len(run_result_list), min(run_result_list), max(run_result_list), len(run_result_list)) ] + # RunCommandArgs(package='com.whatever', readahead='warm', compiler_filter=None) + # -> {'package':['com.whatever'], 'readahead':['warm'], 'compiler_filter':[None]} + values_dict = {k:[v] for k,v in values._asdict().items()} + + values_df = DataFrame(values_dict) + # project 'values_df' to be same number of rows as run_result_list. + values_df = values_df.repeat(run_result_list.data_row_len) + + # the results are added as right-hand-side columns onto the existing labels for the table. + values_df.merge_data_columns(run_result_list) + + yield values_df def eval_and_save_to_csv(output, annotated_result_values): + + printed_header = False + csv_writer = csv.writer(output) for row in annotated_result_values: - csv_writer.writerow(row) + if not printed_header: + headers = row.headers + csv_writer.writerow(headers) + printed_header = True + # TODO: what about when headers change? + + for data_row in row.data_table: + csv_writer.writerow(data_row) + output.flush() # see the output live. def main(): diff --git a/startop/scripts/app_startup/app_startup_runner_test.py b/startop/scripts/app_startup/app_startup_runner_test.py index f96f802a3aef..fd81667fe26f 100755 --- a/startop/scripts/app_startup/app_startup_runner_test.py +++ b/startop/scripts/app_startup/app_startup_runner_test.py @@ -192,19 +192,140 @@ def test_make_script_command_with_temp_output(): with tmp_file: assert cmd_str == ["fake_script", "a", "b", "--count", "2", "--output", tmp_file.name] -def test_parse_run_script_csv_file(): +def test_parse_run_script_csv_file_flat(): # empty file -> empty list f = io.StringIO("") - assert asr.parse_run_script_csv_file(f) == [] + assert asr.parse_run_script_csv_file_flat(f) == [] # common case f = io.StringIO("1,2,3") - assert asr.parse_run_script_csv_file(f) == [1,2,3] + assert asr.parse_run_script_csv_file_flat(f) == [1,2,3] # ignore trailing comma f = io.StringIO("1,2,3,4,5,") - assert asr.parse_run_script_csv_file(f) == [1,2,3,4,5] + assert asr.parse_run_script_csv_file_flat(f) == [1,2,3,4,5] + +def test_data_frame(): + # trivial empty data frame + df = asr.DataFrame() + assert df.headers == [] + assert df.data_table == [] + assert df.data_table_transposed == [] + + # common case, same number of values in each place. + df = asr.DataFrame({'TotalTime_ms':[1,2,3], 'Displayed_ms':[4,5,6]}) + assert df.headers == ['TotalTime_ms', 'Displayed_ms'] + assert df.data_table == [[1, 4], [2, 5], [3, 6]] + assert df.data_table_transposed == [(1, 2, 3), (4, 5, 6)] + + # varying num values. + df = asr.DataFrame({'many':[1,2], 'none': []}) + assert df.headers == ['many', 'none'] + assert df.data_table == [[1, None], [2, None]] + assert df.data_table_transposed == [(1, 2), (None, None)] + + df = asr.DataFrame({'many':[], 'none': [1,2]}) + assert df.headers == ['many', 'none'] + assert df.data_table == [[None, 1], [None, 2]] + assert df.data_table_transposed == [(None, None), (1, 2)] + + # merge multiple data frames + df = asr.DataFrame() + df.concat_rows(asr.DataFrame()) + assert df.headers == [] + assert df.data_table == [] + assert df.data_table_transposed == [] + + df = asr.DataFrame() + df2 = asr.DataFrame({'TotalTime_ms':[1,2,3], 'Displayed_ms':[4,5,6]}) + + df.concat_rows(df2) + assert df.headers == ['TotalTime_ms', 'Displayed_ms'] + assert df.data_table == [[1, 4], [2, 5], [3, 6]] + assert df.data_table_transposed == [(1, 2, 3), (4, 5, 6)] + + df = asr.DataFrame({'TotalTime_ms':[1,2]}) + df2 = asr.DataFrame({'Displayed_ms':[4,5]}) + + df.concat_rows(df2) + assert df.headers == ['TotalTime_ms', 'Displayed_ms'] + assert df.data_table == [[1, None], [2, None], [None, 4], [None, 5]] + + df = asr.DataFrame({'TotalTime_ms':[1,2]}) + df2 = asr.DataFrame({'TotalTime_ms': [3, 4], 'Displayed_ms':[5, 6]}) + + df.concat_rows(df2) + assert df.headers == ['TotalTime_ms', 'Displayed_ms'] + assert df.data_table == [[1, None], [2, None], [3, 5], [4, 6]] + + # data_row_at + df = asr.DataFrame({'TotalTime_ms':[1,2,3], 'Displayed_ms':[4,5,6]}) + assert df.data_row_at(-1) == [3,6] + assert df.data_row_at(2) == [3,6] + assert df.data_row_at(1) == [2,5] + + # repeat + df = asr.DataFrame({'TotalTime_ms':[1], 'Displayed_ms':[4]}) + df2 = asr.DataFrame({'TotalTime_ms':[1,1,1], 'Displayed_ms':[4,4,4]}) + assert df.repeat(3) == df2 + + # repeat + df = asr.DataFrame({'TotalTime_ms':[1,1,1], 'Displayed_ms':[4,4,4]}) + assert df.data_row_len == 3 + df = asr.DataFrame({'TotalTime_ms':[1,1]}) + assert df.data_row_len == 2 + + # repeat + df = asr.DataFrame({'TotalTime_ms':[1,1,1], 'Displayed_ms':[4,4,4]}) + assert df.data_row_len == 3 + df = asr.DataFrame({'TotalTime_ms':[1,1]}) + assert df.data_row_len == 2 + + # data_row_reduce + df = asr.DataFrame({'TotalTime_ms':[1,1,1], 'Displayed_ms':[4,4,4]}) + df_sum = asr.DataFrame({'TotalTime_ms':[3], 'Displayed_ms':[12]}) + assert df.data_row_reduce(sum) == df_sum + + # merge_data_columns + df = asr.DataFrame({'TotalTime_ms':[1,2,3]}) + df2 = asr.DataFrame({'Displayed_ms':[3,4,5,6]}) + + df.merge_data_columns(df2) + assert df == asr.DataFrame({'TotalTime_ms':[1,2,3], 'Displayed_ms':[3,4,5,6]}) + + df = asr.DataFrame({'TotalTime_ms':[1,2,3]}) + df2 = asr.DataFrame({'Displayed_ms':[3,4]}) + + df.merge_data_columns(df2) + assert df == asr.DataFrame({'TotalTime_ms':[1,2,3], 'Displayed_ms':[3,4]}) + + df = asr.DataFrame({'TotalTime_ms':[1,2,3]}) + df2 = asr.DataFrame({'TotalTime_ms':[10,11]}) + + df.merge_data_columns(df2) + assert df == asr.DataFrame({'TotalTime_ms':[10,11,3]}) + + df = asr.DataFrame({'TotalTime_ms':[]}) + df2 = asr.DataFrame({'TotalTime_ms':[10,11]}) + + df.merge_data_columns(df2) + assert df == asr.DataFrame({'TotalTime_ms':[10,11]}) + + + + + +def test_parse_run_script_csv_file(): + # empty file -> empty list + f = io.StringIO("") + assert asr.parse_run_script_csv_file(f) == None + + # common case + f = io.StringIO("TotalTime_ms,Displayed_ms\n1,2") + df = asr.DataFrame({'TotalTime_ms': [1], 'Displayed_ms': [2]}) + pf = asr.parse_run_script_csv_file(f) + assert pf == df if __name__ == '__main__': pytest.main() diff --git a/startop/scripts/app_startup/launch_application b/startop/scripts/app_startup/launch_application index bc7ca802ed85..6704a5a97aa0 100755 --- a/startop/scripts/app_startup/launch_application +++ b/startop/scripts/app_startup/launch_application @@ -39,22 +39,9 @@ launch_application() { # if the $ is not escaped, adb shell will try to evaluate $HomeActivity to a variable. activity=${activity//\$/\\$} - local am_output="$(adb shell am start -S -W "$package"/"$activity")" - verbose_print adb shell am start -S -W "$package"/"$activity" - if [[ $? -ne 0 ]]; then - echo "am start failed" >&2 + adb shell am start -S -W "$package"/"$activity" - return 1 - fi - - # for everything else use the am start "TotalTime" output. - verbose_print "$am_output" - local total_time="$(echo "$am_output" | grep 'TotalTime:' | sed 's/TotalTime: //g')" - verbose_print "total time: $total_time" - - # TODO: Extract alternative metrics such as the #reportFullyDrawn. - - echo "$total_time" + # pipe this into 'parse_metrics' to parse the output. } if [[ $# -lt 2 ]]; then diff --git a/startop/scripts/app_startup/lib/common b/startop/scripts/app_startup/lib/common index 41f8cda126d4..bedaa1e10288 100755 --- a/startop/scripts/app_startup/lib/common +++ b/startop/scripts/app_startup/lib/common @@ -83,17 +83,7 @@ logcat_save_timestamp() { # # 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" "$@" -} - +# Then use 'logcat_from_timestamp_bg $timestamp' logcat_from_timestamp_bg() { local timestamp="$1" shift # drop timestamp from args. @@ -104,9 +94,10 @@ logcat_from_timestamp_bg() { # Starting at timestamp $2, wait until we seen pattern $3 # or until a timeout happens in $1 seconds. +# If successful, also echo the line that matched the pattern. # # Set VERBOSE_LOGCAT=1 to debug every line of logcat it tries to parse. -logcat_wait_for_pattern() { +logcat_select_pattern() { local timeout="$1" local timestamp="$2" local pattern="$3" @@ -143,6 +134,7 @@ logcat_wait_for_pattern() { if [[ "$logcat_output:" == *"$pattern"* ]]; then verbose_print "LOGCAT: " "$logcat_output" verbose_print "WE DID SEE PATTERN" '<<' "$pattern" '>>.' + echo "$logcat_output" return_code=0 break fi @@ -162,3 +154,45 @@ logcat_wait_for_pattern() { return $return_code } + +# 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() { + logcat_select_pattern "$@" > /dev/null +} + +# Starting at timestamp $2, wait until we seen pattern $3 +# or until a timeout happens in $1 seconds. +# If successful, extract with the regular expression pattern in #4 +# and return the first capture group. +# +# Set VERBOSE_LOGCAT=1 to debug every line of logcat it tries to parse. +logcat_extract_pattern() { + local timeout="$1" + local timestamp="$2" + local pattern="$3" + local re_pattern="$4" + + local result + local exit_code + + result="$(logcat_select_pattern "$@")" + exit_code=$? + + if [[ $exit_code -ne 0 ]]; then + return $exit_code + fi + + echo "$result" | sed 's/'"$re_pattern"'/\1/g' +} + +# Join array +# FOO=(a b c) +# join_by , "${FOO[@]}" #a,b,c +join_by() { + local IFS="$1" + shift + echo "$*" +} diff --git a/startop/scripts/app_startup/metrics/com.google.android.GoogleCamera b/startop/scripts/app_startup/metrics/com.google.android.GoogleCamera new file mode 100755 index 000000000000..d95fa32dce3f --- /dev/null +++ b/startop/scripts/app_startup/metrics/com.google.android.GoogleCamera @@ -0,0 +1,25 @@ +#!/bin/bash +# +# 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. + +# 05-06 14:51:17.688 29691 29897 I CAM_Timing: CameraActivity: START -> ACTIVITY_FIRST_PREVIEW_FRAME_RECEIVED: 385ms +pattern="CAM_Timing: CameraActivity: START -> ACTIVITY_FIRST_PREVIEW_FRAME_RECEIVED:" +re_pattern='.*ACTIVITY_FIRST_PREVIEW_FRAME_RECEIVED: \([[:digit:]]\+\)ms' +parse_metric_from_logcat "ACTIVITY_FIRST_PREVIEW_FRAME_RECEIVED_ms" "$pattern" "$re_pattern" + +# 05-06 14:51:17.724 29691 29691 I CAM_Timing: CameraActivity: START -> ACTIVITY_FIRST_PREVIEW_FRAME_RENDERED: 421ms +pattern="CAM_Timing: CameraActivity: START -> ACTIVITY_FIRST_PREVIEW_FRAME_RENDERED:" +re_pattern='.*ACTIVITY_FIRST_PREVIEW_FRAME_RENDERED: \([[:digit:]]\+\)ms' +parse_metric_from_logcat "ACTIVITY_FIRST_PREVIEW_FRAME_RENDERED_ms" "$pattern" "$re_pattern" diff --git a/startop/scripts/app_startup/parse_metrics b/startop/scripts/app_startup/parse_metrics new file mode 100755 index 000000000000..c6bf08ee9dfd --- /dev/null +++ b/startop/scripts/app_startup/parse_metrics @@ -0,0 +1,181 @@ +#!/bin/bash +# +# 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. + +usage() { + cat <<EOF +Usage: launch_application package activity | parse_metrics --package <name> --timestamp <timestamp> [OPTIONS]... + + Reads from stdin the result of 'am start' metrics. May also parse logcat + for additional metrics. + + Output form: + + MetricName_unit=numeric_value + MetricName2_unit=numeric_value2 + + This may block until all desired metrics are parsed from logcat. + To get a list of metrics without doing real parsing, use --simulate. + + To add package-specific metrics, add a script called 'metrics/\$full_package_name' + that exposes additional metrics in same way as above. + + (required) + -p, --package <name> package of the app that is being used + -ts, --timestamp <name> logcat timestamp [only looks at logcat entries after this timestamp]. + + (optional) + -s, --simulate prints dummy values instead of real metrics + -a, --activity <name> activity to use (default: inferred) + -h, --help usage information (this) + -v, --verbose enable extra verbose printing + -t, --timeout <sec> how many seconds to timeout when trying to wait for logcat to change +EOF +} + +DIR="$( cd "$( dirname "${BASH_SOURCE[0]}" )" && pwd )" +source "$DIR/lib/common" + +package="" +activity="" +timeout=10 +simulate="n" +parse_arguments() { + while [[ $# -gt 0 ]]; do + case "$1" in + -h|--help) + usage + exit 0 + ;; + -p|--package) + package="$2" + shift + ;; + -a|--activity) + activity="$2" + shift + ;; + -v|--verbose) + export verbose="y" + ;; + -t|--timeout) + timeout="$2" + shift + ;; + -ts|--timestamp) + timestamp="$2" + shift + ;; + -s|--simulate) + simulate="y" + ;; + *) + echo "Invalid argument: $1" >&2 + exit 1 + esac + shift + done +} + +# Main entry point +if [[ $# -eq 0 ]]; then + usage + exit 1 +else + parse_arguments "$@" + + # if we do not have have package exit early with an error + [[ "$package" == "" ]] && echo "--package not specified" 1>&2 && exit 64 + + # ignore timestamp for --simulate. it's optional. + if [[ $simulate == y ]]; then + timestamp=0 + fi + + # if we do not have timestamp, exit early with an error + [[ "$timestamp" == "" ]] && echo "--timestamp not specified" 1>&2 && exit 64 + + if [[ "$activity" == "" ]] && [[ "$simulate" != "y" ]]; then + activity="$(get_activity_name "$package")" + if [[ "$activity" == "" ]]; then + echo "Activity name could not be found, invalid package name?" 1>&2 + exit 64 + else + verbose_print "Activity name inferred: " "$activity" + fi + fi +fi + +parse_metric_from_logcat() { + local metric_name="$1" + local pattern="$2" + local re_pattern="$3" + local retcode + + # parse logcat for 'Displayed...' and that other one... + + # 05-06 14:34:08.854 29460 29481 I ActivityTaskManager: Displayed com.google.android.dialer/.extensions.GoogleDialtactsActivity: +361ms + verbose_print "parse_metric_from_logcat: $re_pattern" + + + echo -ne "$metric_name=" + + if [[ $simulate == y ]]; then + echo "-1" + return 0 + fi + + logcat_extract_pattern "$timeout" "$timestamp" "$pattern" "$re_pattern" + retcode=$? + + if [[ $retcode -ne 0 ]]; then + # Timed out before finding the pattern. Could also mean the pattern is wrong. + echo "-$?" + fi + + return $retcode +} + + +total_time="-1" +if [[ $simulate != y ]]; then + verbose_print 'logcat timestamp NOW: ' $(logcat_save_timestamp) + + # parse stdin for 'am start' result + while read -t "$timeout" -r input_line; do + verbose_print 'stdin:' "$input_line" + if [[ $input_line == *TotalTime:* ]]; then + total_time="$(echo "$input_line" | sed 's/TotalTime: \([[:digit:]]\+\)/\1/g')" + # but keep reading the rest from stdin until <EOF> + fi + done +fi + +echo "TotalTime_ms=$total_time" + +# parse logcat for 'Displayed...' and that other one... + +# 05-06 14:34:08.854 29460 29481 I ActivityTaskManager: Displayed com.google.android.dialer/.extensions.GoogleDialtactsActivity: +361ms +pattern="ActivityTaskManager: Displayed ${package}" +re_pattern='.*Displayed[[:blank:]]\+'"${package}"'[/][^[:blank:]]\+[[:blank:]]+\([[:digit:]]\+\).*' + +parse_metric_from_logcat "Displayed_ms" "$pattern" "$re_pattern" + +# also call into package-specific scripts if there are additional metrics +if [[ -x "$DIR/metrics/$package" ]]; then + source "$DIR/metrics/$package" "$timestamp" +else + verbose_print parse_metrics: no per-package metrics script found at "$DIR/metrics/$package" +fi diff --git a/startop/scripts/app_startup/run_app_with_prefetch b/startop/scripts/app_startup/run_app_with_prefetch index 18aaf32abb7a..643df1ba0825 100755 --- a/startop/scripts/app_startup/run_app_with_prefetch +++ b/startop/scripts/app_startup/run_app_with_prefetch @@ -317,6 +317,74 @@ configure_compiler_filter() { # No-op if this option was not passed in. configure_compiler_filter "$compiler_filter" "$package" "$activity" || exit 1 +# convert 'a=b\nc=d\ne=f\n...' into 'b,d,f,...' +parse_metrics_output_string() { + # single string with newlines in it. + local input="$1" + + local metric_name + local metric_value + local rest + + local all_metrics=() + + # (n1=v1 n2=v2 n3=v3 ...) + readarray -t all_metrics <<< "$input" + + local kv_pair=() + local i + + for i in "${all_metrics[@]}" + do + verbose_print "parse_metrics_output: element '$i'" + # name=value + + IFS='=' read -r metric_name metric_value rest <<< "$i" + + verbose_print "parse_metrics_output: metric_value '$metric_value'" + + # (value1 value2 value3 ...) + all_metrics+=(${metric_value}) + done + + # "value1,value2,value3,..." + join_by ',' "${all_metrics[@]}" +} + +# convert 'a=b\nc=d\ne=f\n... into b,d,f,...' +parse_metrics_output() { + local metric_name + local metric_value + local rest + + local all_metrics=() + + while IFS='=' read -r metric_name metric_value rest; do + verbose_print "metric: $metric_name, value: $metric_value; rest: $rest" + all_metrics+=($metric_value) + done + + join_by ',' "${all_metrics[@]}" +} + +# convert 'a=b\nc=d\ne=f\n... into b,d,f,...' +parse_metrics_header() { + local metric_name + local metric_value + local rest + + local all_metrics=() + + while IFS='=' read -r metric_name metric_value rest; do + verbose_print "metric: $metric_name, value: $metric_value; rest: $rest" + all_metrics+=($metric_name) + done + + join_by ',' "${all_metrics[@]}" +} + +metrics_header="$("$DIR/parse_metrics" --package "$package" --activity "$activity" --simulate | parse_metrics_header)" + # TODO: This loop logic could probably be moved into app_startup_runner.py for ((i=0;i<count;++i)) do verbose_print "==========================================" @@ -335,7 +403,7 @@ for ((i=0;i<count;++i)) do pre_launch_timestamp="$(logcat_save_timestamp)" # TODO: multiple metrics output. - total_time="$(timeout $timeout $DIR/launch_application "$package" "$activity")" + total_time="$(timeout $timeout "$DIR/launch_application" "$package" "$activity" | "$DIR/parse_metrics" --package "$package" --activity "$activity" --timestamp "$pre_launch_timestamp" | parse_metrics_output)" if [[ $? -ne 0 ]]; then echo "WARNING: Skip bad result, try iteration again." >&2 @@ -353,22 +421,21 @@ for ((i=0;i<count;++i)) do echo "Iteration $i. Total time was: $total_time" - timings_array+=($total_time) + timings_array+=("$total_time") done # drop the first result which is usually garbage. timings_array=("${timings_array[@]:1}") +# Print the CSV header first. +echo_to_output_file "$metrics_header" # Print out interactive/debugging timings and averages. # Other scripts should use the --output flag and parse the CSV. for tim in "${timings_array[@]}"; do - echo_to_output_file -ne "$tim," + echo_to_output_file "$tim" done -echo_to_output_file "" -average_string=$(echo "${timings_array[@]}" | awk '{s+=$0}END{print "Average:",s/NR}' RS=" ") -echo -ne ${average_string}. if [[ x$output != x ]]; then echo " Saved results to '$output'" fi diff --git a/startop/scripts/iorap/collector b/startop/scripts/iorap/collector index 8d105adeaa51..d96125f76a37 100755 --- a/startop/scripts/iorap/collector +++ b/startop/scripts/iorap/collector @@ -263,9 +263,19 @@ launch_application_and_wait_for_trace() { # Ensure application isn't running already. remote_pkill "$package" + # 5 second trace of Home screen causes + # a trace of the home screen. + # There is no way to abort the trace + # so just wait for it to complete instead. + sleep 30 + local time_now="$(logcat_save_timestamp)" local retcode=0 + verbose_print "Drop caches for non-warm start." + # Drop all caches to get cold starts. + adb shell "echo 3 > /proc/sys/vm/drop_caches" + verbose_print "now launching application" # Launch an application "$APP_STARTUP_DIR"/launch_application "$package" "$activity" @@ -317,6 +327,9 @@ collector_main() { # Wait for perfetto trace to finished writing itself out. launch_application_and_wait_for_trace "$package" "$activity" || return $? + # Pull the perfetto trace for manual inspection. + iorapd_perfetto_pull_trace_file "$package" "$activity" "perfetto_trace.pb" + # Compile the trace so that the next app run can use prefetching. iorapd_compiler_for_app_trace "$package" "$activity" "$inodes" || return $? diff --git a/startop/scripts/iorap/common b/startop/scripts/iorap/common index 6dde3d51a5ba..c10327ef09c1 100755 --- a/startop/scripts/iorap/common +++ b/startop/scripts/iorap/common @@ -88,6 +88,26 @@ iorapd_perfetto_purge_app_trace() { adb shell "[[ -f '$remote_path' ]] && rm -f '$remote_path' || exit 0" } +# Pull the remote perfetto trace file into a local file. +iorapd_perfetto_pull_trace_file() { + local package="$1" + local activity="$2" + local output_file="$3" # local path + + local compiled_path="$(_iorapd_path_to_data_file "$package" "$activity" "perfetto_trace.pb")" + + if ! adb shell "[[ -f '$compiled_path' ]]"; then + echo "Error: Remote path '$compiled_path' invalid" >&2 + return 1 + fi + if ! mkdir -p "$(dirname "$output_file")"; then + echo "Error: Fail to make output directory for '$output_file'" >&2 + return 1 + fi + verbose_print adb pull "$compiled_path" "$output_file" + adb pull "$compiled_path" "$output_file" +} + # Compile a perfetto trace for a given application. # This requires the app has run at least once with perfetto tracing enabled. iorapd_compiler_for_app_trace() { @@ -114,6 +134,7 @@ iorapd_compiler_for_app_trace() { # inodes file needs to be on the device for iorap.cmd.compiler to access it local remote_inodes=/data/local/tmp/prefetch/inodes.txt adb shell "mkdir -p \"$(dirname "$remote_inodes")\"" || return 1 + verbose_print adb push "$inodes" "$remote_inodes" adb push "$inodes" "$remote_inodes" verbose_print 'iorapd-compiler: compile app trace in ' "$input_path" @@ -130,7 +151,7 @@ iorapd_compiler_for_app_trace() { fi # Clean up inodes file we just pushed. - adb shell "[[ -f '$remote_inodes' ]] && rm -f '$remote_inodes'" +# adb shell "[[ -f '$remote_inodes' ]] && rm -f '$remote_inodes'" return $retcode } |