Make sure debug printing is consistent #59

powerjg · 2019-05-15T17:49:23Z

Related to #23

Currently, when you run a single cycle in the single stepper, it's not clear whether you're seeing the output from before or after the cycle has happened. To make matters worse, I believe that some components print the "old" value and some the "new" value. Specifically, I believe registers and wires have different behavior.

We need to investigate this to figure out exactly what's going on. One solution would be to remove the printfs in the Chisel code and do everything from the Single stepper. Also, getting #23 would probably go a long way towards fixing this issue.

@cjnitta, anything to add to this?

Email from Chris:

I'm trying to help a student debug their circuit, and there seems to be
a delay with the update of wires by one cycle. I have a similar setup to
them, but I ran:
runMain dinocpu.singlestep addi2 pipelined
It is on the write data to the register file, and the toreg. I see it in
the bundle on cycle 4 to be 17 and 0, but don't see the update of
write_data until a cycle later. Below is the relevant code, and the
output from my single stepping. Is there a reason wires are delayed a
cycle when in regards to the printing?

Thanks,
Chris

val write_data = Wire(UInt(32.W))
...
when (mem_wb.wbcontrol.toreg === 1.U) {
     write_data := mem_wb.readdata
   } .elsewhen (mem_wb.wbcontrol.toreg === 2.U) {
     write_data := mem_wb.wbcontrol.pcplusfour
   } .otherwise {
     write_data := mem_wb.result
   }
...
   printf("writedata: %d\ntoreg: %d\n", write_data, mem_wb.wbcontrol.toreg)


