ハードウェアの気になるあれこれ

技術的に興味のあることを調べて書いてくブログ。主にハードウェアがネタ。

Chiselのシミュレーション実行時にサイクル数を表示する方法

スポンサーリンク

Chiselで書いたモジュールをiotesters.Driverでテストする際に地味ーーに便利(だと思う)なシミュレーションのサイクル数を知る方法についてまとめてみる。

Chiselのテスト実行時の表示について

既に使ったことのある方はご存知のとおりだが、Chiselのテスト機能を使ってシミュレーションを実行した際にログ出力を行うと以下のような表示が得られる。

[info] [0.002] SEED 1564317348485
[info] [0.004] [1] chosen port = 2
valid_0 / ready_0 = 1, 0
valid_1 / ready_1 = 1, 0
valid_2 / ready_2 = 1, 1
valid_3 / ready_3 = 1, 0
[info] [0.006] [2] chosen port = 1
valid_0 / ready_0 = 1, 0
valid_1 / ready_1 = 1, 1
valid_2 / ready_2 = 0, 0
valid_3 / ready_3 = 0, 0
[info] [0.007] [3] chosen port = 0

でこの時間と思しき表記についてだが、Chiselを触りたての頃はこの値はシミュレーションのサイクルとかかなーとか勝手に思い込んでいた。ただ勉強を進めながらテストを色々書いてデバッグをするようになるとどうやらそれは違っていて、単純に実行時間っぽいな、、、と。

改めて調べてみるとChiselのPeekPokeTester内で使用するprintlnPeekPokeTesterのメソッドとして定義されており、実体はTestErrorLogというモジュールの中のinfoメソッドになっていた。

  • iotesters/PeekPokeTester.scala
  implicit val logger = new TestErrorLog

  // ~略~

  def println(msg: String = "") {
    logger.info(msg)
  }
  • iotesters/TestErrors.scala
  /** Emit an informational message */
  def info(m: String): Unit =
    println(new Info("[%2.3f] %s".format(elapsedTime/1e3, m)))  // scalastyle:ignore regex

  // ~略~
  private def elapsedTime: Long = System.currentTimeMillis - startTime

で、上記のinfoメソッドの中で参照されているelapsedTimeを見てもらうとわかる通り、startTimeを現在の時間から引いているので単純にシミュレーション開始時点からの実行時間で間違いなさそう。

Chiselのテスト実行時にサイクル数を知る方法

expectメソッドはFAIL時にはサイクル数の表示も出してくれるが、デバッグ時には何サイクル目で信号がどう変化したといった情報は欲しいので、そのあたりの取得方法を調べてみた。

"--is-verbose"オプション

とりあえず詳細にログが欲しい時には"--is-verbose"をDriver.executeの引数に渡せばいい。これを付与するとpeekpokeといったテスト制御用のメソッドを実行した際にサイクル数とメソッドに応じた出力を表示してくれる

少し前のNICの記事のテスト実行時に付与すると以下のような感じ。

[info] [0.000] SEED 1564319228776
[info] [0.001]   POKE io_in_valid <- 0
[info] [0.001]   POKE io_in_bits_dst <- 0
[info] [0.001]   POKE io_in_bits_data <- 0
[info] [0.001]   POKE io_out_0_ready <- 1
[info] [0.001]   POKE io_out_1_ready <- 1
[info] [0.001]   POKE io_out_2_ready <- 1
[info] [0.001] STEP 0 -> 10
[info] [0.003]   POKE io_in_valid <- 1
[info] [0.003]   POKE io_in_bits_dst <- 0
[info] [0.003]   POKE io_in_bits_data <- 3139097971
[info] [0.003] STEP 10 -> 11
[info] [0.004]   POKE io_in_valid <- 0
[info] [0.004] EXPECT AT 11   io_out_0_valid got 1 expected 1 PASS
[info] [0.004] EXPECT AT 11   io_out_0_bits_dst got 0 expected 0 PASS
[info] [0.004] EXPECT AT 11   io_out_0_bits_data got 3139097971 expected 3139097971 PASS
[info] [0.004] EXPECT AT 11   io_out_1_valid got 0 expected 0 PASS
[info] [0.004] EXPECT AT 11   io_out_1_bits_dst got 0 expected 0 PASS
[info] [0.004] EXPECT AT 11   io_out_1_bits_data got 3139097971 expected 3139097971 PASS
[info] [0.004] EXPECT AT 11   io_out_2_valid got 0 expected 0 PASS
[info] [0.004] EXPECT AT 11   io_out_2_bits_dst got 0 expected 0 PASS
[info] [0.004] EXPECT AT 11   io_out_2_bits_data got 3139097971 expected 3139097971 PASS

ただこの表示信号をが多くなってくると見づらいってのもあるし、データが10進数表記になるから分かりにくいのよね。

PeekPokeTester上で時間を取得して表示

詳細すぎるログだと埋もれてしまうし値が見づらかったりするので、自分でピンポイントでログを整形して出したいといったケースもあると思う。そんな場合に使えるものがないかともう少しソースコードを漁っていく過程で見つけたのが以下。

  • iotesters.PeekPokeTester.scala
  /********************************/
  /*** Classic Tester Interface ***/
  /********************************/
  /* Simulation Time */
  private var simTime = 0L
  protected[iotesters] def incTime(n: Int) { simTime += n }
  def t = simTime

ということで早速試してみる。試すコードは先程"--is-verbose`のお試しに使用したNICDecoderのテストで、そのテストの適当な部分に以下のコードを追加した。

println(f"[$t] in.bits = 0x${peek(in.bits.data)}%08x")

そして以下が実行結果。STEPの右側の表示(10/22)とprintlnの表示が一致しているのが分かると思う。

[info] [0.001] STEP 0 -> 10
[info] [0.003]   POKE io_in_valid <- 1
[info] [0.003]   POKE io_in_bits_dst <- 0
[info] [0.003]   POKE io_in_bits_data <- 3139097971
[info] [0.003]   PEEK io_in_bits_data -> 3139097971
[info] [0.003] [10] in.bits = 0xbb1ad573 <- printlnの表示
~略~
[info] [0.004] STEP 12 -> 22
[info] [0.005]   POKE io_in_valid <- 1
[info] [0.005]   POKE io_in_bits_dst <- 1
[info] [0.005]   POKE io_in_bits_data <- 431529176
[info] [0.005]   PEEK io_in_bits_data -> 431529176
[info] [0.005] [22] in.bits = 0x19b89cd8 <- printlnの表示

これを使えば自分の見たい信号をpeekで取得して、適当に整形してサイクル数と共に表示が出来るので少しはデバッグがしやすくなると思う。