Simplify pretty print of metrics

Test: incremental-build.py -c change
Bug: NA
Change-Id: Ic95b90e16ab2c684c624a9b082e59b2a47ab5135

6 files changed, 125 insertions, 152 deletions

diff --git a/scripts/incremental_build/canonical_perf.sh b/scripts/incremental_build/canonical_perf.sh
index efd5abee..2ea5783b 100755
--- a/scripts/incremental_build/canonical_perf.sh
+++ b/scripts/incremental_build/canonical_perf.sh
@@ -21,70 +21,38 @@ readonly TOP="$(realpath "$(dirname "$0")/../../../..")"
 
 usage() {
   cat <<EOF
-usage: $0 [-l LOG_DIR] [-t TARGETS] CUJS
-  -l    LOG_DIR should be outside of tree, including not in out/,
+usage: $0 [-l LOG_DIR] [BUILD_TYPES]
+  -l    LOG_DIR should be outside of source tree, including not in out/,
         because the whole tree will be cleaned during testing.
-  -t    TARGETS to run e.g. droid
-  CUJS  to run, e.g. "modify Android.bp"
 example:
- $0 -t nothing "no change"
- $0 -t droid -t libc "no change" "modify Android.bp"
+ $0 soong prod
 EOF
   exit 1
 }
 
-declare -a targets
-while getopts "l:t:" opt; do
+declare -a build_types
+while getopts "l:" opt; do
   case "$opt" in
   l) log_dir=$OPTARG ;;
-  t) targets+=("$OPTARG") ;;
   ?) usage ;;
   esac
 done
 shift $((OPTIND - 1))
-
-readonly -a cujs=("$@")
-
-# Pretty print the results
-function pretty() {
-  python3 "$(dirname "$0")/pretty.py" "$1"
-}
-
-# TODO: Switch to oriole when it works
-if [[ -e vendor/google/build ]]; then
-  export TARGET_PRODUCT=cf_x86_64_phone
-else
-  export TARGET_PRODUCT=aosp_cf_x86_64_phone
-fi
-
-export TARGET_BUILD_VARIANT=eng
+readonly -a build_types=("$@")
 
 function build() {
   date
   set -x
   if ! "$TOP/build/bazel/scripts/incremental_build/incremental_build.py" \
-    --ignore-repo-diff ${log_dir:+--log-dir="$log_dir"} "$@"; then
+    --ignore-repo-diff ${log_dir:+--log-dir "$log_dir"} \
+    ${build_types:+--build-types "${build_types[@]}"} \
+    "$@"; then
     echo "See logs for errors"
     exit 1
   fi
   set +x
 }
+build --cujs clean 'create bionic/unreferenced.txt' 'modify Android.bp' -- droid
+build --cujs 'modify bionic/.*/stdio.cpp' --append-csv libc
+build --cujs 'modify .*/adb/daemon/main.cpp' --append-csv adbd
 