Cycles > 1
Cycle=1 IF/ID: Bundle(instruction -> 17827091, pc -> 0, pcplusfour -> 4)
DASM(1100513)
ID/EX: Bundle(excontrol -> Bundle(pc -> 0, sextImm -> 0, readdata1 -> 0, 
readdata2 -> 0, rs1 -> 0, rs2 -> 0, funct7 -> 0, add -> 0, immediate -> 
0, alusrc1 -> 0, branch -> 0, jump -> 0), mcontrol -> Bundle(memread -> 
0, memwrite -> 0, funct3 -> 0), wbcontrol -> Bundle(pcplusfour -> 0, 
toreg -> 3, regwrite -> 0, rd -> 0))
EX/MEM: Bundle(brtarget -> 0, brtaken -> 0, result -> 0, writedata -> 0, 
mcontrol -> Bundle(memread -> 0, memwrite -> 0, funct3 -> 0), wbcontrol 
-> Bundle(pcplusfour -> 0, toreg -> 0, regwrite -> 0, rd -> 0))
MEM/WB: Bundle(result -> 0, readdata -> 19, wbcontrol -> 
Bundle(pcplusfour -> 0, toreg -> 0, regwrite -> 0, rd -> 0))
writedata: 0
toreg: 0
---------------------------------------------
Cycles > 1
Cycle=2 IF/ID: Bundle(instruction -> 80020883, pc -> 4, pcplusfour -> 8)
DASM(4c50593)
ID/EX: Bundle(excontrol -> Bundle(pc -> 0, sextImm -> 17, readdata1 -> 
0, readdata2 -> 0, rs1 -> 0, rs2 -> 17, funct7 -> 0, add -> 0, immediate 
-> 1, alusrc1 -> 0, branch -> 0, jump -> 0), mcontrol -> Bundle(memread 
-> 0, memwrite -> 0, funct3 -> 0), wbcontrol -> Bundle(pcplusfour -> 4, 
toreg -> 0, regwrite -> 1, rd -> 10))
EX/MEM: Bundle(brtarget -> 0, brtaken -> 0, result -> 0, writedata -> 0, 
mcontrol -> Bundle(memread -> 0, memwrite -> 0, funct3 -> 0), wbcontrol 
-> Bundle(pcplusfour -> 0, toreg -> 3, regwrite -> 0, rd -> 0))
MEM/WB: Bundle(result -> 0, readdata -> 19, wbcontrol -> 
Bundle(pcplusfour -> 0, toreg -> 0, regwrite -> 0, rd -> 0))
writedata: 0
toreg: 0
---------------------------------------------
Cycles > 1
Cycle=3 IF/ID: Bundle(instruction -> 19, pc -> 8, pcplusfour -> 12)
DASM(13)
ID/EX: Bundle(excontrol -> Bundle(pc -> 4, sextImm -> 76, readdata1 -> 
0, readdata2 -> 0, rs1 -> 10, rs2 -> 12, funct7 -> 2, add -> 0, 
immediate -> 1, alusrc1 -> 0, branch -> 0, jump -> 0), mcontrol -> 
Bundle(memread -> 0, memwrite -> 0, funct3 -> 0), wbcontrol -> 
Bundle(pcplusfour -> 8, toreg -> 0, regwrite -> 1, rd -> 11))
EX/MEM: Bundle(brtarget -> 16, brtaken -> 0, result -> 17, writedata -> 
0, mcontrol -> Bundle(memread -> 0, memwrite -> 0, funct3 -> 0), 
wbcontrol -> Bundle(pcplusfour -> 4, toreg -> 0, regwrite -> 1, rd -> 10))
MEM/WB: Bundle(result -> 0, readdata -> 19, wbcontrol -> 
Bundle(pcplusfour -> 0, toreg -> 3, regwrite -> 0, rd -> 0))
writedata: 0
toreg: 3
---------------------------------------------
Cycles > 1
Cycle=4 IF/ID: Bundle(instruction -> 19, pc -> 12, pcplusfour -> 16)
DASM(13)
ID/EX: Bundle(excontrol -> Bundle(pc -> 8, sextImm -> 0, readdata1 -> 0, 
readdata2 -> 0, rs1 -> 0, rs2 -> 0, funct7 -> 0, add -> 0, immediate -> 
1, alusrc1 -> 0, branch -> 0, jump -> 0), mcontrol -> Bundle(memread -> 
0, memwrite -> 0, funct3 -> 0), wbcontrol -> Bundle(pcplusfour -> 12, 
toreg -> 0, regwrite -> 1, rd -> 0))
EX/MEM: Bundle(brtarget -> 92, brtaken -> 0, result -> 93, writedata -> 
0, mcontrol -> Bundle(memread -> 0, memwrite -> 0, funct3 -> 0), 
wbcontrol -> Bundle(pcplusfour -> 8, toreg -> 0, regwrite -> 1, rd -> 11))
MEM/WB: Bundle(result -> 17, readdata -> 19, wbcontrol -> 
Bundle(pcplusfour -> 4, toreg -> 0, regwrite -> 1, rd -> 10))
writedata: 0
toreg: 0
---------------------------------------------
Cycles > 1
Cycle=5 IF/ID: Bundle(instruction -> 19, pc -> 16, pcplusfour -> 20)
DASM(13)
ID/EX: Bundle(excontrol -> Bundle(pc -> 12, sextImm -> 0, readdata1 -> 
0, readdata2 -> 0, rs1 -> 0, rs2 -> 0, funct7 -> 0, add -> 0, immediate 
-> 1, alusrc1 -> 0, branch -> 0, jump -> 0), mcontrol -> Bundle(memread 
-> 0, memwrite -> 0, funct3 -> 0), wbcontrol -> Bundle(pcplusfour -> 16, 
toreg -> 0, regwrite -> 1, rd -> 0))
EX/MEM: Bundle(brtarget -> 0, brtaken -> 0, result -> 0, writedata -> 0, 
mcontrol -> Bundle(memread -> 0, memwrite -> 0, funct3 -> 0), wbcontrol 
-> Bundle(pcplusfour -> 12, toreg -> 0, regwrite -> 1, rd -> 0))
MEM/WB: Bundle(result -> 93, readdata -> 0, wbcontrol -> 
Bundle(pcplusfour -> 8, toreg -> 0, regwrite -> 1, rd -> 11))
writedata: 17
toreg: 0
---------------------------------------------
Cycles > q

The text was updated successfully, but these errors were encountered:

powerjg · 2019-05-15T17:49:55Z

@DanG100, this might be a good thing to look at since you're working on testing infrastructure.

DanG100 · 2019-05-15T18:41:00Z

The output is quite different on the CPU in this repo (with the different chisel snapshot). It looks like the print statement are evaluated before the registers are set in that cycle. It look consistent though, in cycle 3, the wires and the regs have the same value.

