Merge pull request #159 from freechipsproject/fix-printf-match-verila…

…tor-2

Make printf behavior more closely match verilator

src/main/scala/treadle/TreadleOptions.scala

@@ -205,6 +205,19 @@ case object CallResetAtStartupAnnotation extends NoTargetAnnotation with Treadle
   )
 }
 
+/**
+  *  Tells treadle to prefix printf strings with a wall time
+  */
+case object PrefixPrintfWithWallTime extends NoTargetAnnotation with TreadleOption with HasShellOptions {
+  val options: Seq[ShellOption[_]] = Seq(
+    new ShellOption[Unit](
+      longOption = "tr-prefix-printf-with-walltime",
+      toAnnotationSeq = _ => Seq(PrefixPrintfWithWallTime),
+      helpText = """Adds a string "[<wall-time>]" to the front of printf lines, helps match to vcd"""
+    )
+  )
+}
+
 /**
   * The circuit used to build a [[TreadleTester]]
   * @param circuit a firrtl ast

src/main/scala/treadle/executable/ExecutionEngine.scala

@@ -32,6 +32,8 @@ class ExecutionEngine(
     expressionViews
   )
 
+  scheduler.executionEngineOpt = Some(this)
+
   if(annotationSeq.collectFirst { case ShowFirrtlAtLoadAnnotation => ShowFirrtlAtLoadAnnotation }.isDefined) {
     println(ast.serialize)
   }
@@ -464,6 +466,9 @@ object ExecutionEngine {
       Seq.empty
     )
     val allowCycles = annotationSeq.exists { case AllowCyclesAnnotation => true; case _ => false }
+    val prefixPrintfWithTime = annotationSeq.exists { case PrefixPrintfWithWallTime => true; case _ => false }
+
+
     val rollbackBuffers = annotationSeq.collectFirst{ case RollBackBuffersAnnotation(rbb) => rbb }.getOrElse(
       TreadleDefaults.RollbackBuffers
     )
@@ -486,7 +491,9 @@ object ExecutionEngine {
 
     val scheduler = new Scheduler(symbolTable)
 
-    val compiler = new ExpressionCompiler(symbolTable, dataStore, scheduler, validIfIsRandom, blackBoxFactories)
+    val compiler = new ExpressionCompiler(
+      symbolTable, dataStore, scheduler, validIfIsRandom, prefixPrintfWithTime, blackBoxFactories
+    )
 
     timer("Build Compiled Expressions") {
       compiler.compile(circuit, blackBoxFactories)

src/main/scala/treadle/executable/ExpressionCompiler.scala

@@ -11,10 +11,11 @@ import treadle.utils.FindModule
 import scala.collection.mutable
 
 class ExpressionCompiler(
-    val symbolTable  : SymbolTable,
-    val dataStore    : DataStore,
-    scheduler        : Scheduler,
-    validIfIsRandom  : Boolean,
+    val symbolTable      : SymbolTable,
+    val dataStore        : DataStore,
+    scheduler            : Scheduler,
+    validIfIsRandom      : Boolean,
+    prefixPrintfWithTime : Boolean,
     blackBoxFactories: Seq[ScalaBlackBoxFactory]
 )
   extends logger.LazyLogging {
@@ -907,7 +908,9 @@ class ExpressionCompiler(
                     getWidth(expression)
                   },
                   clockTransitionGetter,
-                  intExpression
+                  intExpression,
+                  scheduler,
+                  prefixPrintfWithTime
                 )
                 addAssigner(printOp)
               case _ =>

src/main/scala/treadle/executable/PrintfOp.scala

@@ -14,7 +14,9 @@ case class PrintfOp(
   args            : Seq[ExpressionResult],
   fieldWidths     : Seq[Int],
   clockTransition : ClockTransitionGetter,
-  condition       : IntExpressionResult
+  condition       : IntExpressionResult,
+  scheduler       : Scheduler,
+  addWallTime     : Boolean
 ) extends Assigner {
 
   private val formatString = string.escape
@@ -30,7 +32,7 @@ case class PrintfOp(
           throw TreadleException(s"In printf got unknown result in arguments to printf ${string.toString}")
       }
       val instantiatedString = executeVerilogPrint(formatString, currentArgValues)
-      print(instantiatedString.drop(1).dropRight(1))
+      print(instantiatedString)
     }
 
     () => Unit
@@ -110,13 +112,19 @@ case class PrintfOp(
 
   def executeVerilogPrint(formatString: String, allArgs: Seq[BigInt]): String = {
     val processedArgs = allArgs.zip(filterFunctions).map { case (arg, filter) => filter(arg) }
-    paddedFormatString.format(processedArgs:_*)
+    if(addWallTime) {
+      val time = scheduler.executionEngineOpt match {
+        case Some(executionEngine) => executionEngine.wallTime.currentTime
+        case _ => 0L
+      }
+      f"[$time%4d] " + paddedFormatString.format(processedArgs:_*).drop(1).dropRight(1)
+    }
+    else {
+      paddedFormatString.format(processedArgs:_*).drop(1).dropRight(1)
+    }
   }
 
   val (paddedFormatString, filterFunctions) = constructFormatter(formatString, bitWidths = fieldWidths)
-
-  val x = 22
-
 }
 
 object PrintfOp {

src/main/scala/treadle/executable/Scheduler.scala

@@ -25,6 +25,8 @@ class Scheduler(val symbolTable: SymbolTable) extends LazyLogging {
 
   private val toAssigner: mutable.HashMap[Symbol, Assigner] = new mutable.HashMap()
 
+  var executionEngineOpt: Option[ExecutionEngine] = None
+
   def addAssigner(
     symbol: Symbol,
     assigner: Assigner,

src/main/scala/treadle/stage/phases/PrepareAst.scala

@@ -113,7 +113,8 @@ object PrepareAst extends TreadlePhase {
       new HighToLow,
       new TreadleLowFirrtlOptimization,
       new BlackBoxSourceHelper,
-      new FixupOps
+      new FixupOps,
+      AugmentPrintf
     )
   }
 }

src/main/scala/treadle/utils/AugmentPrintf.scala

@@ -17,15 +17,11 @@ object AugmentPrintf extends Transform {
     import firrtl._
     def insert(newStmts: mutable.ArrayBuffer[Statement], namespace: Namespace, info: Info, clockExpression: Expression)
             (a: Expression): Expression = {
-      if (Utils.kind(a) == RegKind) {
         val newName = namespace.newTemp
-        val wref = WRef(newName, a.tpe, NodeKind, MALE)
+        val wref = WRef(newName, a.tpe, NodeKind, SourceFlow)
         newStmts += DefRegister(info, newName, a.tpe, clockExpression, UIntLiteral(0), UIntLiteral(0))
         newStmts += Connect(info, wref, a)
         wref
-      } else {
-        a
-      }
     }
 
     def fixPrintsStmt(namespace: firrtl.Namespace)
@@ -36,7 +32,12 @@ object AugmentPrintf extends Transform {
         Block(newStmts :+ newStop)
       case p: Print =>
         val newStmts = mutable.ArrayBuffer[Statement]()
-        val newPrint = p.mapExpr(insert(newStmts, namespace, p.info, p.clk))
+        val newName = namespace.newTemp
+        val wref = WRef(newName, p.en.tpe, NodeKind, SourceFlow)
+        newStmts += DefRegister(p.info, newName, p.en.tpe, p.clk, UIntLiteral(0), UIntLiteral(0))
+        newStmts += Connect(p.info, wref, p.en)
+
+        val newPrint: Print = p.mapExpr(insert(newStmts, namespace, p.info, p.clk)).asInstanceOf[Print].copy(en = wref)
         Block(newStmts :+ newPrint)
       case other => other
     }

src/test/scala/treadle/PrintStopSpec.scala

@@ -251,7 +251,7 @@ class PrintStopSpec extends FlatSpec with Matchers with LazyLogging {
         |      node _T_3 = bits(reset, 0, 0) @[PrintfWrong.scala 19:11]
         |      node _T_4 = eq(_T_3, UInt<1>("h00")) @[PrintfWrong.scala 19:11]
         |      when _T_4 : @[PrintfWrong.scala 19:11]
-        |        printf(clock, UInt<1>(1), "+++ y=%d ry=%d rry=%d isZero=%x is480=%x\n", y, regY, regRegY, _T_1, _T_2) @[PrintfWrong.scala 19:11]
+        |        printf(clock, UInt<1>(1), "+++ y=%d ry=%d rry=%d rryIsZero(_T_1)=%x rryIs480(_T_2)=%x\n", y, regY, regRegY, _T_1, _T_2) @[PrintfWrong.scala 19:11]
         |        skip @[PrintfWrong.scala 19:11]
         |      skip @[PrintfWrong.scala 18:28]
         |    io.out <= regRegY @[PrintfWrong.scala 22:10]
@@ -261,7 +261,7 @@ class PrintStopSpec extends FlatSpec with Matchers with LazyLogging {
 
     val output = new ByteArrayOutputStream()
     Console.withOut(new PrintStream(output)) {
-      val tester = TreadleTester(Seq(FirrtlSourceAnnotation(input)))
+      val tester = TreadleTester(Seq(FirrtlSourceAnnotation(input), WriteVcdAnnotation, PrefixPrintfWithWallTime))
 
       tester.poke("io_in", 479)
       tester.step()
@@ -270,16 +270,25 @@ class PrintStopSpec extends FlatSpec with Matchers with LazyLogging {
       tester.step()
 
       tester.poke("io_in", 481)
-      tester.step()
+      tester.step(3)
+      tester.finish
 
     }
 
+    // "+++ count=    0 r0=   0 r1=   0"
+    // "+++ count=    0 r0=   0 r1=   1"
+
+
+
+    Logger.setLevel("treadle.PrintStopSpec", LogLevel.Debug)
     logger.debug(output.toString)
 
     output
       .toString
       .split("\n")
-      .count { line => line.contains("+++ y=  481 ry=  481 rry=  480 isZero=0 is480=1") } should be (1)
+      .count { line =>
+        line.contains("+++ y=  481 ry=  481 rry=  480 rryIsZero(_T_1)=0 rryIs480(_T_2)=1")
+      } should be (1)
 
     output
       .toString
@@ -379,10 +388,10 @@ class PrintStopSpec extends FlatSpec with Matchers with LazyLogging {
 
     logger.debug(output.toString)
 
-    printfLines.head should include ("+++ count=    0 r0=   0 r1=   1")
+    printfLines.head should include ("+++ count=    0 r0=   0 r1=   0")
 
     val linesCorrect = printfLines
-            .tail
+            .drop(2)
             .zipWithIndex
             .map { case (line, lineNumber) =>
               if (lineNumber % 2 == 0) {

src/test/scala/treadle/PrintfCorrectnessSpec.scala

@@ -65,29 +65,33 @@ class PrintfCorrectnessSpec extends FreeSpec with Matchers with LazyLogging {
         |    reg _GEN_7 : UInt<8>, clock with :
         |      reset => (UInt<1>("h0"), UInt<1>("h0")) @[PrintfTreadleVsVerilatorTest.scala 50:9]
         |    _GEN_7 <= tailPointer @[PrintfTreadleVsVerilatorTest.scala 50:9]
-        |    printf(clock, _T_25, "PRINTF:%d moveHead %d, moveTail %d, head %d, tail %d, nextTail %d\n", _GEN_3, moveHead, moveTail, _GEN_6, _GEN_7, nextTail) @[PrintfTreadleVsVerilatorTest.scala 50:9]
+        |    printf(clock, _T_25, "PRINTF:moveHead %d, moveTail %d, head %d, tail %d, nextTail %d\n", moveHead, moveTail, _GEN_6, _GEN_7, nextTail) @[PrintfTreadleVsVerilatorTest.scala 50:9]
         |
         |""".stripMargin
 
     val output = new ByteArrayOutputStream()
     Console.withOut(new PrintStream(output)) {
-      val tester = TreadleTester(Seq(FirrtlSourceAnnotation(input)))
+      val tester = TreadleTester(Seq(FirrtlSourceAnnotation(input), WriteVcdAnnotation))
       tester.step()
       tester.poke("moveTail", 1)
       tester.step()
       tester.step()
+      tester.step()
       tester.finish
     }
 
+
+    Logger.setLevel("treadle.PrintfCorrectnessSpec", LogLevel.Debug)
     logger.debug(output.toString)
 
 
+    val outputString = output.toString
     Seq(
-      "PRINTF:   0 moveHead  0, moveTail  0, head    0, tail    0, nextTail    1",
-      "PRINTF:   1 moveHead  0, moveTail  1, head    0, tail    0, nextTail    2",
-      "PRINTF:   2 moveHead  0, moveTail  1, head    0, tail    1, nextTail    3"
+      "PRINTF:moveHead  0, moveTail  0, head    0, tail    0, nextTail    1",
+      "PRINTF:moveHead  0, moveTail  1, head    0, tail    0, nextTail    2",
+      "PRINTF:moveHead  0, moveTail  1, head    0, tail    1, nextTail    3"
     ).foreach { targetLine =>
-      output.toString.contains(targetLine) should be (true)
+      outputString should include (targetLine)
     }
   }
 }

src/test/scala/treadle/PrintfTimingSpec.scala

@@ -0,0 +1,53 @@
+// See README.md for license details.
+
+package treadle
+
+import firrtl.stage.FirrtlSourceAnnotation
+import org.scalatest.{FreeSpec, Matchers}
+
+private class PrintfTimingSpec extends FreeSpec with Matchers {
+  "printf has strict timing requirements" - {
+    "it must fire before registers are updated" in {
+      val input =
+        """
+          |;buildInfoPackage: chisel3, version: 3.2-SNAPSHOT, scalaVersion: 2.12.6, sbtVersion: 1.2.7
+          |circuit Printf1 :
+          |  module Printf1 :
+          |    input clock : Clock
+          |    input reset : UInt<1>
+          |
+          |    reg reg0 : UInt<8>, clock
+          |    reg0 <= add(reg0, UInt(1))
+          |
+          |    node wire0 = add(reg0, UInt(1))
+          |
+          |    printf(clock, UInt<1>(1), "reg0=%x wire0=%x\n", reg0, wire0)
+          |""".stripMargin
+
+      val treadleTester = TreadleTester(Seq(FirrtlSourceAnnotation(input), WriteVcdAnnotation))
+      treadleTester.step(10)
+      treadleTester.finish
+    }
+    "printf every other time based on reg" in {
+      val input =
+        """
+          |;buildInfoPackage: chisel3, version: 3.2-SNAPSHOT, scalaVersion: 2.12.6, sbtVersion: 1.2.7
+          |circuit Printf2 :
+          |  module Printf2 :
+          |    input clock : Clock
+          |    input reset : UInt<1>
+          |
+          |    reg reg0 : UInt<8>, clock
+          |    reg0 <= add(reg0, UInt(1))
+          |
+          |    node enable = eq(mod(reg0, UInt(4)), UInt(0))
+          |
+          |    printf(clock, enable, "reg0=%x\n", reg0)
+          |""".stripMargin
+
+      val treadleTester = TreadleTester(Seq(FirrtlSourceAnnotation(input), WriteVcdAnnotation))
+      treadleTester.step(10)
+      treadleTester.finish
+    }
+  }
+}

src/test/scala/treadle/chronometry/PrintfOnDerivedClockSpec.scala

@@ -6,10 +6,11 @@ import java.io.{ByteArrayOutputStream, PrintStream}
 
 import firrtl.options.TargetDirAnnotation
 import firrtl.stage.{FirrtlSourceAnnotation, OutputFileAnnotation}
+import logger.{LazyLogging, LogLevel, Logger}
 import org.scalatest.{FreeSpec, Matchers}
-import treadle.TreadleTester
+import treadle.{PrefixPrintfWithWallTime, TreadleTester, WriteVcdAnnotation}
 
-class PrintfOnDerivedClockSpec extends FreeSpec with Matchers {
+class PrintfOnDerivedClockSpec extends FreeSpec with Matchers with LazyLogging {
   "Printf in submodule in scope of withClock should appear in output" in {
     val input =
       """
@@ -22,7 +23,7 @@ class PrintfOnDerivedClockSpec extends FreeSpec with Matchers {
         |    spi.out <= spi.sck
         |    node derived_clock = asClock(spi.sck)
         |    node out_from_clock = asUInt(derived_clock)
-        |    printf(derived_clock, UInt<1>(1), "SPI spi.sck=%d derived_clock=%d\n", spi.sck, out_from_clock)
+        |    printf(derived_clock, UInt<1>(1), "SPI spi.sck=%d derived_clock=%d DERIVED\n", spi.sck, out_from_clock)
         |
         |  module Outer :
         |    input clock : Clock
@@ -42,21 +43,27 @@ class PrintfOnDerivedClockSpec extends FreeSpec with Matchers {
     Console.withOut(new PrintStream(output)) {
       val options = Seq(
         TargetDirAnnotation("test_run_dir/print_on_derived_clock"),
-        OutputFileAnnotation("printf_on_derived_clock")
+        OutputFileAnnotation("printf_on_derived_clock"),
+        PrefixPrintfWithWallTime,
+        WriteVcdAnnotation
       )
 
       val tester = TreadleTester(FirrtlSourceAnnotation(input) +: options)
+      tester.step() // currently without this the first printf does not happen :-(, reset is behind a register
       tester.poke("io_in", 1)
       tester.step()
       tester.poke("io_in", 0)
       tester.step()
       tester.poke("io_in", 1)
       tester.step()
       tester.poke("io_in", 0)
-      tester.step()
+      tester.step(3)
       tester.finish
     }
 
+    Logger.setLevel("treadle.chronometry.PrintfOnDerivedClockSpec", LogLevel.Debug)
+    logger.debug(output.toString)
+
     // printf will be in output twice once for each up transition of io_in, which drives the derived clock
     output.toString.split("\n").count( line => line.contains("SPI spi.sck=")) should be (2)
   }