Built-in Message Logging – Part 2 of 2

[Team Specman welcomes back guest blogger, Michael Avery from our Services Group in the UK]

Building on the Part 1 introduction to Specman’s messaging built-in infrastructure, allow me to share some tips on how to programmatically control and scale message display to help shorten your debug time.

First and foremost: please, please, please avoid manually commenting out/in debug messages.  While it’s very tempting to use this classic, quick & dirty technique, it’s always a waste of time in the end because Specman makes it very easy to control message viewing in a scalable, automated manner.  Specifically, we can control which messages we see or don't see by configuring the loggers as follows:

1. Via constraints on the logger.
2. Via Specman commands or message logger GUI
3. By calling methods of the logger instances.    

Additionally, message_loggers also have hook methods which allow us to customise how messages are handled.  Consider the following example of a situation that may occur with big environments.

There you are with a large environment and find that you are seeing lots of low level messages that are not relevant to the area you are presently trying to debug.  All these messages are simply creating a large amount of noise such that it’s hard to see the important messages relating to your current debug requirements.

Remember that a message request can potentially be displayed by any one of several loggers on the way from the unit that made the message request up through the hierarchy to sys.logger. If we set the message format to "long" then we get more detail about the message which is automatically added by the messaging infrastructure.  An example Specman command to do this:

      Specman> set message -format=long

So lets say that a message request is made like this:

       mytcm() @myclk is {  message(T1, LOW, "This is the text of my message"); };

This message will be passed up towards sys.logger. It may or may not get displayed.  It will only be displayed if a message_logger has been configured to display messages with the “tag” T1 and a verbosity setting of LOW.

If such a message_logger exists then we will see in the Specman window the message like this:

   [55] ENV UNITC (LOW) at line 113 in @msg_log_top in UNITC unit_c_u-@3:
   This is the text of my message

So the information we get with message format=long can be described like this:

     [55]              -  Time the message request was made
     ENV UNITC  -  Return value of short_name_path() method of unit which made the message request
     (LOW)          - Verbosity of the message
     line 113 in...  - Line of source code where message request was made
     UNITC unit_c_u-@3  -  Unit instance which contained the message() request

We can see where the message request is made but cannot easily see which message logger actually displayed the message.

If we are seeing lots of low level messages we don't want then it is probably because a message_logger is incorrectly configured, but which one?  There is no easy way to find this out but we can extend a predefined method of the pre defined message_logger unit.  The predefined method called format_message() is called automatically every time a message is to be displayed.  We can extend this method to add more information to the message:

   extend message_logger {
     format_message():list of string is also {
        result.add( append( "Logger instance  ", me, " displayed this message"));
     };
   };

Now our message request which looks like this:

message(T1, LOW, "This is the text of my message");

..will be displayed like this:

    [55] ENV UNITC (LOW) at line 113 in @msg_log_top in UNITC unit_c_u-@3:
    This is the text of my message
    Logger instance message_logger-@12 displayed this message

Now we have identified the offending logger and can configure it so that we no longer see the messages which are currently irrelevant to us.

Even better: a very useful command option added in Specman 9.2 allows us to recursively turn off messages from some stated point in the hierarchy.

What it does:

• Recursively traverse a unit tree starting from the specified root (which is "sys" by default)
• Replace, add, or remove the messages specified by the filter on all loggers that are allocated the specified tags

Specman> set message -rec [-root=unit-exp] [-replace|-add|-remove] [-tags=tag-list|all] [filter]

For a more in-depth view of message loggers attend the Advanced Specman Training Course - http://www.cadence.com/Training

Michael Avery
Cadence Services, UK