Cycles > 1
---------------------------------------------
MEM/WB: MEMWBBundle(writereg -> 0, aluresult -> 0, readdata -> 0, pcplusfour -> 0, wbcontrol -> WBControl(toreg -> 0, regwrite -> 0))
EX/MEM: EXMEMBundle(writereg -> 0, readdata2 -> 0, aluresult -> 0, nextpc -> 0, pcplusfour -> 0, mcontrol -> MControl(memread -> 0, memwrite -> 0, taken -> 0, maskmode -> 0, sext -> 0), wbcontrol -> WBControl(toreg -> 0, regwrite -> 0))
ID/EX: IDEXBundle(writereg -> 0, funct7 -> 0, funct3 -> 0, imm -> 0, readdata2 -> 0, readdata1 -> 0, pc -> 0, pcplusfour -> 0, excontrol -> EXControl(add -> 0, immediate -> 0, alusrc1 -> 0, branch -> 0, jump -> 0, prediction -> 0), mcontrol -> MControl(memread -> 0, memwrite -> 0, taken -> 0, maskmode -> 0, sext -> 0), wbcontrol -> WBControl(toreg -> 0, regwrite -> 0), rs1 -> 0, rs2 -> 0, branchpc -> 0)
DASM(0)
IF/ID: IFIDBundle(instruction -> 0, pc -> 0, pcplusfour -> 0)
PC: 0
Cycle=0 
writedata: 0
toreg: 0
Cycles > 1
---------------------------------------------
MEM/WB: MEMWBBundle(writereg -> 0, aluresult -> 0, readdata -> 19, pcplusfour -> 0, wbcontrol -> WBControl(toreg -> 0, regwrite -> 0))
EX/MEM: EXMEMBundle(writereg -> 0, readdata2 -> 0, aluresult -> 0, nextpc -> 0, pcplusfour -> 0, mcontrol -> MControl(memread -> 0, memwrite -> 0, taken -> 0, maskmode -> 0, sext -> 0), wbcontrol -> WBControl(toreg -> 0, regwrite -> 0))
ID/EX: IDEXBundle(writereg -> 0, funct7 -> 0, funct3 -> 0, imm -> 0, readdata2 -> 0, readdata1 -> 0, pc -> 0, pcplusfour -> 0, excontrol -> EXControl(add -> 0, immediate -> 0, alusrc1 -> 0, branch -> 0, jump -> 0, prediction -> 0), mcontrol -> MControl(memread -> 0, memwrite -> 0, taken -> 0, maskmode -> 0, sext -> 1), wbcontrol -> WBControl(toreg -> 3, regwrite -> 0), rs1 -> 0, rs2 -> 0, branchpc -> 0)
DASM(1100513)
IF/ID: IFIDBundle(instruction -> 17827091, pc -> 0, pcplusfour -> 4)
PC: 4
Cycle=1 
writedata: 0
toreg: 0
Cycles > 1
---------------------------------------------
MEM/WB: MEMWBBundle(writereg -> 0, aluresult -> 0, readdata -> 19, pcplusfour -> 0, wbcontrol -> WBControl(toreg -> 0, regwrite -> 0))
EX/MEM: EXMEMBundle(writereg -> 0, readdata2 -> 0, aluresult -> 0, nextpc -> 0, pcplusfour -> 0, mcontrol -> MControl(memread -> 0, memwrite -> 0, taken -> 0, maskmode -> 0, sext -> 1), wbcontrol -> WBControl(toreg -> 3, regwrite -> 0))
ID/EX: IDEXBundle(writereg -> 10, funct7 -> 0, funct3 -> 0, imm -> 17, readdata2 -> 0, readdata1 -> 0, pc -> 0, pcplusfour -> 4, excontrol -> EXControl(add -> 0, immediate -> 1, alusrc1 -> 0, branch -> 0, jump -> 0, prediction -> 0), mcontrol -> MControl(memread -> 0, memwrite -> 0, taken -> 0, maskmode -> 0, sext -> 1), wbcontrol -> WBControl(toreg -> 0, regwrite -> 1), rs1 -> 0, rs2 -> 17, branchpc -> 17)
DASM(4c50593)
IF/ID: IFIDBundle(instruction -> 80020883, pc -> 4, pcplusfour -> 8)
PC: 8
Cycle=2 
writedata: 0
toreg: 0
Cycles > 1
---------------------------------------------
MEM/WB: MEMWBBundle(writereg -> 0, aluresult -> 0, readdata -> 19, pcplusfour -> 0, wbcontrol -> WBControl(toreg -> 3, regwrite -> 0))
EX/MEM: EXMEMBundle(writereg -> 10, readdata2 -> 0, aluresult -> 17, nextpc -> 4, pcplusfour -> 4, mcontrol -> MControl(memread -> 0, memwrite -> 0, taken -> 0, maskmode -> 0, sext -> 1), wbcontrol -> WBControl(toreg -> 0, regwrite -> 1))
ID/EX: IDEXBundle(writereg -> 11, funct7 -> 2, funct3 -> 0, imm -> 76, readdata2 -> 0, readdata1 -> 0, pc -> 4, pcplusfour -> 8, excontrol -> EXControl(add -> 0, immediate -> 1, alusrc1 -> 0, branch -> 0, jump -> 0, prediction -> 0), mcontrol -> MControl(memread -> 0, memwrite -> 0, taken -> 0, maskmode -> 0, sext -> 1), wbcontrol -> WBControl(toreg -> 0, regwrite -> 1), rs1 -> 10, rs2 -> 12, branchpc -> 80)
DASM(13)
IF/ID: IFIDBundle(instruction -> 19, pc -> 8, pcplusfour -> 12)
PC: 12
Cycle=3 
writedata: 17
toreg: 3

