Add more timing information (#641)

Lib/ufo2ft/__init__.py

@@ -5,6 +5,7 @@
 from fontTools import varLib
 from fontTools.designspaceLib import DesignSpaceDocument
 from fontTools.designspaceLib.split import splitInterpolable, splitVariableFonts
+from fontTools.misc.loggingTools import Timer
 from fontTools.otlLib.optimize.gpos import GPOS_COMPACT_MODE_ENV_KEY
 
 from ufo2ft.constants import SPARSE_OTF_MASTER_TABLES, SPARSE_TTF_MASTER_TABLES
@@ -35,6 +36,7 @@
 
 
 logger = logging.getLogger(__name__)
+timer = Timer(logging.getLogger("ufo2ft.timer"), level=logging.DEBUG)
 
 
 class CFFOptimization(IntEnum):
@@ -43,6 +45,7 @@ class CFFOptimization(IntEnum):
     SUBROUTINIZE = 2
 
 
+@timer("preprocess UFO")
 def call_preprocessor(ufo_or_ufos, *, preProcessorClass, **kwargs):
     logger.info("Pre-processing glyphs")
     if kwargs["skipExportGlyphs"] is None:
@@ -70,17 +73,19 @@ def call_preprocessor(ufo_or_ufos, *, preProcessorClass, **kwargs):
     return preProcessor.process()
 
 
+@timer("compile a basic TTF")
 def call_outline_compiler(ufo, glyphSet, *, outlineCompilerClass, **kwargs):
     kwargs = prune_unknown_kwargs(kwargs, outlineCompilerClass)
     outlineCompiler = outlineCompilerClass(ufo, glyphSet=glyphSet, **kwargs)
     return outlineCompiler.compile()
 
 
 def call_postprocessor(otf, ufo, glyphSet, *, postProcessorClass, **kwargs):
-    if postProcessorClass is not None:
-        postProcessor = postProcessorClass(otf, ufo, glyphSet=glyphSet)
-        kwargs = prune_unknown_kwargs(kwargs, postProcessor.process)
-        otf = postProcessor.process(**kwargs)
+    with timer("postprocess TTF"):
+        if postProcessorClass is not None:
+            postProcessor = postProcessorClass(otf, ufo, glyphSet=glyphSet)
+            kwargs = prune_unknown_kwargs(kwargs, postProcessor.process)
+            otf = postProcessor.process(**kwargs)
     return otf
 
 
@@ -603,13 +608,15 @@ def compileVariableTTFs(designSpaceDoc: DesignSpaceDocument, **kwargs):
 
     logger.info("Building variable TTF fonts: %s", ", ".join(vfNameToBaseUfo))
 
-    vfNameToTTFont = varLib.build_many(
-        designSpaceDoc,
-        exclude=excludeVariationTables,
-        optimize=optimizeGvar,
-        skip_vf=lambda vf_name: variableFontNames and vf_name not in variableFontNames,
-        colr_layer_reuse=colrLayerReuse,
-    )
+    with timer("merge fonts to variable"):
+        vfNameToTTFont = varLib.build_many(
+            designSpaceDoc,
+            exclude=excludeVariationTables,
+            optimize=optimizeGvar,
+            skip_vf=lambda vf_name: variableFontNames
+            and vf_name not in variableFontNames,
+            colr_layer_reuse=colrLayerReuse,
+        )
 
     for vfName, varfont in list(vfNameToTTFont.items()):
         vfNameToTTFont[vfName] = call_postprocessor(

Lib/ufo2ft/featureCompiler.py

@@ -9,6 +9,7 @@
 from fontTools.feaLib.builder import addOpenTypeFeaturesFromString
 from fontTools.feaLib.error import FeatureLibError, IncludedFeaNotFound
 from fontTools.feaLib.parser import Parser
+from fontTools.misc.loggingTools import Timer
 
 from ufo2ft.constants import MTI_FEATURES_PREFIX
 from ufo2ft.featureWriters import (
@@ -22,6 +23,7 @@
 )
 
 logger = logging.getLogger(__name__)
+timer = Timer(logging.getLogger("ufo2ft.timer"), level=logging.DEBUG)
 
 
 def parseLayoutFeatures(font, includeDir=None):
@@ -275,17 +277,18 @@ def setupFeatures(self):
         may override this method to handle the file creation
         in a different way if desired.
         """
-        if self.featureWriters:
-            featureFile = parseLayoutFeatures(self.ufo, self.feaIncludeDir)
+        with timer("run feature writers"):
+            if self.featureWriters:
+                featureFile = parseLayoutFeatures(self.ufo, self.feaIncludeDir)
 
-            for writer in self.featureWriters:
-                writer.write(self.ufo, featureFile, compiler=self)
+                for writer in self.featureWriters:
+                    writer.write(self.ufo, featureFile, compiler=self)
 
-            # stringify AST to get correct line numbers in error messages
-            self.features = featureFile.asFea()
-        else:
-            # no featureWriters, simply read existing features' text
-            self.features = self.ufo.features.text or ""
+                # stringify AST to get correct line numbers in error messages
+                self.features = featureFile.asFea()
+            else:
+                # no featureWriters, simply read existing features' text
+                self.features = self.ufo.features.text or ""
 
     def writeFeatures(self, outfile):
         if hasattr(self, "features"):
@@ -308,16 +311,19 @@ def buildTables(self):
         # if we generated some automatic features, includes have already been
         # resolved, and we work from a string which does't exist on disk
         path = self.ufo.path if not self.featureWriters else None
-        try:
-            addOpenTypeFeaturesFromString(self.ttFont, self.features, filename=path)
-        except FeatureLibError:
-            if path is None:
-                # if compilation fails, create temporary file for inspection
-                data = self.features.encode("utf-8")
-                with NamedTemporaryFile(delete=False) as tmp:
-                    tmp.write(data)
-                logger.error("Compilation failed! Inspect temporary file: %r", tmp.name)
-            raise
+        with timer("build OpenType features"):
+            try:
+                addOpenTypeFeaturesFromString(self.ttFont, self.features, filename=path)
+            except FeatureLibError:
+                if path is None:
+                    # if compilation fails, create temporary file for inspection
+                    data = self.features.encode("utf-8")
+                    with NamedTemporaryFile(delete=False) as tmp:
+                        tmp.write(data)
+                    logger.error(
+                        "Compilation failed! Inspect temporary file: %r", tmp.name
+                    )
+                raise
 
 
 class MtiFeatureCompiler(BaseFeatureCompiler):

Lib/ufo2ft/filters/base.py

@@ -5,7 +5,12 @@
 
 from ufo2ft.util import _GlyphSet, _LazyFontName, getMaxComponentDepth
 
-logger = logging.getLogger(__name__)
+# reuse the "ufo2ft.filters" logger
+logger = logging.getLogger("ufo2ft.filters")
+
+# library-level logger specialized for timing info which apps like fontmake
+# can selectively configure
+timing_logger = logging.getLogger("ufo2ft.timer")
 
 
 class BaseFilter:
@@ -204,7 +209,7 @@ def __call__(self, font, glyphSet=None):
 
         num = len(modified)
         if num > 0:
-            logger.debug(
+            timing_logger.debug(
                 "Took %.3fs to run %s on %d glyph%s",
                 t,
                 self.name,