More time logging

Summary: In `BuckPartScope` also log times to the console.

Reviewed By: NTillmann

Differential Revision: D48481598

fbshipit-source-id: 1309f38a8a5ba5d9f3701c829a8ac9ce477a8faa

pyredex/buck.py

@@ -13,8 +13,11 @@
 import os
 import platform
 import typing
+from contextlib import contextmanager
 from io import TextIOWrapper
 
+from pyredex.utils import time_it
+
 
 # Data class for a running step.
 class _RunningPart:
@@ -172,13 +175,23 @@ def __exit__(self, *args: typing.Any) -> None:
             _BUCK_CONNECTION.disconnect()
 
 
-class BuckPartScope:
-    def __init__(self, name: str, desc: str) -> None:
-        self.name = name
-        self.desc = desc
-
-    def __enter__(self) -> None:
-        _BUCK_CONNECTION.start(self.name, self.desc)
-
-    def __exit__(self, *args: typing.Any) -> None:
-        _BUCK_CONNECTION.end()
+@contextmanager
+def BuckPartScope(
+    name: str, desc: str, timed: bool = True, timed_start: bool = True
+) -> typing.Generator[int, None, None]:
+    if timed:
+        with time_it(
+            f"{desc} took {{time:.2f}} seconds",
+            **({"start": desc} if timed_start else {}),
+        ):
+            _BUCK_CONNECTION.start(name, desc)
+            try:
+                yield 1  # Irrelevant
+            finally:
+                _BUCK_CONNECTION.end()
+    else:
+        _BUCK_CONNECTION.start(name, desc)
+        try:
+            yield 1  # Irrelevant
+        finally:
+            _BUCK_CONNECTION.end()

pyredex/packer.py

@@ -248,7 +248,7 @@ def _compress(
         return
 
     with _warning_timer(item.name, 1.0) as _:
-        logging.info("Compressing %s...", item.name)
+        logging.debug("Compressing %s...", item.name)
 
         # If an output name is given, use it. If not, ensure that it is only
         # one file.

pyredex/utils.py

@@ -23,6 +23,7 @@
 import timeit
 import typing
 import zipfile
+from contextlib import contextmanager
 from os.path import basename, dirname, isfile, join
 
 from pyredex.logger import log
@@ -65,7 +66,10 @@ def with_temp_cleanup(
         success = True
     finally:
         if success:
-            remove_temp_dirs()
+            from pyredex.buck import BuckPartScope  # Circular dependency...
+
+            with BuckPartScope("Redex::TempDirs", "Cleaning up temporary directories"):
+                remove_temp_dirs()
 
 
 class _FindAndroidBuildToolHelper:
@@ -499,18 +503,23 @@ def get_file_ext(file_name: str) -> str:
 
 
 def _verify_dex(dex_file: str, cmd: str) -> bool:
-    logging.debug("Verifying %s...", dex_file)
+    try:
+        logging.info("Verifying %s...", dex_file)
 
-    res = subprocess.run(
-        f"{cmd} '{dex_file}'", shell=True, text=False, capture_output=True
-    )
-    if res.returncode == 0:
-        return True
+        res = subprocess.run(
+            f"{cmd} '{dex_file}'", shell=True, text=False, capture_output=True
+        )
+        if res.returncode == 0:
+            return True
 
-    try:
-        stderr_str = res.stderr.decode("utf-8")
-    except BaseException:
-        stderr_str = "<unable to decode, contains non-UTF8>"
+        try:
+            stderr_str = res.stderr.decode("utf-8")
+        except BaseException:
+            stderr_str = "<unable to decode, contains non-UTF8>"
+
+    except BaseException as e:
+        logging.exception("Error for dex file %s", dex_file)
+        stderr_str = f"{e}"
 
     logging.error("Failed verification for %s:\n%s", dex_file, stderr_str)
     return False
@@ -557,3 +566,28 @@ def get_xz_path() -> typing.Optional[str]:
         logging.debug("Using command line xz")
         xz = "xz"
     return xz
+
+
+_TIME_IT_DEPTH: int = 0
+
+
+@contextmanager
+def time_it(
+    fmt: str, *args: typing.Any, **kwargs: str
+) -> typing.Generator[int, None, None]:
+    global _TIME_IT_DEPTH
+    this_depth = _TIME_IT_DEPTH
+    _TIME_IT_DEPTH += 1
+
+    if "start" in kwargs:
+        logging.info("-" * this_depth + kwargs["start"])
+
+    timer = timeit.default_timer
+    start_time = timer()
+    try:
+        yield 1  # Irrelevant
+    finally:
+        end_time = timer()
+        logging.info("-" * this_depth + fmt.format(time=end_time - start_time), *args)
+
+        _TIME_IT_DEPTH -= 1