Logging in pyuvm

This is part of the Python for Verification series of blog posts.

The IEEE UVM specification (1800.2-2020) devotes Section 6 to “Reporting classes” because SystemVerilog does not provide a robust logging system. Python does. The logging module provides standard logging functionality across the Python ecosystem, including cocotb.

Therefore, pyuvm does not implement the UVM reporting classes. Instead, it incorporates the logging module into the UVM hierarchy, links pyuvm logging to cocotb logging, and hides elements of the logging module that frustrate new users.

This blog post provides a brief overview of logging and compares it to UVM reporting. Then it discusses logging in pyuvm.

Logging levels

SystemVerilog UVM combines several concepts to control logging. Severity is the most basic, ranging from UVM_INFO to UVM_FATAL and supported by macro calls that apply the severity to a log message.

Verbosity applies only to UVM_INFO messages and controls whether a given info message gets logged. When users invoke the uvm_info() macro, they supply a verbosity that ranges from UVM_NONE through UVM_LOW up to UVM_FULL.

Users can control information messages by setting a verbosity level in a component. The set_verbosity_level() method creates a verbosity ceiling. The UVM reporting system prints a component‘s uvm_info() messages only if their verbosity is below the ceiling.

This ceiling system means information messages with verbosity UVM_LOW get printed before those with UVM_FULL. The uvm_warning, uvm_error, and uvm_fatal messages ignore verbosity.

The Python logging module combines and simplifies these ideas into logging levels. There are five levels by default:

Logging Level	Numeric Value
CRITICAL	50
ERROR	40
WARNING	30
INFO	20
DEBUG	10
NOTSET	0

You log messages using functions such as self.logger.info() or self.logger.critical(). Then you set the logging level on a component. The messages created in that component get printed if their level is greater than or equal to the component logging level.

pyuvm provides methods that set the logging level in components or component hierarchies.

Logging in pyuvm

pyuvm follows the IEEE 1800.2 specification in that it defines a class named uvm_report_object and extends that class to create uvm_component. This means that all uvm_components are report objects, which is why you must call super().__init__() if you override the __init__() method in a uvm_component.

UVM components support logging with the following steps.

• Every component creates a logger stored in self.logger. These loggers are part of the cocotb logging system.
• The component sets the logger’s level to the default logging level. By default the default is INFO. You can change the default by using the class method uvm_report_object.set_default_logging_level() before awaiting uvm_root().run_test().
• pyuvm defines PyuvmFormatter() which makes pyuvm log messages look like UVM log messages.
• The component creates a StreamHandler that prints messages to sys.stdout rather than sys.stderr.

Now any component can log messages.

Logging messages in pyuvm

We log messages using the critical, warning, error, info, and debug functions in self.logger. For example, these components print warning, info, and debug messages:

class WarningComp(uvm_component):
    def start_of_simulation_phase(self):
        self.logger.debug("This is WARNING")

class InfoComp(uvm_component):
    def start_of_simulation_phase(self):
        self.logger.info("This is INFO")

class DebugComp(uvm_component):
    def start_of_simulation_phase(self):
        self.logger.debug("This is DEBUG")

We instantiate these components in a test and call the test from a @cocotb.test():

class LogTest(uvm_test):
    def build_phase(self):
        self.info = InfoComp("info", self)
        self.warning = WarningComp("warning", self)
        self.debug = DebugComp("debug", self)

@cocotb.test()
async def default_logging_levels(_):
    """Demonstrate default logging levels"""
    await uvm_root().run_test("LogTest")

And voila!

#      0.00ns INFO     running default_logging_levels (1/5)
#      0.00ns INFO     testbench.py(14)[uvm_test_top.info]: This is INFO
#      0.00ns WARNING  testbench.py(10)[uvm_test_top.warning]: This is WARNING
#   1000.00ns INFO     default_logging_levels passed

Examining the log message

The first question you might ask is, “Where is the DEBUG message?” It is not there because the default log level is INFO (20), and DEBUG (10) is less than 20.

On a terminal we’d see that cocotb has colorized the WARNING message. It’s also added the time stamp to the INFO and WARNING messages.

