6 minutes reading time (1244 words)

The Art of Logging


The one thing that verification engineers spend most of their time on is debug. The most traditional way of debugging any problem is by sifting through logfiles to understand exactly what went wrong in a simulation. A lot of things can cause the testbench to break and the test to fail, and the logfiles can only help if you put intelligent display messages in them.

Using SystemVerilog $display

$display system task is a primitive way of printing messages to the log now that advanced verification methodologies like OVM/UVM has built-in verbosity control mechanisms. All $display statements are always printed into the log. Debug messages will either have to be commented in the source code and enabled when required or some workaround using macros and functions have to be used. Essentially verbosity control has become a very important requirement in complex verification environments.

module tb;
  initial begin
    // Both are printed to the log
    $display("This is supposed to be a debug message");
    $display("This can be an informational message");

But consider the example shown below where we have some mechanism to control verbosity. A better version would be to have the verbosity passed in as a command line option. But the idea is that debug messages can be shown when required and hidden at other times.

typedef enum int {LOW, MEDIUM, HIGH} e_verbosity;
class Logger;  
  e_verbosity m_verbosity = LOW;
  virtual function void info(e_verbosity e_verb, string str);
    if (e_verb >= m_verbosity)
      $display (str);
module tb;
  initial begin
    Logger log = new;
    log.m_verbosity = HIGH;
    log.info(LOW,     "Priority low");
    log.info(MEDIUM,  "Priority medium");
    log.info(HIGH,     "Priority high");

Using UVM verbosity control

Advanced verification environments typically use some form of a methodology like OVM/UVM which has built-in verbosity control mechanisms. However there is more to intelligent display than mere verbosity control and it becomes important to analyze the UVM display message to understand what gets printed by default and what more has to be added to make a good message.

Anatomy of a UVM message

The format of a `uvm_info macro is shown below and it accepts three arguments. The first one represents the ID which is a string that can be used to identify this message. The second is also a string, but it is the main content of the message and the last is the verbosity setting. This macro will be automatically expanded into a uvm_report_info method call during compilation.
`uvm_info(ID, MSG, VERBOSITY)
// The macro will expand into uvm_report_info() method call
`define uvm_info(ID, MSG, VERBOSITY) \
   begin \
     if (uvm_report_enabled(VERBOSITY,UVM_INFO,ID)) \
       uvm_report_info (ID, MSG, VERBOSITY, `uvm_file, `uvm_line, "", 1); \

Let us now look at an example of how this is called and what it prints.

module tb_top;
  bit [3:0] var1;
  time     var2;
  initial begin
    std::randomize(var1, var2) with { var2 == 4000; };
    `uvm_info("TAG", "This is the real message content", UVM_MEDIUM)
    `uvm_info("tb_top", $sformatf("var=0x%0h", var1), UVM_LOW)
    `uvm_warning("tb_top", $sformatf("Time is about to expire, time_set=%0d", var2))
    `uvm_error("CHECKER", $sformatf("[FAIL] Data mismatch exp=0x%0h", var1))
Simulation Log
ncsim> run
UVM_INFO /playground_lib/uvm-1.2/src/base/uvm_root.svh(392) @ 0: reporter [UVM/RELNOTES] 
UVM_INFO testbench.sv(7) @ 1060: reporter [TAG] This is the real message content
UVM_INFO testbench.sv(12) @ 3890: reporter [tb_top] var=0x6
UVM_WARNING testbench.sv(16) @ 3890: reporter [tb_top] Time is about to expire, time_set=4000
UVM_ERROR testbench.sv(13) @ 3036: reporter [CHECKER] [FAIL] Data mismatch exp=0x6
ncsim: *W,RNQUIE: Simulation is complete.

So now its clear that verbosity, file name, line number, time, component instance name that calls the macro, message ID and the message content are displayed.

The Art in Logging

It is always good to remember why we want to log all activity. Simply because it helps to understand the activity as it happened and gives better idea of what is going on, and saves the trouble from opening waveforms. Ofcourse analyzing waveforms is the best way but it simply consumes time to pull in signals from the design hierarchy, and more time for interactive debug. Logs are still good for a fast and effective analysis - provided you logged well !

1. Plan on how you would use the message ID

If there are post-processing scripts that rely on a tag in the UVM messages, then you can make use of the ID field in `uvm_info. Generally you can place get_type_name() in the ID field because it will show child class name in the case of inheritance.

