Possible bug: UVM 1.2,IEEE: uvm_transaction.svh, etc.

[kaushalmodi]

Hello all,

Today, I ended up in a situation where the transaction boxes in Cadence Simvision will not at the exact time where they were supposed to be. This resulted in a drift of the boxes represented in the waves.

On looking closer, the box begin time happened only at 1ns resolution, whereas my agent package's resolution and even the default simulation timescale was 1ns/1ps.

So I expected the boxes' begin times to be possible at 1ps resolution (not 1ns).

Here are the prints from the uvm_info debug statements in my agent monitor:

 

 

   UVM_INFO @2832.523ns  ch0_TX_QEC_OUT: after end_tr of micro_tr :DEBUG_TR

   UVM_INFO @2832.523ns  ch0_TX_QEC_OUT: before begin_tr of micro_tr :DEBUG_TR
   UVM_INFO @2832.523ns  ch0_TX_QEC_OUT: after begin_tr of micro_tr :DEBUG_TR
   UVM_INFO @2833.540ns  ch0_TX_QEC_OUT: after wait for slave_cb :DEBUG_TR
   UVM_INFO @2833.540ns  ch0_TX_QEC_OUT: before write of micro_tr :DEBUG_TR
   UVM_INFO @2833.540ns  ch0_TX_QEC_OUT: before end_tr of micro_tr :DEBUG_TR
   UVM_INFO @2833.540ns  ch0_TX_QEC_OUT: after end_tr of micro_tr :DEBUG_TR

   UVM_INFO @2833.540ns  ch0_TX_QEC_OUT: before begin_tr of micro_tr :DEBUG_TR

The attached figure shows how it looks in waves.

When I then printed tr_micro.print() I saw that the begin_time and end_time variables in there had lost the precision in picoseconds!

So I start grepping UVM source code to see how the begin_time was assigned, and I find this:

function integer uvm_transaction::m_begin_tr (time begin_time=0, 
                                              integer parent_handle=0);
   time tmp_time = (begin_time == 0) ? $realtime : begin_time;
   uvm_recorder parent_recorder;

I believe the bug is wherever in UVM the $realtime is assigned to a time type variable.

If the time type is refactored to realtime type, this issue will be fixed.

With the clock period of 1.018ns, I expected each transaction box to be 1.018ns wide. But with this loss of precision in begin_time and end_time, the transaction recording happens incorrectly and shows grossly wrong transaction representation in the waves. This is highlighted with the fact that the clock period (1.018ns) is close to the timescale step of 1ns.

Here is a minimal SystemVerilog example that shows the information loss in time when $realtime value is assigned to a time variable:

`timescale 1ns/1ps

module top;

  //In uvm_transaction.svh (UVM 1.2), we have:
  //
  //
  //    function integer uvm_transaction::m_begin_tr (time begin_time=0,
  //                                                  integer parent_handle=0);
  //       time tmp_time = (begin_time == 0) ? $realtime : begin_time;
  //       // ..
  //
  //This example shows how when $realtime is assign to tmp_time of
  //type time, all the precision is lost. So above is as good as
  //assigning the time from $time instead of $realtime.
  //

  function void print_now();
    realtime nowr;
    time now;
    begin
      nowr = $realtime;
      now = $realtime; // "now" loses the 1ps resolution compared to "nowr"
      $display("time: %t, realtime: %t", now, nowr);
    end
  endfunction : print_now

  initial begin
    $timeformat(-9, 3, " ns", 11); // units, precision, suffix_string, minimum_field_width

    print_now(); // -> time:    0.000 ns, realtime:    0.000 ns

    #1.1;
    print_now(); // -> time:    1.000 ns, realtime:    1.100 ns

    #1.23;
    print_now(); // -> time:    2.000 ns, realtime:    2.330 ns

    #1.456;
    print_now(); // -> time:    4.000 ns, realtime:    3.786 ns

    $finish;
  end
endmodule : top

 

[kaushalmodi]

Here is a minimal example to reproduce this bug:

// Time-stamp: <2019-09-13 08:40:25 kmodi>
// Original Author    : Kaushal Modi
// File Name          : begin_time_end_time.sv
// Description        : Minimal reproducible example to show the issue with
//                      begin_time and end_time of transactions begin of
//                      time type instead of realtime.
// Run command        : For Cadence:
//                        xrun -uvm -uvmhome CDNS-1.2 begin_time_end_time.sv
//                      Command should be similar for other vendors.

// *** Fix is to replace the time type with realtime type everywhere
// *** where $realtime value is assigned to a variable in the entire UVM
// *** code.

`timescale 1ns/1ps

`include "uvm_macros.svh"
import uvm_pkg::*;

module top;

  initial begin
    $timeformat(-12, 0, "ps", 7);  // units, precision, suffix, min field width
    run_test("my_test");
  end

endmodule : top

class my_tr extends uvm_sequence_item;

  static int id;

  `uvm_object_utils_begin(my_tr)
    `uvm_field_int(id, UVM_DEFAULT | UVM_DEC)
  `uvm_object_utils_end

  function new(string name = "my_tr");
    begin
      super.new(name);
      id++;
    end
  endfunction // new

endclass : my_tr

class my_test extends uvm_test;
  `uvm_component_utils(my_test)

  function new(string name = "my_test", uvm_component parent = null);
    super.new(name, parent);
  endfunction : new

  virtual task run_phase(uvm_phase phase);
    begin
      super.run_phase(phase);
      phase.raise_objection(this, $sformatf("%s: At the beginning of run phase", get_type_name()));

      repeat (1) begin
        automatic my_tr tr;
        automatic realtime actual_begin_time, actual_end_time;
        tr = my_tr::type_id::create("tr");
        actual_begin_time = $realtime;
        void'(begin_tr(tr));
        #1ps; // Commenting out this line and uncommenting the next line will mask the bug
        // #1ns; // If the time increments is done in full time steps (`timescale 1ns/1ps), this bug is masked
        actual_end_time = $realtime;
        end_tr(tr);
        tr.print();
        assert (actual_begin_time == tr.get_begin_time()) else
          `uvm_error("BEGIN_TIME_MISMATCH", $sformatf("Actual begin time (%t) != begin_time recorded in tr (%t)",
                                                      actual_begin_time, tr.get_begin_time()));
        assert (actual_end_time == tr.get_end_time())else
          `uvm_error("END_TIME_MISMATCH", $sformatf("Actual end time (%t) != end_time recorded in tr (%t)",
                                                    actual_end_time, tr.get_end_time()));
      end

      phase.drop_objection(this);
    end
  endtask : run_phase

endclass : my_test

 

[kaushalmodi]

Here's the same example that can be directly run on EDA Playground: https://www.edaplayground.com/x/4Ydz