Add Logging for Timing Metrics (#473)

* Updated Timings to be more generic

* Updated api to accept logger hook

* Added print metrics flag

* Updated metrics flag to be shared and stored in Options

* Renamed types and vars

* Updated outstanding refernces to 'logger' when referring to hooks

src/fixit/api.py

@@ -21,6 +21,7 @@
     Config,
     FileContent,
     LintViolation,
+    MetricsHook,
     Options,
     OutputFormat,
     Result,
@@ -99,6 +100,7 @@ def fixit_bytes(
     *,
     config: Config,
     autofix: bool = False,
+    metrics_hook: Optional[MetricsHook] = None,
 ) -> Generator[Result, bool, Optional[FileContent]]:
     """
     Lint raw bytes content representing a single path, using the given configuration.
@@ -127,7 +129,7 @@ def fixit_bytes(
         pending_fixes: List[LintViolation] = []
 
         clean = True
-        for violation in runner.collect_violations(rules, config):
+        for violation in runner.collect_violations(rules, config, metrics_hook):
             clean = False
             fix = yield Result(path, violation)
             if fix or autofix:
@@ -153,6 +155,7 @@ def fixit_stdin(
     *,
     autofix: bool = False,
     options: Optional[Options] = None,
+    metrics_hook: Optional[MetricsHook] = None,
 ) -> Generator[Result, bool, None]:
     """
     Wrapper around :func:`fixit_bytes` for formatting content from STDIN.
@@ -169,7 +172,9 @@ def fixit_stdin(
         content: FileContent = sys.stdin.buffer.read()
         config = generate_config(path, options=options)
 
-        updated = yield from fixit_bytes(path, content, config=config, autofix=autofix)
+        updated = yield from fixit_bytes(
+            path, content, config=config, autofix=autofix, metrics_hook=metrics_hook
+        )
         if autofix:
             sys.stdout.buffer.write(updated or content)
 
@@ -183,6 +188,7 @@ def fixit_file(
     *,
     autofix: bool = False,
     options: Optional[Options] = None,
+    metrics_hook: Optional[MetricsHook] = None,
 ) -> Generator[Result, bool, None]:
     """
     Lint a single file on disk, detecting and generating appropriate configuration.
@@ -201,7 +207,9 @@ def fixit_file(
         content: FileContent = path.read_bytes()
         config = generate_config(path, options=options)
 
-        updated = yield from fixit_bytes(path, content, config=config, autofix=autofix)
+        updated = yield from fixit_bytes(
+            path, content, config=config, autofix=autofix, metrics_hook=metrics_hook
+        )
         if updated and updated != content:
             LOG.info(f"{path}: writing changes to file")
             path.write_bytes(updated)
@@ -212,13 +220,19 @@ def fixit_file(
 
 
 def _fixit_file_wrapper(
-    path: Path, *, autofix: bool = False, options: Optional[Options] = None
+    path: Path,
+    *,
+    autofix: bool = False,
+    options: Optional[Options] = None,
+    metrics_hook: Optional[MetricsHook] = None,
 ) -> List[Result]:
     """
     Wrapper because generators can't be pickled or used directly via multiprocessing
     TODO: replace this with some sort of queue or whatever
     """
-    return list(fixit_file(path, autofix=autofix, options=options))
+    return list(
+        fixit_file(path, autofix=autofix, options=options, metrics_hook=metrics_hook)
+    )
 
 
 def fixit_paths(
@@ -227,6 +241,7 @@ def fixit_paths(
     autofix: bool = False,
     options: Optional[Options] = None,
     parallel: bool = True,
+    metrics_hook: Optional[MetricsHook] = None,
 ) -> Generator[Result, bool, None]:
     """
     Lint multiple files or directories, recursively expanding each path.
@@ -276,11 +291,20 @@ def fixit_paths(
             expanded_paths.extend(trailrunner.walk(path))
 
     if is_stdin:
-        yield from fixit_stdin(stdin_path, autofix=autofix, options=options)
+        yield from fixit_stdin(
+            stdin_path, autofix=autofix, options=options, metrics_hook=metrics_hook
+        )
     elif len(expanded_paths) == 1 or not parallel:
         for path in expanded_paths:
-            yield from fixit_file(path, autofix=autofix, options=options)
+            yield from fixit_file(
+                path, autofix=autofix, options=options, metrics_hook=metrics_hook
+            )
     else:
-        fn = partial(_fixit_file_wrapper, autofix=autofix, options=options)
+        fn = partial(
+            _fixit_file_wrapper,
+            autofix=autofix,
+            options=options,
+            metrics_hook=metrics_hook,
+        )
         for _, results in trailrunner.run_iter(expanded_paths, fn):
             yield from results

src/fixit/cli.py

@@ -86,6 +86,7 @@ def f(v: int) -> str:
     default="",
     help="Python format template to use with output format 'custom'",
 )
+@click.option("--print-metrics", is_flag=True, help="Print metrics of this run")
 def main(
     ctx: click.Context,
     debug: Optional[bool],
@@ -94,6 +95,7 @@ def main(
     rules: str,
     output_format: Optional[OutputFormat],
     output_template: str,
+    print_metrics: bool,
 ) -> None:
     level = logging.WARNING
     if debug is not None:
@@ -113,6 +115,7 @@ def main(
         ),
         output_format=output_format,
         output_template=output_template,
+        print_metrics=print_metrics,
     )
 
 
@@ -140,7 +143,9 @@ def lint(
     dirty: Set[Path] = set()
     autofixes = 0
     config = generate_config(options=options)
-    for result in fixit_paths(paths, options=options):
+    for result in fixit_paths(
+        paths, options=options, metrics_hook=print if options.print_metrics else None
+    ):
         visited.add(result.path)
         if print_result(
             result,
@@ -200,7 +205,13 @@ def fix(
 
     # TODO: make this parallel
     generator = capture(
-        fixit_paths(paths, autofix=autofix, options=options, parallel=False)
+        fixit_paths(
+            paths,
+            autofix=autofix,
+            options=options,
+            parallel=False,
+            metrics_hook=print if options.print_metrics else None,
+        )
     )
     config = generate_config(options=options)
     for result in generator:

src/fixit/engine.py

@@ -19,9 +19,9 @@
     Config,
     FileContent,
     LintViolation,
+    Metrics,
+    MetricsHook,
     NodeReplacement,
-    Timings,
-    TimingsHook,
 )
 from .rule import LintRule
 
@@ -53,17 +53,17 @@ def __init__(self, path: Path, source: FileContent) -> None:
         self.path = path
         self.source = source
         self.module: Module = parse_module(source)
-        self.timings: Timings = defaultdict(lambda: 0)
+        self.metrics: Metrics = defaultdict(lambda: 0)
 
     def collect_violations(
         self,
         rules: Collection[LintRule],
         config: Config,
-        timings_hook: Optional[TimingsHook] = None,
+        metrics_hook: Optional[MetricsHook] = None,
     ) -> Generator[LintViolation, None, int]:
         """Run multiple `LintRule`s and yield any lint violations.
 
-        The optional `timings_hook` parameter will be called (if provided) after all
+        The optional `metrics_hook` parameter will be called (if provided) after all
         lint rules have finished running, passing in a dictionary of
         ``RuleName.visit_function_name`` -> ``duration in microseconds``.
         """
@@ -76,7 +76,7 @@ def visit_hook(name: str) -> Iterator[None]:
             finally:
                 duration_us = int(1000 * 1000 * (time.perf_counter() - start))
                 LOG.debug(f"PERF: {name} took {duration_us} µs")
-                self.timings[name] += duration_us
+                self.metrics[name] += duration_us
 
         metadata_cache: Mapping[ProviderT, object] = {}
         needs_repo_manager: Set[ProviderT] = set()
@@ -111,8 +111,8 @@ def visit_hook(name: str) -> Iterator[None]:
                     violation = replace(violation, diff=diff)
 
                 yield violation
-        if timings_hook:
-            timings_hook(self.timings)
+        if metrics_hook:
+            metrics_hook(self.metrics)
 
         return count
 

src/fixit/ftypes.py

@@ -46,8 +46,8 @@
 
 NodeReplacement = Union[CSTNodeT, FlattenSentinel[CSTNodeT], RemovalSentinel]
 
-Timings = Dict[str, int]
-TimingsHook = Callable[[Timings], None]
+Metrics = Dict[str, Any]
+MetricsHook = Callable[[Metrics], None]
 
 VisitorMethod = Callable[[CSTNode], None]
 VisitHook = Callable[[str], ContextManager[None]]
@@ -191,6 +191,7 @@ class Options:
     rules: Sequence[QualifiedRule] = ()
     output_format: Optional[OutputFormat] = None
     output_template: str = ""
+    print_metrics: bool = False
 
 
 @dataclass

src/fixit/tests/rule.py

@@ -47,15 +47,15 @@ def test_timing(self) -> None:
         rule = NoopRule()
         for _ in self.runner.collect_violations([rule], Config()):
             pass  # exhaust the generator
-        self.assertIn("NoopRule.visit_Module", self.runner.timings)
-        self.assertIn("NoopRule.leave_Module", self.runner.timings)
-        self.assertGreaterEqual(self.runner.timings["NoopRule.visit_Module"], 0)
+        self.assertIn("NoopRule.visit_Module", self.runner.metrics)
+        self.assertIn("NoopRule.leave_Module", self.runner.metrics)
+        self.assertGreaterEqual(self.runner.metrics["NoopRule.visit_Module"], 0)
 
     def test_timing_hook(self) -> None:
         rule = NoopRule()
         hook = MagicMock()
         for i, _ in enumerate(
-            self.runner.collect_violations([rule], Config(), timings_hook=hook)
+            self.runner.collect_violations([rule], Config(), metrics_hook=hook)
         ):
             if i <= 1:
                 # only called at the end