Added more stylized debugging style

6 files changed, 27 insertions, 19 deletions

diff --git a/src/main/scala/firrtl/Compiler.scala b/src/main/scala/firrtl/Compiler.scala
index 780f5eb0..3da25083 100644
--- a/src/main/scala/firrtl/Compiler.scala
+++ b/src/main/scala/firrtl/Compiler.scala
@@ -131,9 +131,12 @@ abstract class Transform {
 trait SimpleRun extends LazyLogging {
   def runPasses(circuit: Circuit, passSeq: Seq[Pass]): Circuit =
     passSeq.foldLeft(circuit) { (c: Circuit, pass: Pass) =>
-      val x = Utils.time(pass.name) { pass.run(c) }
-      logger.debug(s"** Pass ${pass.name} **")
-      logger.debug(x.serialize)
+      val name = pass.name
+      logger.info(s"-------- Starting Pass $name --------")
+      val (timeMillis, x) = Utils.time { pass.run(c) }
+      logger.info(f"Time: $timeMillis%.1f ms")
+      logger.debug(s"Circuit:\n${c.serialize}")
+      logger.info(s"-------- Finished Pass $name --------")
       x
     }
 }
@@ -311,7 +314,10 @@ trait Compiler extends LazyLogging {
     val allTransforms = CompilerUtils.mergeTransforms(transforms, customTransforms) :+ emitter
 
     val finalState = allTransforms.foldLeft(state) { (in, xform) =>
-      val result = Utils.time(s"***${xform.name}***") { xform.execute(in) }
+      logger.info(s"======== Starting Transform ${xform.name} ========")
+      val (timeMillis, result) = Utils.time { xform.execute(in) }
+
+      logger.info(f"Time: $timeMillis%.1f ms")
 
       val newAnnotations = {
         val inSet = in.annotations.getOrElse(AnnotationMap(Seq.empty)).annotations.toSet
@@ -331,12 +337,15 @@ trait Compiler extends LazyLogging {
         anno <- newAnnotations.toSeq
         newAnno <- anno.update(renames.getOrElse(anno.target, Seq(anno.target)))
       } yield newAnno
-      logger.debug(s"*** ${xform.name} ***")
-      logger.debug(s"Form: ${result.form}")
-      logger.debug(result.circuit.serialize)
+
+      logger.info(s"Form: ${result.form}")
+      logger.debug(s"Annotations:")
       remappedAnnotations.foreach { a =>
         logger.debug(a.serialize)
       }
+      logger.debug(s"Circuit:\n${result.circuit.serialize}")
+      logger.info(s"======== Finished Transform ${xform.name} ========\n")
+
       CircuitState(result.circuit, result.form, Some(AnnotationMap(remappedAnnotations)))
     }
     finalState
diff --git a/src/main/scala/firrtl/Parser.scala b/src/main/scala/firrtl/Parser.scala
index 5f0e682d..f40c465e 100644
--- a/src/main/scala/firrtl/Parser.scala
+++ b/src/main/scala/firrtl/Parser.scala
@@ -26,7 +26,7 @@ object Parser extends LazyLogging {
   /** Takes Iterator over lines of FIRRTL, returns FirrtlNode (root node is Circuit) */
   def parse(lines: Iterator[String], infoMode: InfoMode = UseInfo): Circuit = {
 
-    val cst = time("ANTLR Parser") {
+    val (parseTimeMillis, cst) = time {
       val parser = {
         import scala.collection.JavaConverters._
         val inStream = new SequenceInputStream(
@@ -47,9 +47,10 @@ object Parser extends LazyLogging {
     }
 
     val visitor = new Visitor(infoMode)
-    val ast = time("Visitor") {
+    val (visitTimeMillis, visit) = time {
       visitor.visit(cst)
-    } match {
+    }
+    val ast = visit match {
       case c: Circuit => c
       case x => throw new ClassCastException("Error! AST not rooted with Circuit node!")
     }
diff --git a/src/main/scala/firrtl/Utils.scala b/src/main/scala/firrtl/Utils.scala
index b4ad2e74..c13e031e 100644
--- a/src/main/scala/firrtl/Utils.scala
+++ b/src/main/scala/firrtl/Utils.scala
@@ -130,15 +130,12 @@ class FIRRTLException(str: String) extends Exception(str)
 object Utils extends LazyLogging {
   def throwInternalError =
     error("Internal Error! Please file an issue at https://github.com/ucb-bar/firrtl/issues")
-  private[firrtl] def time[R](name: String)(block: => R): R = {
-    logger.info(s"Starting $name")
+  private[firrtl] def time[R](block: => R): (Double, R) = {
     val t0 = System.nanoTime()
     val result = block
     val t1 = System.nanoTime()
-    logger.info(s"Finished $name")
     val timeMillis = (t1 - t0) / 1000000.0
-    logger.info(f"$name took $timeMillis%.1f ms\n")
-    result
+    (timeMillis, result)
   }
 
   /** Removes all [[firrtl.ir.EmptyStmt]] statements and condenses
diff --git a/src/main/scala/firrtl/annotations/Annotation.scala b/src/main/scala/firrtl/annotations/Annotation.scala
index 9efc6e9b..cbc9bf1c 100644
--- a/src/main/scala/firrtl/annotations/Annotation.scala
+++ b/src/main/scala/firrtl/annotations/Annotation.scala
@@ -35,7 +35,7 @@ object DeletedAnnotation {
     Annotation(anno.target, classOf[Transform], s"""DELETED by $xFormName\n${AnnotationUtils.toYaml(anno)}""")
 
   private val deletedRegex = """(?s)DELETED by ([^\n]*)\n(.*)""".r
-  def unapply(a: Annotation): Option[Tuple2[String, Annotation]] = a match {
+  def unapply(a: Annotation): Option[(String, Annotation)] = a match {
     case Annotation(named, t, deletedRegex(xFormName, annoString)) if t == classOf[Transform] =>
       Some((xFormName, AnnotationUtils.fromYaml(annoString)))
     case _ => None
diff --git a/src/main/scala/logger/Logger.scala b/src/main/scala/logger/Logger.scala
index 07855c47..dcacbc63 100644
--- a/src/main/scala/logger/Logger.scala
+++ b/src/main/scala/logger/Logger.scala
@@ -85,17 +85,21 @@ object Logger {
 class Logger(containerClass: String) {
   def error(message: => String): Unit = {
     Logger.showMessage(LogLevel.Error, containerClass, message)
+    Logger.showMessage(LogLevel.Debug, containerClass, message)
   }
   def warn(message: => String): Unit = {
     Logger.showMessage(LogLevel.Warn, containerClass, message)
+    Logger.showMessage(LogLevel.Debug, containerClass, message)
   }
   def info(message: => String): Unit = {
     Logger.showMessage(LogLevel.Info, containerClass, message)
+    Logger.showMessage(LogLevel.Debug, containerClass, message)
   }
   def debug(message: => String): Unit = {
     Logger.showMessage(LogLevel.Debug, containerClass, message)
   }
   def trace(message: => String): Unit = {
     Logger.showMessage(LogLevel.Trace, containerClass, message)
+    Logger.showMessage(LogLevel.Debug, containerClass, message)
   }
 }
diff --git a/src/test/scala/firrtlTests/ReplSeqMemTests.scala b/src/test/scala/firrtlTests/ReplSeqMemTests.scala
index 93aec7f4..f0dda368 100644
--- a/src/test/scala/firrtlTests/ReplSeqMemTests.scala
+++ b/src/test/scala/firrtlTests/ReplSeqMemTests.scala
@@ -7,11 +7,8 @@ import firrtl.ir._
 import firrtl.passes._
 import firrtl.passes.memlib._
 import annotations._
-import logger.Logger
-import logger.LogLevel.Debug
 
 class ReplSeqMemSpec extends SimpleTransformSpec {
-  def emitter = new LowFirrtlEmitter
   def transforms = Seq(
     new ChirrtlToHighFirrtl(),
     new IRToWorkingIR(),