The pyuvm log messages look much like the UVM log messages with the following fields:

• The timestamp comes from the simulator. 0.00ns in this case because we haven’t started the simulation.
• The level in all caps (INFO, WARNING) matches the function call.
• The file name and line number shows where the message was logged.
• pyuvm logging does not have the message ID from SystemVerilog UVM reporting. Instead, we find the UVM hierarchy between square brackets ([])
• Finally, we see the string passed to the logging function.

Changing the logging level

There are two ways to change the logging level. The first way (as of pyuvm 2.5) is to change the default logging level before awaiting the run_test() coroutine. This way, all components get their logging level set to the new default:

@cocotb.test()
async def debug_default_logging_level(_):
    """Demonstrate debug logging level"""
    uvm_report_object.set_default_logging_level(DEBUG)
    await uvm_root().run_test("LogTest")

The second way to change the logging level is to use the set_logging_level_hier() method in the end_of_elaboration_phase(). This is analogous to the set_verbosity_level_hier() method in the SystemVerilog UVM. It changes the logging level from this point in the hierarchy down. There is also a set_logging_level() method that only changes the calling component’s logging level.

We extend LogTest and change the logging level:

class DebugTest(LogTest):
    def end_of_elaboration_phase(self):
        self.set_logging_level_hier(DEBUG)

Both approaches deliver the same result:

1000.00ns INFO     running debug_default_logging_level (2/5)
#   1000.00ns INFO     testbench.py(14)[uvm_test_top.info]: This is INFO
#   1000.00ns WARNING  testbench.py(10)[uvm_test_top.warning]: This is WARNING
#   1000.00ns DEBUG    testbench.py(18)[uvm_test_top.debug]: This is DEBUG
#   2000.00ns INFO     debug_default_logging_level passed
#   2000.00ns INFO     running debug_logging_level (3/5)
#   2000.00ns INFO     testbench.py(14)[uvm_test_top.info]: This is INFO
#   2000.00ns WARNING  testbench.py(10)[uvm_test_top.warning]: This is WARNING
#   2000.00ns DEBUG    testbench.py(18)[uvm_test_top.debug]: This is DEBUG
#   3000.00ns INFO     debug_logging_level passed

Controlling output

The logging module controls output using handlers that extend logging.Handler. There are several predefined handlers in the logging.handlers module. We will discuss three of them.

Every uvm_components has a data member named self.logger, which contains a StreamingHandler that writes to stdout. You can remove this default handler using self.remove_streaming_handler(), at which point your logger will have no handler, so you’ll replace it with another handler.

Writing to a file

If you want to log your information to a file instead of writing to the screen, you add a FileHandler and remove the streaming handlers:

class FileTest(LogTest):
    def end_of_elaboration_phase(self):
        file_handler = logging.FileHandler("log.txt", mode="w")
        self.add_logging_handler_hier(file_handler)
        self.remove_streaming_handler_hier()

The result is that the pyuvm log messages go into log.txt:

#  cat log.txt
  3000.00ns INFO     testbench.py(14)[uvm_test_top]: This is INFO
  3000.00ns WARNING  testbench.py(10)[uvm_test_top]: This is WARNING
  3000.00ns DEBUG    testbench.py(18)[uvm_test_top]: This is DEBUG

The add_logging_handler() and add_logging_handler_hier() methods work for any of the handlers that extend logging.Handler.

Disabling Logging

To completely disable logging use self.disable_logging() or self.disable_logging_hier()which removes the stream handler and replaces it with a NullHandler.

class NoLog(LogTest):
    def end_of_elaboration_phase(self):
        self.disable_logging_hier()

Which gives the result:

#   4000.00ns INFO     running disable_logging (5/5)
#   5000.00ns INFO     disable_logging passed

Summary

This blog post showed how pyuvm incorporated the logging module into a UVM testbench. We learned the difference between SystemVerilog UVM’s severity and verbosity levels and how they relate to the levels in the logging module.

We saw how pyuvm mimics the message structure of SystemVerilog UVM and how it replaced the message-id with the UVM component path between the square brackets.

Finally, we saw how to direct pyuvm logging output to different locations using logging.Handler objects and how to disable logging.