FPGA開発日記

カテゴリ別記事インデックス https://msyksphinz.github.io/github_pages , English Version https://fpgadevdiary.hatenadiary.com/

gem5のデバッグ情報を深堀する

例えば、gem5でのシミュレーション結果、以下のようなパイプライン情報を取得したものとする。 このような、s4580 で示されるlw命令がどのように動作しているのかを見てみたい。ログを取得することでその動作の詳細を確認できる。

まず、命令の動作記録を確認するためには、デバッグ時の情報として--debug-flags=ExecAllを追加する。これにより、命令の実行状況がログとして出力されるようになる。

$ ./build/RISCV/gem5.opt --debug-flags=ExecAll --debug-file=hello.log configs/example/se.py  --cpu-type=O3CPU --caches --cmd ./tests/test-progs/hello/src/hello.bare.riscv

このとき、シリアル番号s4580で示された命令を確認してみる。

$ grep 4580 m5out/hello.log

4313000: system.cpu: A0 T0 : 0x10a5a @__sfvwrite_r+736    : c_lw a3, 12(s0)            : MemRead :  D=0x0000000000000000 A=0x13c8c  FetchSeq=4580  CPSeq=1512  flags=(IsInteger|IsLoad)

最初の数字は非常に大きいので、だいたい500くらいで割れば、1サイクル毎の情報にすることができる。

次に、命令の発行状況とコミットの状況を取得する。このためには、sn:<シリアル番号>で検索してみるとよい。

$ ./build/RISCV/gem5.opt --debug-flags=IEW,Commit,ExecAll --debug-file=hello.log configs/example/se.py  --cpu-type=O3CPU --caches --cmd ./tests/test-progs/hello/src/hello.bare.riscv

grep -e =4580 -e sn:4580 m5out/hello.log 

4315500(8631): system.cpu.commit: [tid:0] [sn:4580] Inserting PC (0x10a5a=>0x10a5c).(0=>1) into ROB.
4316000(8632): system.cpu.iew: [tid:0] Issue: Adding PC (0x10a5a=>0x10a5c).(0=>1) [sn:4580] [tid:0] to IQ.
4316500(8633): system.cpu.iew: Execute: Processing PC (0x10a5a=>0x10a5c).(0=>1), [tid:0] [sn:4580].
4316500(8633): system.cpu.commit: [tid:0] Can't commit, Instruction [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1) is head of ROB and not ready
4317000(8634): system.cpu.commit: [tid:0] Can't commit, Instruction [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1) is head of ROB and not ready
4317500(8635): system.cpu.iew: Sending instructions to commit, [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1).
4317500(8635): system.cpu.commit: [tid:0] Can't commit, Instruction [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1) is head of ROB and not ready
4318000(8636): system.cpu.commit: [tid:0] Marking PC (0x10a5a=>0x10a5c).(0=>1), [sn:4580] ready within ROB.
4318000(8636): system.cpu.commit: [tid:0] Instruction [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1) is head of ROB and ready to commit
4318500(8637): system.cpu.commit: Trying to commit head instruction, [tid:0] [sn:4580]
4318500(8637): system.cpu.commit: [tid:0] [sn:4580] Committing instruction with PC (0x10a5a=>0x10a5c).(0=>1)
4313000(8626): system.cpu: A0 T0 : 0x10a5a @__sfvwrite_r+736    : c_lw a3, 12(s0)            : MemRead :  D=0x0000000000000000 A=0x13c8c  FetchSeq=4580  CPSeq=1512  flags=(IsInteger|IsLoad)

Can't commitは、おそらくROBの先頭に当該命令がいるものの、命令が実行完了になっておらずコミットできていない状態だと思う。 命令の発行状況を見るために、IQデバッグを追加して、命令発行ユニットの状況を確認する。

$ ./build/RISCV/gem5.opt --debug-flags=IEW,Commit,ExecAll,IQ --debug-file=hello.log configs/example/se.py  --cpu-type=O3CPU --caches --cmd ./tests/test-progs/hello/src/hello.bare.riscv
$ grep -e =4580 -e sn:4580 m5out/hello.log

4315000(8630): global: [sn:4580] has 1 ready out of 1 sources. RTI 0)
4315500(8631): system.cpu.commit: [tid:0] [sn:4580] Inserting PC (0x10a5a=>0x10a5c).(0=>1) into ROB.
4316000(8632): system.cpu.iew: [tid:0] Issue: Adding PC (0x10a5a=>0x10a5c).(0=>1) [sn:4580] [tid:0] to IQ.
4316000(8632): system.cpu.iq: Adding instruction [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1) to the IQ.
4316000(8632): system.cpu.iq: Instruction is ready to issue, putting it onto the ready list, PC (0x10a5a=>0x10a5c).(0=>1) opclass:47 [sn:4580].
4316000(8632): system.cpu.iq: Thread 0: Issuing instruction PC (0x10a5a=>0x10a5c).(0=>1) [sn:4580]
4316500(8633): system.cpu.iew: Execute: Processing PC (0x10a5a=>0x10a5c).(0=>1), [tid:0] [sn:4580].
4316500(8633): system.cpu.commit: [tid:0] Can't commit, Instruction [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1) is head of ROB and not ready
4317000(8634): system.cpu.commit: [tid:0] Can't commit, Instruction [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1) is head of ROB and not ready
4317500(8635): system.cpu.iew: Sending instructions to commit, [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1).
4317500(8635): system.cpu.iq: Completing mem instruction PC: (0x10a5a=>0x10a5c).(0=>1) [sn:4580]
4317500(8635): system.cpu.commit: [tid:0] Can't commit, Instruction [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1) is head of ROB and not ready
4318000(8636): system.cpu.commit: [tid:0] Marking PC (0x10a5a=>0x10a5c).(0=>1), [sn:4580] ready within ROB.
4318000(8636): system.cpu.commit: [tid:0] Instruction [sn:4580] PC (0x10a5a=>0x10a5c).(0=>1) is head of ROB and ready to commit
4318500(8637): system.cpu.commit: Trying to commit head instruction, [tid:0] [sn:4580]
4318500(8637): system.cpu.commit: [tid:0] [sn:4580] Committing instruction with PC (0x10a5a=>0x10a5c).(0=>1)
4313000(8626): system.cpu: A0 T0 : 0x10a5a @__sfvwrite_r+736    : c_lw a3, 12(s0)            : MemRead :  D=0x0000000000000000 A=0x13c8c  FetchSeq=4580  CPSeq=1512  flags=(IsInteger|IsLoad)
4319000(8638): system.cpu.iq: [tid:0] Committing instructions older than [sn:4580]

命令の発行自体は、4316000(8632)に終わっているのだが、そこからコミットまでは4318500(8637)までかかっている。 さらに、Completing mem instructionが4317500(8635)なので、最初の図では、ISが示すのは命令発行そのもので、そこから実行される様子は表示されていない。 これは、コミットのタイミングから判断するしかないということか。