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
内で使用するprintln
はPeekPokeTester
のメソッドとして定義されており、実体は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
の引数に渡せばいい。これを付与するとpeek
やpoke
といったテスト制御用のメソッドを実行した際にサイクル数とメソッドに応じた出力を表示してくれる
少し前の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
で取得して、適当に整形してサイクル数と共に表示が出来るので少しはデバッグがしやすくなると思う。