Add back support for simplified fine-grained logging

mypy/build.py

@@ -55,6 +55,13 @@
 from mypy.server.deps import get_dependencies
 
 
+# Switch to True to produce debug output related to fine-grained incremental
+# mode only that is useful during development. This produces only a subset of
+# output compared to --verbose output. We use a global flag to enable this so
+# that it's easy to enable this when running tests.
+DEBUG_FINE_GRAINED = False
+
+
 PYTHON_EXTENSIONS = ['.pyi', '.py']
 
 
@@ -734,6 +741,17 @@ def log(self, *message: str) -> None:
                 print(file=sys.stderr)
             sys.stderr.flush()
 
+    def log_fine_grained(self, *message: str) -> None:
+        if self.options.verbosity >= 1:
+            self.log('fine-grained:', *message)
+        elif DEBUG_FINE_GRAINED:
+            # Output log in a simplified format that is quick to browse.
+            if message:
+                print(*message, file=sys.stderr)
+            else:
+                print(file=sys.stderr)
+            sys.stderr.flush()
+
     def trace(self, *message: str) -> None:
         if self.options.verbosity >= 2:
             print('TRACE:', *message, file=sys.stderr)

mypy/server/update.py

@@ -123,7 +123,7 @@
 
 from mypy.build import (
     BuildManager, State, BuildSource, Graph, load_graph, SavedCache, CacheMeta,
-    cache_meta_from_dict, find_module_clear_caches
+    cache_meta_from_dict, find_module_clear_caches, DEBUG_FINE_GRAINED
 )
 from mypy.checker import DeferredNode
 from mypy.errors import Errors, CompileError
@@ -201,23 +201,23 @@ def update(self, changed_modules: List[Tuple[str, str]]) -> List[str]:
         self.triggered = []
         changed_modules = dedupe_modules(changed_modules + self.stale)
         initial_set = {id for id, _ in changed_modules}
-        self.manager.log('fine-grained: ==== update %s ====' % ', '.join(
+        self.manager.log_fine_grained('==== update %s ====' % ', '.join(
             repr(id) for id, _ in changed_modules))
-        if self.previous_targets_with_errors and self.options.verbosity >= 1:
-            self.manager.log('fine-grained: previous targets with errors: %s' %
+        if self.previous_targets_with_errors and is_verbose(self.manager):
+            self.manager.log_fine_grained('previous targets with errors: %s' %
                              sorted(self.previous_targets_with_errors))
 
         if self.blocking_error:
             # Handle blocking errors first. We'll exit as soon as we find a
             # module that still has blocking errors.
-            self.manager.log('fine-grained: existing blocker: %s' % self.blocking_error[0])
+            self.manager.log_fine_grained('existing blocker: %s' % self.blocking_error[0])
             changed_modules = dedupe_modules([self.blocking_error] + changed_modules)
             self.blocking_error = None
 
         while changed_modules:
             next_id, next_path = changed_modules.pop(0)
             if next_id not in self.previous_modules and next_id not in initial_set:
-                self.manager.log('fine-grained: skip %r (module not in import graph)' % next_id)
+                self.manager.log_fine_grained('skip %r (module not in import graph)' % next_id)
                 continue
             result = self.update_single(next_id, next_path)
             messages, remaining, (next_id, next_path), blocker = result
@@ -248,7 +248,7 @@ def update_single(self, module: str, path: str) -> Tuple[List[str],
             - Module which was actually processed as (id, path) tuple
             - Whether there was a blocking error in the module
         """
-        self.manager.log('fine-grained: --- update single %r ---' % module)
+        self.manager.log_fine_grained('--- update single %r ---' % module)
 
         # TODO: If new module brings in other modules, we parse some files multiple times.
         manager = self.manager
@@ -272,10 +272,10 @@ def update_single(self, module: str, path: str) -> Tuple[List[str],
 
         # TODO: What to do with stale dependencies?
         triggered = calculate_active_triggers(manager, old_snapshots, {module: tree})
-        if self.options.verbosity >= 1:
+        if is_verbose(self.manager):
             filtered = [trigger for trigger in triggered
                         if not trigger.endswith('__>')]
-            self.manager.log('fine-grained: triggered: %r' % sorted(filtered))
+            self.manager.log_fine_grained('triggered: %r' % sorted(filtered))
         self.triggered.extend(triggered | self.previous_targets_with_errors)
         collect_dependencies({module: tree}, self.deps, graph)
         remaining += propagate_changes_using_dependencies(
@@ -367,7 +367,7 @@ def update_single_isolated(module: str,
     if module in manager.modules:
         assert_equivalent_paths(path, manager.modules[module].path)
     else:
-        manager.log('fine-grained: new module %r' % module)
+        manager.log_fine_grained('new module %r' % module)
 
     old_modules = dict(manager.modules)
     sources = get_sources(previous_modules, [(module, path)])
@@ -411,7 +411,7 @@ def update_single_isolated(module: str,
             else:
                 del manager.modules[id]
             del graph[id]
-        manager.log('fine-grained: --> %r (newly imported)' % module)
+        manager.log_fine_grained('--> %r (newly imported)' % module)
     else:
         remaining_modules = []
 
@@ -485,7 +485,7 @@ def assert_equivalent_paths(path1: str, path2: str) -> None:
 def delete_module(module_id: str,
                   graph: Dict[str, State],
                   manager: BuildManager) -> Dict[str, State]:
-    manager.log('fine-grained: delete module %r' % module_id)
+    manager.log_fine_grained('delete module %r' % module_id)
     # TODO: Deletion of a package
     # TODO: Remove deps for the module (this only affects memory use, not correctness)
     assert module_id not in graph
@@ -735,7 +735,7 @@ def propagate_changes_using_dependencies(
             if id is not None and id not in up_to_date_modules:
                 if id not in todo:
                     todo[id] = set()
-                manager.log('fine-grained: process: %s' % target)
+                manager.log_fine_grained('process: %s' % target)
                 todo[id].update(lookup_target(manager.modules, target))
         triggered = set()
         # TODO: Preserve order (set is not optimal)
@@ -753,8 +753,8 @@ def propagate_changes_using_dependencies(
         # dependency loop that loops back to an originally processed module.
         up_to_date_modules = set()
         targets_with_errors = set()
-        if manager.options.verbosity >= 1:
-            manager.log('fine-grained: triggered: %r' % list(triggered))
+        if is_verbose(manager):
+            manager.log_fine_grained('triggered: %r' % list(triggered))
 
     return remaining_modules
 
@@ -793,7 +793,7 @@ def find_targets_recursive(
                     continue
                 if module_id not in result:
                     result[module_id] = set()
-                manager.log('fine-grained: process %s' % target)
+                manager.log_fine_grained('process %s' % target)
                 deferred = lookup_target(modules, target)
                 result[module_id].update(deferred)
 
@@ -810,7 +810,7 @@ def reprocess_nodes(manager: BuildManager,
     Return fired triggers.
     """
     if module_id not in manager.saved_cache or module_id not in graph:
-        manager.log('fine-grained: %s not in saved cache or graph (blocking errors or deleted?)' %
+        manager.log_fine_grained('%s not in saved cache or graph (blocking errors or deleted?)' %
                     module_id)
         return set()
 
@@ -1008,3 +1008,7 @@ def extract_type_maps(graph: Graph) -> Dict[str, Dict[Expression, Type]]:
     # This is used to export information used only by the testmerge harness.
     return {id: state.type_map() for id, state in graph.items()
             if state.tree}
+
+
+def is_verbose(manager: BuildManager) -> bool:
+    return manager.options.verbosity > 1 or DEBUG_FINE_GRAINED