Hoist Transform timing to the Phase level (#2190)

With Stage/Phase, users can provide complex functionality at the phase
level rather than just the transform level. It is useful to have the
same logging information at that level. Note that this change still logs
transforms in the same way, but now the time in inclusive of annotation
renaming which can also [unfortunately] be slow.

Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

4 files changed, 11 insertions, 17 deletions

diff --git a/src/main/scala/firrtl/Compiler.scala b/src/main/scala/firrtl/Compiler.scala
index 38b71f4a..2998af3c 100644
--- a/src/main/scala/firrtl/Compiler.scala
+++ b/src/main/scala/firrtl/Compiler.scala
@@ -210,22 +210,9 @@ final case object UnknownForm extends CircuitForm(-1) {
 // Internal utilities to keep code DRY, not a clean interface
 private[firrtl] object Transform {
 
-  // Run transform with logging
-  def runTransform(name: String, mk: => CircuitState, logger: Logger): CircuitState = {
-    logger.info(s"======== Starting Transform $name ========")
-
-    val (timeMillis, result) = Utils.time(mk)
-
-    logger.info(s"""----------------------------${"-" * name.size}---------\n""")
-    logger.info(f"Time: $timeMillis%.1f ms")
-
-    result
-  }
-
   def remapAnnotations(name: String, before: CircuitState, after: CircuitState, logger: Logger): CircuitState = {
     val remappedAnnotations = propagateAnnotations(name, logger, before.annotations, after.annotations, after.renames)
 
-    logger.info(s"Form: ${after.form}")
     logger.trace(s"Annotations:")
     logger.trace {
       JsonProtocol
@@ -240,7 +227,6 @@ private[firrtl] object Transform {
     }
 
     logger.trace(s"Circuit:\n${after.circuit.serialize}")
-    logger.info(s"======== Finished Transform $name ========\n")
 
     CircuitState(after.circuit, after.form, remappedAnnotations, None)
   }
@@ -385,7 +371,7 @@ trait Transform extends TransformLike[CircuitState] with DependencyAPI[Transform
     * @return A transformed Firrtl AST
     */
   final def runTransform(state: CircuitState): CircuitState = {
-    val result = Transform.runTransform(name, execute(prepare(state)), logger)
+    val result = execute(prepare(state))
     Transform.remapAnnotations(name, state, result, logger)
   }
 
diff --git a/src/main/scala/firrtl/options/DependencyManager.scala b/src/main/scala/firrtl/options/DependencyManager.scala
index 5e911940..f8299bbb 100644
--- a/src/main/scala/firrtl/options/DependencyManager.scala
+++ b/src/main/scala/firrtl/options/DependencyManager.scala
@@ -275,7 +275,14 @@ trait DependencyManager[A, B <: TransformLike[A] with DependencyAPI[B]] extends
                 |  prerequisites: ${prerequisites.mkString("\n    -", "\n    -", "")}""".stripMargin
           )
         }
-        (t.transform(a), ((state + wrapperToClass(t)).map(dToO).filterNot(t.invalidates).map(oToD)))
+        val logger = t.getLogger
+        logger.info(s"======== Starting ${t.name} ========")
+        val (timeMillis, annosx) = firrtl.Utils.time { t.transform(a) }
+        logger.info(s"""----------------------------${"-" * t.name.size}---------\n""")
+        logger.info(f"Time: $timeMillis%.1f ms")
+        logger.info(s"======== Finished ${t.name} ========")
+        val statex = (state + wrapperToClass(t)).map(dToO).filterNot(t.invalidates).map(oToD)
+        (annosx, statex)
     }._1
   }
 
diff --git a/src/main/scala/firrtl/stage/transforms/UpdateAnnotations.scala b/src/main/scala/firrtl/stage/transforms/UpdateAnnotations.scala
index 4fa7788d..8bd29b9c 100644
--- a/src/main/scala/firrtl/stage/transforms/UpdateAnnotations.scala
+++ b/src/main/scala/firrtl/stage/transforms/UpdateAnnotations.scala
@@ -19,7 +19,7 @@ class UpdateAnnotations(val underlying: Transform)
   }
 
   def internalTransform(b: (CircuitState, CircuitState)): (CircuitState, CircuitState) = {
-    val result = Transform.runTransform(name, underlying.transform(b._2), logger)
+    val result = underlying.transform(b._2)
     (b._1, result)
   }
 }
diff --git a/src/main/scala/logger/Logger.scala b/src/main/scala/logger/Logger.scala
index 20c1338e..09fc0924 100644
--- a/src/main/scala/logger/Logger.scala
+++ b/src/main/scala/logger/Logger.scala
@@ -47,6 +47,7 @@ object LogLevel extends Enumeration {
   */
 trait LazyLogging {
   protected val logger = new Logger(this.getClass.getName)
+  def getLogger: Logger = logger
 }
 
 /**