SystemVerilog Tip: How to Do Logging in UVM

SystemVerilog Tip: How to Do Logging in UVM

Posted by

UVM comes with a great messaging system which can be easily controlled with simulator commands. Some of these commands are making use of an ID which can be assign to a message. Unfortunately, UVM does not allow us to assign multiple IDs to the same message.

In this post I will present why assigning multiple IDs to the same message can make a big difference in debugging and, of course, how this can be achieve.

However, if you want to jump straight to the solution click here.

What Is `uvm_info?

Printing out messages to figure out what is happening in a test is, without a doubt, the most commonly used debugging tool. For managing the messages, UVM offers the `uvm_info macro with the following syntax:

`uvm_info(ID, MSG, VERBOSITY)

The ID parameter can be used in various ways. For example, one use-case is to assign an unique ID to a specific functionality. In this case, a typical code would look like this:

task write_registers();
   ...
   reg_block.crc.update(.status(status));

   `uvm_info("REG_ACCESS", $sformatf("Wrote CRC.POLY: 'h%0x", value), UVM_MEDIUM)
   ...
endtask

UVM offers two commands for controlling the messages via their IDs:

The Issue With `uvm_info

Let’s say that we need to verify some DUT which encrypts some data using the AES algorithm, packs it into a CAN packet and sends it away. As the CAN packet has an CRC field, our DUT must also be able to compute the CRC.

In order to have a good control over the log file, we can organize the messages with the following IDs:

  • “REG_ACCESS” – for register access messages.
  • “CRC” – for CRC related messages.
  • “AES” – for AES related messages.

Therefore, the messages in our code would look like this:

  virtual task write_registers();
    ...
    `uvm_info("REG_ACCESS", $sformatf("WR CTRL.EN: 'b%0b", en), UVM_LOW)
    ...
    `uvm_info("REG_ACCESS", $sformatf("WR CAN_CTRL.VERS: %0d", can_vers), UVM_LOW)
    ...
    `uvm_info("REG_ACCESS", $sformatf("WR AES_CTRL.KEY: 'h%0x", aes_key), UVM_LOW)
    ...
  endtask
  ...
  virtual task encrypt_data();
    ...
    `uvm_info("AES", $sformatf("AES started with key: 'h%0x", aes_key), UVM_LOW)
    ...
    `uvm_info("AES", $sformatf("Encrypted information is 'h%0x", aes_data), UVM_LOW)
  endtask
  
  virtual task compute_crc();
    ...
    `uvm_info("CRC", $sformatf("Computed CRC is 'h%0x", crc_data), UVM_LOW)
  endtask
  ...

Now, imagine that we get a failing test with a mismatch for the CRC value.

In order to properly debug the failure, we would need the following information from the log:

  • CAN version so that we know the CRC polynomial value
  • encrypted data, which is the input of the CRC logic
  • output of the CRC algorithm

With all messages enable, the log file will contain 50% of information not relevant for out problem. In fact, in a real project, this percentage is usually much higher.

The log file, with all messages enabled

In order to filter out some of the useless information we could try to disable messages with IDs “REG_ACCESS” and “AES”:

+uvm_set_action=*,REG_ACCESS,UVM_INFO,UVM_NO_ACTION
+uvm_set_action=*,AES,       UVM_INFO,UVM_NO_ACTION

However, this will produce a log file with incomplete information:

The log file with only “CRC” ID enabled

What we need is a way to assign multiple IDs to one message as one message is relevant for more than one feature.

Solution

One solution is to create a macro, similar in form with `uvm_info, but which accepts a list of IDs. If the list contains at least one ID for which the printing is enabled, then that ID is used and the rest are ignored. Its syntax would look like this:

`uvm_infos(IDS, MSG, VERBOSITIES)

Next, we must replace the `uvm_info macro with the new one, and assign the proper IDs to all the messages:

  virtual task write_registers();
    ...
    `uvm_infos('{"REG_ACCESS"}, $sformatf("WR CTRL.EN: 'b%0b", en), '{UVM_LOW})
    ...
    `uvm_infos('{"REG_ACCESS", "CRC"}, $sformatf("WR CAN_CTRL.VERS: %0d", can_vers), '{UVM_LOW, UVM_MEDIUM})
    ...
    `uvm_infos('{"REG_ACCESS", "AES"}, $sformatf("WR AES_CTRL.KEY: 'h%0x", aes_key), '{UVM_LOW})
  endtask
  
  virtual task encrypt_data();
    ...
    `uvm_infos('{"AES"}, $sformatf("AES started with key: 'h%0x", aes_key), '{UVM_LOW})
    ...
    `uvm_infos('{"AES", "CRC"}, $sformatf("AES encrypted data: 'h%0x", aes_data), '{UVM_LOW})
  endtask
  
  virtual task compute_crc();
    ...
    `uvm_infos('{"CRC"}, $sformatf("Computed CRC is 'h%0x", crc_data), '{UVM_LOW})
  endtask
  

 

In this case, showing only the messages with ID equal to “CRC” yields this log file:

The log file, in which only the “CRC” ID is enabled

What is Behind `uvm_infos?

Bellow you can see the macro definition:

`define uvm_infos(IDS, MSG, VERBOSITIES) \
  begin \
    string ids[$] = IDS; \
    uvm_verbosity verbosities[$] = VERBOSITIES; \
    if(verbosities.size() == 0) begin \
      `uvm_fatal("ALGORITHM_ISSUE", "Must provide at least one verbosity to macro uvm_infos") \
    end\
    foreach (ids[i]) begin \
      bit is_uvm_no_action = 0; \
      uvm_report_object ro; \
      uvm_verbosity verbosity = (i >= verbosities.size()) ? verbosities[$] : verbosities[i]; \
      \
      if($cast(ro, this) == 0) begin \
        uvm_root top; \
        uvm_coreservice_t cs; \
        cs = uvm_coreservice_t::get(); \
        ro = cs.get_root(); \
      end \
      \
      is_uvm_no_action = ro.get_report_action(UVM_INFO, ids[i]) == UVM_NO_ACTION; \
      \
      if((uvm_report_enabled(verbosity,UVM_INFO,ids[i]) != 0) && !is_uvm_no_action) begin \
        uvm_report_info(ids[i], MSG, verbosity, `uvm_file, `uvm_line); \
        break;\
      end \
    end \
  end  

The macro takes into consideration that the original `uvm_info relies on the fact that there are two definitions of a function called uvm_report_info:

  1. uvm_report_info() from uvm_report_object class – this is a parent of uvm_component. This will handle all the messages from components (e.g. printing the full path of that component).
  2. uvm_report_info() declared as a global function – to handle messages called from any other place.

One drawback of this macro is the fact that it can only be called from a SystemVerilog class as it uses the this reference. But, as the vast majority of our debug messages are called from SystemVerilog classes this should not be a problem at all.

You can play around with a small example for this on EDA Playground.

Hope you found this useful 🙂

Cristian Slav

3 Comments

  • nimrodweinberg@gmail.com' nimi says:

    “In order to filter out some of the useless information we could try to disable messages with IDs “REG_ACCESS” and “AES”:”

    What tool do you use to filter the log?

    • I am only using the +args:
      +uvm_set_action=*,REG_ACCESS,UVM_INFO,UVM_NO_ACTION
      +uvm_set_action=*,AES, UVM_INFO,UVM_NO_ACTION

      • bcassell@gmail.com' Brian C says:

        For such filtering I typically create a uvm_report_catcher that prints the IDs I care about to a separate logfile l. Adding file descriptors & IDs to member queues via methods keeps it reusable and configurable.

Leave a Reply

Your email address will not be published.