nganjehloo · 2019-05-15T23:00:16Z

Based on what I've done in verilator, I've noticed everything is evaluated in this order as follows:

debug is printed using wires as inputs
registers are set
combinational logic is evaluated either using the values set in registers or something else

Below is how debug is evaluated. Hopefully this provides a hint to what's going on. Idk if verilator changes things up from firrtil, but based on my testing the verilator output is identical to non verilator output

//----------------FIRST PRINTING HAPPENS USING WIRES--------------------
VL_FWRITEF(0x80000002U,"control: Bundle(opcode -> %3#, validinst -> %1#, branch -> %1#, memread -> %1#, toreg -> %1#, add -> %1#, memwrite -> %1#, regwrite -> %1#, immediate -> %1#, alusrc1 -> %1#, jump -> %1#)\n",
7,(0x7fU & vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction),
1,(IData)(vlTOPp->Top__DOT__cpu__DOT__control_io_validinst),
1,((0x33U != (0x7fU & vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))
& ((0x13U != (0x7fU & vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))
& ((3U != (0x7fU & vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))
& ((0x23U != (0x7fU & vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))

VL_FWRITEF(0x80000002U,"registers: Bundle(readreg1 -> %2#, readreg2 -> %2#, writereg -> %2#, writedata -> %10#, wen -> %1#, readdata1 -> %10#, readdata2 -> %10#)\n",
5,(0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 0xfU)),5,(0x1fU &
(vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 0x14U)),
5,(0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 7U)),32,vlTOPp->Top__DOT__cpu__DOT__registers_io_writedata,
1,(IData)(vlTOPp->Top__DOT__cpu__DOT__registers_io_wen),
32,vlTOPp->Top__DOT__cpu__DOT__registers_io_readdata1,
32,vlTOPp->Top__DOT__cpu__DOT__registers_io_readdata2);
}
//OMITTED THE REST FOR READABILITY

//--------------------THEN REGISTERS ARE SET-------------------------------
// ALWAYS at Top.v:514
if (vlTOPp->Top__DOT__cpu__DOT__registers_io_wen) {
if ((0U == (0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 7U)))) {
vlTOPp->Top__DOT__cpu__DOT__registers__DOT__regs_0
= vlTOPp->Top__DOT__cpu__DOT__registers_io_writedata;
}
}
// ALWAYS at Top.v:514
if (vlTOPp->Top__DOT__cpu__DOT__registers_io_wen) {
if ((1U == (0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 7U)))) {
vlTOPp->Top__DOT__cpu__DOT__registers__DOT__regs_1
= vlTOPp->Top__DOT__cpu__DOT__registers_io_writedata;
}
}
// ALWAYS at Top.v:514
if (vlTOPp->Top__DOT__cpu__DOT__registers_io_wen) {
if ((2U == (0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 7U)))) {
vlTOPp->Top__DOT__cpu__DOT__registers__DOT__regs_2
= vlTOPp->Top__DOT__cpu__DOT__registers_io_writedata;
}
}
// ALWAYS at Top.v:514
if (vlTOPp->Top__DOT__cpu__DOT__registers_io_wen) {
if ((3U == (0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 7U)))) {
vlTOPp->Top__DOT__cpu__DOT__registers__DOT__regs_3
= vlTOPp->Top__DOT__cpu__DOT__registers_io_writedata;
}
//OMITTED THE REST FOR READABILITY