1. Don't just print variable names, write a story

The messages printed into the log file has to convey what is going on in simulation. Printing variable values requires you to look into the source code to track activity. Being a little more descriptive will make reading logs much easier. Variable values can be printed at a higher verbosity just for debug. Take a look at the example below to see how being more descriptive in the message will help aid debug.

`uvm_info(get_type_name(), $sformatf("Deassert reset _reset=%0b", _reset), UVM_LOW)
// Print regname and address along with the value -> this helps in waveform debug as well
`uvm_info(get_type_name(), $sformatf("Register:%s with addr=0x%0x should be cleared to default=0x%0h" reg.get_name(), _reg.get_address(), _reg.get_reset()), UVM_MEDIUM)
`uvm_info("program_load", $sformatf("Program%0d at 0x%0h is now started by thread%0d", prgm.idx, prgm.start_addr, thrd), UVM_LOW)

The example shown below prints only variable names and it becomes difficult to know what the values represent and what should follow.

`uvm_info(get_type_name(), $sformatf("_reset=%0b", _reset), UVM_LOW)
`uvm_info(get_type_name(), $sformatf("regname=%s default=0x%0h" reg.get_name(), reg.get_reset()), UVM_MEDIUM)
`uvm_info("program_load", $sformatf("prgm.idx=%0d start=0x%0h thrd=%0d", prgm.idx, prgm.start_addr, thrd), UVM_LOW)

2. Don't forget to print loop iterations

It is quite easy to be lost in a bunch of nested loops and the best way to know the point of execution is to print out the indices in each message.

for (int i = 0; i < l_queue.size(); i++) begin
  for (int j = 0; j < l_queue[i].item.size(); j++) begin
    // Some other statements
    `uvm_info("iterate", $sformatf("Idx[i=%0d,j=%0d] Item=%s has value=0x%0h"), i, j, l_queue[i].item[j].m_name, l_queue[i].item[j].m_value), UVM_HIGH)

3. Assign thread numbers to forked off threads

Another place where things become unclear is when multiple threads are forked off and each print different statements to the log which can become pretty complicated to debug. It would be useful to have a consistent thread number for each message statement inside each thread.

The advantage of maintaining a consistent display for threads is that it shows up in a neat way in logs.

    `uvm_info(get_type_name(), $sformatf("[Thread0] Start cfg of regblock"), UVM_LOW)
    // Few other statements
    `uvm_info(get_type_name(), $sformatf("[Thread0] Set calc engine to active"), UVM_LOW)
    `uvm_info(get_type_name(), $sformatf("[Thread1] Wait for event done"), UVM_LOW)
    // Some other code
    `uvm_info(get_type_name(), $sformatf("[Thread1] Event done, check registers"), UVM_LOW)
virtual task wait_for_evt_done(string tag);
  while(!l_tmp) begin
    `uvm_info(get_type_name(), $sformatf("%s Waiting for item to be active", tag), UVM_LOW)
    // ...
    `uvm_info(get_type_name(), $sformatf("%s Item active, start engine", tag), UVM_LOW)

4. Print item values that can be correlated with waveform

Values printed in the log should allow you to correlate it with the waveform. Say you are writing some values into multiple registers. In addition to register names, it would be useful to print register addresses and any offsets if required along with data written.

By doing so, you already know what the register addresses are and can look it up in the waveform by pulling in signals from the bus or vice-versa.

  `uvm_info(get_type_name(), $sformatf("Start engine write to reg:%s at addr=0x%0h(O=0x%0h) with data=0x%0h", _reg.get_name(), reg.get_address(), _reg.get_offset(), _reg.get()), UVM_MEDIUM)
Power of SystemVerilog Constraints
Overriding covergroups

Related Posts


By accepting you will be accessing a service provided by a third-party external to https://www.chipverify.com/