googlefonts / ufo2ft

A bridge from UFOs to FontTools objects (and therefore, OTFs and TTFs).
MIT License
151 stars 43 forks source link

Add more timing information #641

Closed simoncozens closed 2 years ago

anthrotype commented 2 years ago

I was touching the same code here and in fontmake cleaning things up a bit, but I am not as fast as you 😅 I'll see if we can consolidate the work

anthrotype commented 2 years ago

@simoncozens PTAL https://github.com/googlefonts/fontmake/pull/919

anthrotype commented 2 years ago

@simoncozens since you're touching this code here, I drop the local patch I have here so you can apply if you like.

There's the ufo2ft.filters.base module which uses a Timer class to compute how long each filter run takes, and at the end also prints the number of glyphs that the filter has modified.

It makes sense to use the same "ufo2ft.timer" logger for this (currently it was using the "ufo2ft.filters.base" logger but since it issues a debug message it was only visible when fontmake --verbose DEBUG, the --timing flag had no effect on this as you found out).

diff --git a/Lib/ufo2ft/filters/base.py b/Lib/ufo2ft/filters/base.py
index 60c7690..23c0b7f 100644
--- a/Lib/ufo2ft/filters/base.py
+++ b/Lib/ufo2ft/filters/base.py
@@ -5,7 +5,13 @@ from fontTools.misc.loggingTools import Timer

 from ufo2ft.util import _GlyphSet, _LazyFontName, getMaxComponentDepth

-logger = logging.getLogger(__name__)
+# reuse the "ufo2ft.filters" logger instead of creating one just for
+# "ufo2ft.filters.base", which seems redundant.
+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 +210,7 @@ class BaseFilter:

         num = len(modified)
         if num > 0:
-            logger.debug(
+            timing_logger.debug(
                 "Took %.3fs to run %s on %d glyph%s",
                 t,
                 self.name,
anthrotype commented 2 years ago

(the reason that code is not using a with timer(f"run {self.name} on {len(modified)} glyphs"): ... statement, but is calling directly the "ufo2ft.timer" logger, is because the number of modified glyphs isn't known at the time of entering the context manager but only after the filter has completed)

anthrotype commented 2 years ago

heads up, I think after merging #637 to main, there're merge conflicts with this and the other pending PR of yours