//-----------------THEN WIRES ARE SET USING OTHER WIRES ARE REGISTER OUTPUTS-------------------
vlTOPp->Top__DOT__cpu__DOT__control_io_alusrc1
= ((0x33U == (0x7fU & vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))
? 0U : ((0x13U == (0x7fU & vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))
? 0U : ((3U == (0x7fU & vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))
? 0U : ((0x23U == (0x7fU
& vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))
? 0U : ((0x63U
==
(0x7fU
& vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))
? 0U
: (
(0x37U
==
(0x7fU
& vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))
? 1U
:
((0x17U
==
(0x7fU
& vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction))
? 2U
:
(0x6fU
==
(0x7fU
& vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction)))))))));
vlTOPp->Top__DOT__cpu__DOT__registers_io_readdata1
= ((0x1fU == (0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 0xfU))) ? vlTOPp->Top__DOT__cpu__DOT__registers__DOT__regs_31
: ((0x1eU == (0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 0xfU))) ? vlTOPp->Top__DOT__cpu__DOT__registers__DOT__regs_30
: ((0x1dU == (0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 0xfU))) ? vlTOPp->Top__DOT__cpu__DOT__registers__DOT__regs_29
: ((0x1cU == (0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 0xfU)))
? vlTOPp->Top__DOT__cpu__DOT__registers__DOT__regs_28
: ((0x1bU == (0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 0xfU)))
? vlTOPp->Top__DOT__cpu__DOT__registers__DOT__regs_27
: ((0x1aU == (0x1fU & (vlTOPp->Top__DOT__mem__DOT__memory_imem_instruction
>> 0xfU)))
? vlTOPp->Top__DOT__cpu__DOT__registers__DOT__regs_26
//OMITTED THE REST OF READABILITY

nganjehloo · 2019-05-15T23:16:06Z

Basically inconsistency arises due to printing contents of registers and wires mixed together. we should only ever be printing one or the other.

- Add dump function to the single stepper - Improve the instruction print function Still need to make the pipeline registers print nicely Closes #107 Closes #59 Signed-off-by: Jason Lowe-Power <jason@lowepower.com>

- Add dump function to the single stepper - Improve the instruction print function Still need to make the pipeline registers print nicely Closes jlpteaching#107 Closes jlpteaching#59 Signed-off-by: Jason Lowe-Power <jason@lowepower.com>

powerjg assigned DanG100 May 15, 2019

powerjg added this to the ECS154B WQ '20 milestone Nov 11, 2019

This was referenced Dec 17, 2019

Update simulator to use AnnotationSeq instead of options #106

Open

Remove debug statements in the chisel #108

Closed

powerjg closed this as completed in 8965399 Jan 3, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make sure debug printing is consistent #59

Make sure debug printing is consistent #59

powerjg commented May 15, 2019

powerjg commented May 15, 2019

DanG100 commented May 15, 2019

nganjehloo commented May 15, 2019 •

edited

Loading

nganjehloo commented May 15, 2019 •

edited

Loading

Make sure debug printing is consistent #59

Make sure debug printing is consistent #59

Comments

powerjg commented May 15, 2019

powerjg commented May 15, 2019

DanG100 commented May 15, 2019

nganjehloo commented May 15, 2019 • edited Loading

nganjehloo commented May 15, 2019 • edited Loading

nganjehloo commented May 15, 2019 •

edited

Loading

nganjehloo commented May 15, 2019 •

edited

Loading