Merge pull request #972 from YoannPruvost/dev_rvfi_trace_log

RVFI - Correcting issue on trace log generation from rvfi

Author: pascalgouedo

bhv/cv32e40p_instr_trace.svh

@@ -49,7 +49,10 @@ typedef struct {
 
 class instr_trace_t;
   time         simtime;
+  time         stoptime;
+  bit          external_time;
   int          cycles;
+  int          stopcycles;
   logic [31:0] pc;
   logic [31:0] instr;
   bit          compressed;
@@ -70,10 +73,15 @@ class instr_trace_t;
     regs_read  = {};
     regs_write = {};
     mem_access = {};
+    external_time = 0;
+    stoptime = 0;
+    stopcycles = 0;
   endfunction
 
   function void init(int unsigned cycles, bit [31:0] pc, bit compressed, bit [31:0] instr);
-    this.simtime        = $time;
+    if(!this.external_time) begin
+      this.simtime        = $time;
+    end
     this.cycles         = cycles;
     this.pc             = pc;
     this.compressed     = compressed;
@@ -322,7 +330,23 @@ class instr_trace_t;
     begin
       string insn_str;  // Accumulate writes into a single string to enable single $fwrite
 
-      insn_str = $sformatf("%t %15d %h %h %-36s", simtime, cycles, pc, instr, str);
+      if(simtime < 100ns) begin
+        insn_str = $sformatf("       %t %15d %h %h %-36s", simtime, cycles, pc, instr, str);
+      end else if (simtime < 1us) begin
+        insn_str = $sformatf("      %t %15d %h %h %-36s", simtime, cycles, pc, instr, str);
+      end else if (simtime < 10us) begin
+        insn_str = $sformatf("     %t %15d %h %h %-36s", simtime, cycles, pc, instr, str);
+      end else if (simtime < 100us) begin
+        insn_str = $sformatf("    %t %15d %h %h %-36s", simtime, cycles, pc, instr, str);
+      end else if (simtime < 1ms) begin
+        insn_str = $sformatf("   %t %15d %h %h %-36s", simtime, cycles, pc, instr, str);
+      end else if (simtime < 10ms) begin
+        insn_str = $sformatf("  %t %15d %h %h %-36s", simtime, cycles, pc, instr, str);
+      end else if (simtime < 100ms) begin
+        insn_str = $sformatf(" %t %15d %h %h %-36s", simtime, cycles, pc, instr, str);
+      end else begin
+        insn_str = $sformatf("%t %15d %h %h %-36s", simtime, cycles, pc, instr, str);
+      end
 
       foreach (regs_write[i]) begin
         if (regs_write[i].addr != 0)
@@ -344,6 +368,12 @@ class instr_trace_t;
         insn_str = $sformatf("%s  PA:%08x", insn_str, mem_acc.addr);
       end
 
+      casex (instr)
+      INSTR_FDIV: insn_str = $sformatf("%s %15d %t", insn_str, stopcycles, stoptime);
+      INSTR_FSQRT:insn_str = $sformatf("%s %15d %t", insn_str, stopcycles, stoptime);
+      default: ;
+      endcase
+
       $fwrite(f, "%s\n", insn_str);
     end
   endfunction

bhv/cv32e40p_rvfi.sv

@@ -332,6 +332,10 @@ module cv32e40p_rvfi
     // the convention of RISC-V Formal Interface Specification.
     output logic       [ 0:0] rvfi_valid,
     output logic       [63:0] rvfi_order,
+    output integer            rvfi_start_cycle,
+    output time               rvfi_start_time,
+    output integer            rvfi_stop_cycle,
+    output time               rvfi_stop_time,
     output logic       [31:0] rvfi_insn,
     output rvfi_trap_t        rvfi_trap,
     output logic       [ 0:0] rvfi_halt,
@@ -351,6 +355,7 @@ module cv32e40p_rvfi
     output logic        rvfi_frd_wvalid [1:0],
     output logic [ 4:0] rvfi_frd_addr   [1:0],
     output logic [31:0] rvfi_frd_wdata  [1:0],
+    output logic        rvfi_2_rd,
     output logic [ 4:0] rvfi_rs1_addr,
     output logic [ 4:0] rvfi_rs2_addr,
     output logic [ 4:0] rvfi_rs3_addr,
@@ -371,8 +376,8 @@ module cv32e40p_rvfi
     output logic [31:0] rvfi_pc_wdata,
 
     output logic [31:0] rvfi_mem_addr,
-    output logic [ 3:0] rvfi_mem_rmask,
-    output logic [ 3:0] rvfi_mem_wmask,
+    output logic [31:0] rvfi_mem_rmask,
+    output logic [31:0] rvfi_mem_wmask,
     output logic [31:0] rvfi_mem_rdata,
     output logic [31:0] rvfi_mem_wdata,
 
@@ -623,6 +628,13 @@ module cv32e40p_rvfi
   bit clk_i_d;
   assign #0.01 clk_i_d = clk_i;
 
+  integer cycles;
+  // cycle counter
+  always_ff @(posedge clk_i_d, negedge rst_ni) begin
+    if (rst_ni == 1'b0) cycles <= 0;
+    else cycles <= cycles + 1;
+  end
+
   logic pc_mux_debug;
   logic pc_mux_dret;
   logic pc_mux_exception;
@@ -753,6 +765,10 @@ insn_trace_t trace_if, trace_id, trace_ex, trace_ex_next, trace_wb;
     end
 
     rvfi_order       = new_rvfi_trace.m_order;
+    rvfi_start_cycle = new_rvfi_trace.m_start_cycle;
+    rvfi_start_time  = new_rvfi_trace.m_start_time;
+    rvfi_stop_cycle = new_rvfi_trace.m_stop_cycle;
+    rvfi_stop_time  = new_rvfi_trace.m_stop_time;
     rvfi_pc_rdata    = new_rvfi_trace.m_pc_rdata;
     rvfi_insn        = new_rvfi_trace.m_insn;
 
@@ -807,6 +823,7 @@ insn_trace_t trace_if, trace_id, trace_ex, trace_ex_next, trace_wb;
     rvfi_frd_addr[1]   = '0;
     rvfi_frd_wdata[1]  = '0;
 
+    rvfi_2_rd = new_rvfi_trace.m_2_rd_insn;
     if (new_rvfi_trace.m_rd_addr[0][5] == 1'b0) begin
       rvfi_rd_addr[0]  = new_rvfi_trace.m_rd_addr[0][4:0];
       rvfi_rd_wdata[0] = new_rvfi_trace.m_rd_wdata[0];
@@ -1368,6 +1385,9 @@ insn_trace_t trace_if, trace_id, trace_ex, trace_ex_next, trace_wb;
           end
         end
         csr_to_apu_resp();
+
+        trace_apu_resp.m_stop_cycle = cycles;
+        trace_apu_resp.m_stop_time = $time;
         send_rvfi(trace_apu_resp);
         ->e_send_rvfi_trace_apu_resp;
       end
@@ -1402,10 +1422,10 @@ insn_trace_t trace_if, trace_id, trace_ex, trace_ex_next, trace_wb;
 
   function logic [31:0] be_to_mask(logic [3:0] be);
     logic [31:0] mask;
-    mask[7:0]   = be[0] ? 8'hFF : 8'h00;
-    mask[15:8]  = be[0] ? 8'hFF : 8'h00;
-    mask[23:16] = be[0] ? 8'hFF : 8'h00;
-    mask[31:24] = be[0] ? 8'hFF : 8'h00;
+    mask[7:0]   = (be[0] == 1'b1) ? 8'hFF : 8'h00;
+    mask[15:8]  = (be[1] == 1'b1) ? 8'hFF : 8'h00;
+    mask[23:16] = (be[2] == 1'b1) ? 8'hFF : 8'h00;
+    mask[31:24] = (be[3] == 1'b1) ? 8'hFF : 8'h00;
 
     be_to_mask  = mask;
     return mask;

bhv/cv32e40p_rvfi_trace.sv

@@ -36,16 +36,21 @@ module cv32e40p_rvfi_trace
 
     input logic [31:0] imm_s3_type,
 
-    input logic        rvfi_valid,
-    input logic [31:0] rvfi_insn,
-    input logic [31:0] rvfi_pc_rdata,
+    input logic          rvfi_valid,
+    input logic   [31:0] rvfi_insn,
+    input integer        rvfi_start_cycle,
+    input time           rvfi_start_time,
+    input integer        rvfi_stop_cycle,
+    input time           rvfi_stop_time,
+    input logic   [31:0] rvfi_pc_rdata,
 
     input logic [ 4:0] rvfi_rd_addr [1:0],
     input logic [31:0] rvfi_rd_wdata[1:0],
 
     input logic        rvfi_frd_wvalid[1:0],
     input logic [ 4:0] rvfi_frd_addr  [1:0],
     input logic [31:0] rvfi_frd_wdata [1:0],
+    input logic        rvfi_2_rd,
 
     input logic [ 4:0] rvfi_rs1_addr,
     input logic [ 4:0] rvfi_rs2_addr,
@@ -65,8 +70,8 @@ module cv32e40p_rvfi_trace
     input logic [31:0] rvfi_frs3_rdata,
 
     input logic [31:0] rvfi_mem_addr,
-    input logic [ 3:0] rvfi_mem_rmask,
-    input logic [ 3:0] rvfi_mem_wmask,
+    input logic [31:0] rvfi_mem_rmask,
+    input logic [31:0] rvfi_mem_wmask,
     input logic [31:0] rvfi_mem_rdata,
     input logic [31:0] rvfi_mem_wdata
 );
@@ -78,7 +83,7 @@ module cv32e40p_rvfi_trace
 
   integer f;  //file pointer
   string fn;
-  integer cycles;
+  // integer cycles;
   string info_tag;
 
   logic is_compressed;
@@ -129,7 +134,13 @@ module cv32e40p_rvfi_trace
       rs3_value = rvfi_rs3_rdata;
     end
 
-    if (rvfi_frd_wvalid[0]) begin
+    if (rvfi_2_rd) begin
+      if (rvfi_frd_wvalid[1]) begin
+        rd = {1'b1, rvfi_frd_addr[1]};
+      end else begin
+        rd = {1'b0, rvfi_rd_addr[1]};
+      end
+    end else if (rvfi_frd_wvalid[0]) begin
       rd = {1'b1, rvfi_frd_addr[0]};
     end else begin
       rd = {1'b0, rvfi_rd_addr[0]};
@@ -138,57 +149,68 @@ module cv32e40p_rvfi_trace
 
   assign rs4 = rs3;
 
-  assign imm_i_type = {{20{rvfi_insn[31]}}, rvfi_insn[31:20]};
-  assign imm_iz_type = {20'b0, rvfi_insn[31:20]};
-  assign imm_s_type = {{20{rvfi_insn[31]}}, rvfi_insn[31:25], rvfi_insn[11:7]};
+  cv32e40p_compressed_decoder #(
+      .FPU(FPU)
+  ) rvfi_trace_decompress_i (
+      .instr_i(rvfi_insn),
+      .instr_o(decomp_insn),
+      .is_compressed_o(is_compressed)
+  );
+
+  assign imm_i_type = {{20{decomp_insn[31]}}, decomp_insn[31:20]};
+  assign imm_iz_type = {20'b0, decomp_insn[31:20]};
+  assign imm_s_type = {{20{decomp_insn[31]}}, decomp_insn[31:25], decomp_insn[11:7]};
   assign imm_sb_type = {
-    {19{rvfi_insn[31]}}, rvfi_insn[31], rvfi_insn[7], rvfi_insn[30:25], rvfi_insn[11:8], 1'b0
+    {19{decomp_insn[31]}},
+    decomp_insn[31],
+    decomp_insn[7],
+    decomp_insn[30:25],
+    decomp_insn[11:8],
+    1'b0
   };
-  assign imm_u_type = {rvfi_insn[31:12], 12'b0};
+  assign imm_u_type = {decomp_insn[31:12], 12'b0};
   assign imm_uj_type = {
-    {12{rvfi_insn[31]}}, rvfi_insn[19:12], rvfi_insn[20], rvfi_insn[30:21], 1'b0
+    {12{decomp_insn[31]}}, decomp_insn[19:12], decomp_insn[20], decomp_insn[30:21], 1'b0
   };
 
-  assign imm_z_type = '0;  //{27'b0, rvfi_insn[REG_S1_MSB:REG_S1_LSB]};
+  assign imm_z_type = '0;  //{27'b0, decomp_insn[REG_S1_MSB:REG_S1_LSB]};
 
-  assign imm_s2_type = {27'b0, rvfi_insn[24:20]};
+  assign imm_s2_type = {27'b0, decomp_insn[24:20]};
   assign imm_vs_type = '0;
   assign imm_vu_type = '0;
   assign imm_shuffle_type = '0;
   assign imm_clip_type = '0;
 
-  cv32e40p_compressed_decoder #(
-      .FPU(FPU)
-  ) rvfi_trace_decompress_i (
-      .instr_i(rvfi_insn),
-      .instr_o(decomp_insn),
-      .is_compressed_o(is_compressed)
-  );
-
   `include "cv32e40p_instr_trace.svh"
 instr_trace_t trace_retire;
 
   function instr_trace_t trace_new_instr();
     instr_trace_t trace;
     trace = new();
-    trace.init(.cycles(cycles), .pc(rvfi_pc_rdata), .compressed(is_compressed),
+    trace.external_time = 1;
+    trace.simtime = rvfi_start_time - 1ns;
+    trace.stoptime = rvfi_stop_time;
+    trace.stopcycles = rvfi_stop_cycle;
+    trace.init(.cycles(rvfi_start_cycle), .pc(rvfi_pc_rdata), .compressed(is_compressed),
                .instr(decomp_insn));
     return trace;
   endfunction : trace_new_instr
 
   function void apply_reg_write();
     foreach (trace_retire.regs_write[i]) begin
-      if (rvfi_frd_wvalid[0] && (trace_retire.regs_write[i].addr == {1'b1, rvfi_frd_addr[0]})) begin
-        trace_retire.regs_write[i].value = rvfi_frd_wdata[0];
-      end else if (trace_retire.regs_write[i].addr == rvfi_rd_addr[0]) begin
-        trace_retire.regs_write[i].value = rvfi_rd_wdata[0];
-      end
       if (rvfi_frd_wvalid[1] && (trace_retire.regs_write[i].addr == {1'b1, rvfi_frd_addr[1]})) begin
         trace_retire.regs_write[i].value = rvfi_frd_wdata[1];
       end else if (trace_retire.regs_write[i].addr == rvfi_rd_addr[1]) begin
         trace_retire.regs_write[i].value = rvfi_rd_wdata[1];
       end
     end
+    foreach (trace_retire.regs_write[i]) begin
+      if (rvfi_frd_wvalid[0] && (trace_retire.regs_write[i].addr == {1'b1, rvfi_frd_addr[0]})) begin
+        trace_retire.regs_write[i].value = rvfi_frd_wdata[0];
+      end else if (trace_retire.regs_write[i].addr == rvfi_rd_addr[0]) begin
+        trace_retire.regs_write[i].value = rvfi_rd_wdata[0];
+      end
+    end
   endfunction : apply_reg_write
 
   function void apply_mem_access();
@@ -206,18 +228,19 @@ instr_trace_t trace_retire;
     end
   endfunction : apply_mem_access
 
-  // cycle counter
-  always_ff @(posedge clk_i, negedge rst_ni) begin
-    if (rst_ni == 1'b0) cycles <= 0;
-    else cycles <= cycles + 1;
-  end
+  string        insn_disas;
+  logic  [31:0] insn_pc;
+  logic  [31:0] insn_val;
 
   always @(posedge clk_i) begin
     if (rvfi_valid) begin
       trace_retire = trace_new_instr();
       apply_reg_write();
       apply_mem_access();
       trace_retire.printInstrTrace();
+      insn_disas = trace_retire.str;
+      insn_pc    = trace_retire.pc;
+      insn_val   = trace_retire.instr;
     end
   end
 
@@ -227,7 +250,8 @@ instr_trace_t trace_retire;
     $sformat(info_tag, "CORE_TRACER %2d", hart_id_i);
     $display("[%s] Output filename is: %s", info_tag, fn);
     f = $fopen(fn, "w");
-    $fwrite(f, "Time\tCycle\tPC\tInstr\tDecoded instruction\tRegister and memory contents\n");
+    $fwrite(f,
+            "            Time           Cycle PC       Instr    Decoded instruction Register and memory contents                                 Stop cycle  Stop time\n");
   end
 
 

bhv/cv32e40p_tb_wrapper.sv

@@ -459,12 +459,17 @@ module cv32e40p_tb_wrapper
 
       .rvfi_valid(rvfi_valid),
       .rvfi_insn(rvfi_insn),
+      .rvfi_start_cycle(rvfi_start_cycle),
+      .rvfi_start_time(rvfi_start_time),
+      .rvfi_stop_cycle(rvfi_stop_cycle),
+      .rvfi_stop_time(rvfi_stop_time),
       .rvfi_pc_rdata(rvfi_pc_rdata),
       .rvfi_rd_addr(rvfi_rd_addr),
       .rvfi_rd_wdata(rvfi_rd_wdata),
       .rvfi_frd_wvalid(rvfi_frd_wvalid),
       .rvfi_frd_addr(rvfi_frd_addr),
       .rvfi_frd_wdata(rvfi_frd_wdata),
+      .rvfi_2_rd(rvfi_2_rd),
       .rvfi_rs1_addr(rvfi_rs1_addr),
       .rvfi_rs2_addr(rvfi_rs2_addr),
       .rvfi_rs3_addr(rvfi_rs3_addr),

bhv/cv32e40p_tracer.sv

@@ -185,7 +185,8 @@ module cv32e40p_tracer
     $sformat(info_tag, "CORE_TRACER %2d", hart_id_i);
     $display("[%s] Output filename is: %s", info_tag, fn);
     f = $fopen(fn, "w");
-    $fwrite(f, "Time\tCycle\tPC\tInstr\tDecoded instruction\tRegister and memory contents\n");
+    $fwrite(f,
+            "            Time           Cycle PC       Instr    Decoded instruction Register and memory contents\n");
   end
 
   //initial begin