-if [[ ${#cujs[@]} -ne "0" ]]; then
-  echo "you might want to add \"clean\" as the first CUJ to mitigate caching issues"
-else
-  if [[ ${#targets[@]} -ne "0" ]]; then
-    echo "you must specify cujs as well"
-    usage
-  fi
-fi
-
-if [[ ${#cujs[@]} -ne "0" ]]; then
-  build -c "${cujs[@]}" -- "${targets[*]}"
-else
-  build -c 'clean' 'create bionic/unreferenced.txt' 'modify Android.bp' -- droid
-  build -c 'modify bionic/.*/stdio.cpp' --append-csv libc
-  build -c 'modify .*/adb/daemon/main.cpp' --append-csv adbd
-fi
-
-pretty ${$log_dir:"$log_dir/metrics.csv"}
diff --git a/scripts/incremental_build/incremental_build.py b/scripts/incremental_build/incremental_build.py
index 8c1965f4..dde0123e 100755
--- a/scripts/incremental_build/incremental_build.py
+++ b/scripts/incremental_build/incremental_build.py
@@ -61,13 +61,17 @@ def _prepare_env() -> (Mapping[str, str], str):
     return soong_ui_ninja_args
 
   overrides: Mapping[str, str] = {
-    'NINJA_ARGS': get_soong_build_ninja_args(),
-    'SOONG_UI_NINJA_ARGS': get_soong_ui_ninja_args()
+      'NINJA_ARGS': get_soong_build_ninja_args(),
+      'SOONG_UI_NINJA_ARGS': get_soong_ui_ninja_args()
   }
   env = {**os.environ, **overrides}
-  if not os.environ.get('TARGET_BUILD_PRODUCT'):
-    env['TARGET_BUILD_PRODUCT'] = 'aosp_arm64'
-    env['TARGET_BUILD_VARIANT'] = 'userdebug'
+  if not os.environ.get('TARGET_PRODUCT'):
+    # TODO: Switch to oriole when it works
+    env['TARGET_PRODUCT'] = 'cf_x86_64_phone' \
+      if util.get_top_dir().joinpath('vendor/google/build').exists() \
+      else 'aosp_cf_x86_64_phone'
+  if not os.environ.get('TARGET_BUILD_VARIANT'):
+    env['TARGET_BUILD_VARIANT'] = 'eng'
 
   pretty_env_str = [f'{k}={v}' for (k, v) in env.items()]
   pretty_env_str.sort()
@@ -110,14 +114,14 @@ def _build(build_type: ui.BuildType, run_dir: Path) -> (int, BuildInfo):
 
   def recompact_ninja_log():
     subprocess.run([
-      util.get_top_dir().joinpath(
-        'prebuilts/build-tools/linux-x86/bin/ninja'),
-      '-f',
-      util.get_out_dir().joinpath(
-        f'combined-{env.get("TARGET_PRODUCT", "aosp_arm")}.ninja'),
-      '-t', 'recompact'],
-      check=False, cwd=util.get_top_dir(), shell=False,
-      stdout=f, stderr=f)
+        util.get_top_dir().joinpath(
+            'prebuilts/build-tools/linux-x86/bin/ninja'),
+        '-f',
+        util.get_out_dir().joinpath(
+            f'combined-{env.get("TARGET_PRODUCT", "aosp_arm")}.ninja'),
+        '-t', 'recompact'],
+        check=False, cwd=util.get_top_dir(), shell=False,
+        stdout=f, stderr=f)
 
   with open(logfile, mode='w') as f:
     action_count_before = get_action_count()
@@ -134,14 +138,14 @@ def _build(build_type: ui.BuildType, run_dir: Path) -> (int, BuildInfo):
     action_count_after = get_action_count()
 
   return (p.returncode, {
-    'build_type': build_type.to_flag(),
-    'build.ninja': _build_file_sha(),
-    'build.ninja.size': _build_file_size(),
-    'targets': ' '.join(ui.get_user_input().targets),
-    'log': str(run_dir.relative_to(ui.get_user_input().log_dir)),
-    'ninja_explains': util.count_explanations(logfile),
-    'actions': action_count_after - action_count_before,
-    'time': util.hhmmss(datetime.timedelta(microseconds=elapsed_ns / 1000))
+      'build_type': build_type.to_flag(),
+      'build.ninja': _build_file_sha(),
+      'build.ninja.size': _build_file_size(),
+      'targets': ' '.join(ui.get_user_input().targets),
+      'log': str(run_dir.relative_to(ui.get_user_input().log_dir)),
+      'ninja_explains': util.count_explanations(logfile),
+      'actions': action_count_after - action_count_before,
+      'time': util.hhmmss(datetime.timedelta(microseconds=elapsed_ns / 1000))
   })
 
 
@@ -163,8 +167,8 @@ def _run_cuj(run_dir: Path, build_type: ui.BuildType,
   # summarize
   log_desc = desc if run == 0 else f'rebuild-{run} after {desc}'
   build_info = {
-                 'description': log_desc,
-                 'build_result': build_result
+                   'description': log_desc,
+                   'build_result': build_result
                } | build_info
   logging.info('%s after %s: %s',
                build_info["build_result"], build_info["time"], log_desc)
@@ -224,7 +228,8 @@ def main():
 
   perf_metrics.tabulate_metrics_csv(user_input.log_dir)
   perf_metrics.display_tabulated_metrics(user_input.log_dir)
-  pretty.pretty(user_input.log_dir, False)
+  pretty.summarize_metrics(user_input.log_dir)
+  pretty.display_summarized_metrics(user_input.log_dir, False)
 
 
 if __name__ == '__main__':
diff --git a/scripts/incremental_build/perf_metrics.py b/scripts/incremental_build/perf_metrics.py
index 4d17e2e0..0ab3e0ef 100755
--- a/scripts/incremental_build/perf_metrics.py
+++ b/scripts/incremental_build/perf_metrics.py
@@ -27,6 +27,7 @@ from pathlib import Path
 from typing import Optional
 
 import util
+import pretty
 
 
 @dataclasses.dataclass
@@ -46,7 +47,7 @@ class PerfInfoOrEvent:
     if isinstance(self.start_time, int):
       epoch = datetime.datetime(1970, 1, 1, tzinfo=datetime.timezone.utc)
       self.start_time = epoch + datetime.timedelta(
-        microseconds=self.start_time / 1000)
+          microseconds=self.start_time / 1000)
 
 
 SOONG_PB = 'soong_metrics'
@@ -245,14 +246,15 @@ def display_tabulated_metrics(log_dir: Path):
   1 To view key metrics in metrics.csv:
     %s
   2 To view column headers:
-    %s'''), output, cmd_str, util.get_csv_columns_cmd(log_dir))
+    %s
+    '''), output, cmd_str, util.get_csv_columns_cmd(log_dir))
 
 
 def main():
   p = argparse.ArgumentParser(
-    formatter_class=argparse.RawTextHelpFormatter,
-    description='read archived perf metrics from [LOG_DIR] and '
-                f'summarize them into {util.METRICS_TABLE}')
+      formatter_class=argparse.RawTextHelpFormatter,
+      description='read archived perf metrics from [LOG_DIR] and '
+                  f'summarize them into {util.METRICS_TABLE}')
   default_log_dir = util.get_default_log_dir()
   p.add_argument('-l', '--log-dir', type=Path, default=default_log_dir,
                  help=textwrap.dedent('''
@@ -273,6 +275,8 @@ def main():
 
   tabulate_metrics_csv(options.log_dir)
   display_tabulated_metrics(options.log_dir)
+  pretty.summarize_metrics(options.log_dir)
+  pretty.display_summarized_metrics(options.log_dir, False)
 
 
 if __name__ == '__main__':
diff --git a/scripts/incremental_build/pretty.py b/scripts/incremental_build/pretty.py
index c1736213..518fe47a 100755..100644
--- a/scripts/incremental_build/pretty.py
+++ b/scripts/incremental_build/pretty.py
@@ -13,13 +13,13 @@
 # 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.
-import argparse
 import csv
-import functools
+import datetime
+import logging
 import re
 import statistics
-import sys
-from decimal import Decimal
+import subprocess
+import textwrap
 from pathlib import Path
 from typing import Callable
 
@@ -27,8 +27,6 @@ from typing.io import TextIO
 
 import util
 
-NA = "   --:--"
-
 
 def normalize_rebuild(line: dict) -> dict:
   line['description'] = re.sub(r'^(rebuild)-[\d+](.*)$', '\\1\\2',
@@ -45,55 +43,12 @@ def groupby(xs: list[dict], keyfn: Callable[[dict], str]) -> dict[
   return grouped
 
 
-def pretty_time(t_secs: Decimal) -> str:
-  s = int(t_secs.to_integral_exact())
-  h = int(s / 3600)
-  s = s % 3600
-  m = int(s / 60)
-  s = s % 60
-  if h > 0:
-    as_str = f'{h}:{m:02d}:{s:02d}'
-  elif m > 0:
-    as_str = f'{m}:{s:02d}'
-  else:
-    as_str = str(s)
-  return f'{as_str:>8s}'
-
-
 def write_table(out: TextIO, rows: list[list[str]]):
-  def cell_width(prev, row):
-    for i in range(len(row)):
-      if len(prev) <= i:
-        prev.append(0)
-      prev[i] = max(prev[i], len(str(row[i])))
-    return prev
-
-  widths = functools.reduce(cell_width, rows, [])
-  fmt = "  ".join([f"%-{width}s" for width in widths]) + "\n"
-
-  def draw_separator():
-    table_width: int = functools.reduce(lambda a, b: a + b + 2, widths)
-    out.write("—" * table_width + "\n")
-
-  draw_separator()
-  out.write(fmt % tuple(str(header) for header in rows[0]))
-  draw_separator()
-  for r in rows[1:]:
-    out.write(fmt % tuple([str(cell) for cell in r]))
-  draw_separator()
-
-
-def seconds(s, acc=Decimal(0.0)) -> Decimal:
-  colonpos = s.find(':')
-  if colonpos > 0:
-    left_part = s[0:colonpos]
-  else:
-    left_part = s
-  acc = acc * 60 + Decimal(left_part)
-  if colonpos > 0:
-    return seconds(s[colonpos + 1:], acc)
-  else:
-    return acc
+  for r in rows:
+    for c in r:
+      out.write(str(c) + ',')
+    out.write('\n')
+  return
 
 
 def _get_build_types(xs: list[dict]) -> list[str]:
@@ -105,19 +60,16 @@ def _get_build_types(xs: list[dict]) -> list[str]:
   return build_types
 
 
-def pretty(log_dir: Path, include_rebuilds: bool):
-  filename = log_dir if log_dir.is_file() else log_dir.joinpath(util.METRICS_TABLE)
+def summarize_metrics(log_dir: Path):
+  filename = log_dir if log_dir.is_file() else log_dir.joinpath(
+      util.METRICS_TABLE)
   with open(filename) as f:
-    csv_lines = [normalize_rebuild(line) for line in
-                 csv.DictReader(f) if
-                 include_rebuilds or not line['description'].startswith(
-                     'rebuild-')]
+    csv_lines = [normalize_rebuild(line) for line in csv.DictReader(f)]
 
   lines: list[dict] = []
   for line in csv_lines:
-    if line["build_result"] != "SUCCESS":
-      print(f"{line['build_result']}: "
-            f"{line['description']} / {line['build_type']}")
+    if line["build_result"] == "FAILED":
+      logging.warning(f"{line['description']} / {line['build_type']}")
     else:
       lines.append(line)
 
@@ -134,22 +86,28 @@ def pretty(log_dir: Path, include_rebuilds: bool):
       for build_type in build_types:
         selected_lines = by_build_type.get(build_type)
         if not selected_lines:
-          row.append(NA)
+          row.append('')
         else:
-          times = [seconds(l['time']) for l in selected_lines]
-          cell = pretty_time(statistics.median(times))
+          times = [util.period_to_seconds(sl['time']) for sl in selected_lines]
+          cell = util.hhmmss(
+              datetime.timedelta(seconds=statistics.median(times)))
           if len(selected_lines) > 1:
             cell = f'{cell}[N={len(selected_lines)}]'
           row.append(cell)
       rows.append(row)
 
-  write_table(sys.stdout, rows)
-
-
-if __name__ == "__main__":
-  p = argparse.ArgumentParser()
-  p.add_argument('--include-rebuilds', default=False, action='store_true')
-  p.add_argument('log_dir', nargs='?', type=Path,
-                 default=util.get_default_log_dir())
-  options = p.parse_args()
-  pretty(options.log_dir, options.include_rebuilds)
+  with open(log_dir.joinpath(util.SUMMARY_TABLE), mode='wt') as f:
+    write_table(f, rows)
+
+
+def display_summarized_metrics(log_dir: Path, include_rebuilds: bool):
+  f = log_dir.joinpath(util.SUMMARY_TABLE)
+  cmd = f'column -t -s, {f}' if include_rebuilds \
+    else f'grep -v rebuild {f} | column -t -s,'
+  output = subprocess.check_output(cmd, shell=True, text=True)
+  logging.info(textwrap.dedent(f'''
+  %s
+  TIPS:
+  To view condensed summary:
+  %s
+  '''), output, cmd)
diff --git a/scripts/incremental_build/util.py b/scripts/incremental_build/util.py
index 95bff31b..9f78328f 100644
--- a/scripts/incremental_build/util.py
+++ b/scripts/incremental_build/util.py
@@ -27,6 +27,7 @@ from typing import Generator
 
 INDICATOR_FILE: Final[str] = 'build/soong/soong_ui.bash'
 METRICS_TABLE: Final[str] = 'metrics.csv'
+SUMMARY_TABLE: Final[str] = 'summary.csv'
 RUN_DIR_PREFIX: Final[str] = 'run'
 BUILD_INFO_JSON: Final[str] = 'build_info.json'
 
@@ -245,7 +246,28 @@ def any_match_under(root: Path, *patterns: str) -> (Path, list[str]):
 
 
 def hhmmss(t: datetime.timedelta) -> str:
+  """pretty prints time periods, prefers mm:ss.sss and resorts to hh:mm:ss.sss
+  only if t >= 1 hour.
+  Examples: 02:12.231, 00:00.512, 00:01:11.321, 1:12:13.121
+  See unit test for more examples."""
   h, f = divmod(t.seconds, 60 * 60)
   m, f = divmod(f, 60)
   s = f + t.microseconds / 1000_000
-  return f'{h:02d}:{m:02d}:{s:06.3f}'
+  return f'{h}:{m:02d}:{s:06.3f}' if h else f'{m:02d}:{s:06.3f}'
+
+
+def period_to_seconds(s: str) -> float:
+  """converts a time period into seconds. The input is expected to be in the
+  format used by hhmmss().
+  Example: 02:04.000 -> 125.0
+  See unit test for more examples."""
+  if s == '':
+    return 0.0
+  acc = 0.0
+  while True:
+    [left, *right] = s.split(':', 1)
+    acc = acc * 60 + float(left)
+    if right:
+      s = right[0]
+    else:
+      return acc
diff --git a/scripts/incremental_build/util_test.py b/scripts/incremental_build/util_test.py
index 0e68bc3a..01b5f9c2 100644
--- a/scripts/incremental_build/util_test.py
+++ b/scripts/incremental_build/util_test.py
@@ -19,6 +19,7 @@ from util import _next_path_helper
 from util import any_match
 from util import get_top_dir
 from util import hhmmss
+from util import period_to_seconds
 
 
 class UtilTest(unittest.TestCase):
@@ -78,10 +79,25 @@ class UtilTest(unittest.TestCase):
 
   def test_hhmmss(self):
     examples = [
-        (datetime.timedelta(seconds=(2 * 60 + 5)), '00:02:05.000'),
+        (datetime.timedelta(seconds=(2 * 60 + 5)), '02:05.000'),
         (datetime.timedelta(seconds=(3600 + 23 * 60 + 45.897898)),
-         '01:23:45.898'),
+         '1:23:45.898'),
     ]
     for (ts, expected) in examples:
       self.subTest(ts=ts, expected=expected)
       self.assertEqual(hhmmss(ts), expected)
+
+  def test_period_to_seconds(self):
+    examples = [
+        ('02:05.000', 2 * 60 + 5),
+        ('1:23:45.898', 3600 + 23 * 60 + 45.898),
+        ('1.898', 1.898),
+        ('0.3', 0.3),
+        ('0', 0),
+        ('0:00', 0),
+        ('0:00:00', 0),
+        ('', 0)
+    ]
+    for (ts, expected) in examples:
+      self.subTest(ts=ts, expected=expected)
+      self.assertEqual(period_to_seconds(ts), expected)