Message, message on the wall!
Posted by Janick Bergeron on 19th June 2008
Why does the VMM message interface (the vmm_log class) have a start_msg() and a text() method that must be used in this convoluted way:
if (log.start_msg(vmm_log::DEBUG_TYP, vmm_log::TRACE_SEV)) begin
log.text("This is a trace message");
log.end_msg();
end
Why not the much simpler one-liner:
log.message(vmm_log::DEBUG_TYP, vmm_log::TRACE_SEV,
"This is a trace message");
which would then eliminate the need for the macro:
`vmm_trace(log, "This is a trace message");
Given the examples above, there is absolutely no reason. However, this example illustrates why:
`vmm_trace(log, $psprintf("Read 'h%h from 'h%h with status %s",
data, addr, status.name()));
which expands to:
if (log.start_msg(vmm_log::DEBUG_TYP, vmm_log::TRACE_SEV)) begin
log.text($psprintf("Read 'h%h from 'h%h with status %s",
data, addr, status.name()));
log.end_msg();
end
The $psprintf() (and all other formatting system tasks $sformat(), $format(), $write(), $display(), etc…) may be simple to use but they are very run-time expensive. And if you are not going to display a message, why incur the cost of composing its image?
When using a single procedure call, the value of all of its arguments must be determined before it is called. Thus, using this approach:
log.trace($psprintf("Read 'h%h from 'h%h with status %s",
data, addr, status.name());
incurs the cost of creating the message image every single time. And most of the time, this debug message will simply be filtered out (think about the thousands and thousands of regression runs where debug is not enabled!).
On the other hand, checking first if messages of a certain type or severity are going to be filtered out or not and only then composing the image of the message improves your run-time performance.
By how much? Of course, it depends on the number of messages that will eventually get filtered out. But just to give you an idea, I ran this experiment using VCS:
program p;
initial
begin
int i;
string msg;
i = $urandom() % 2; // See footnote1
if (i == 1) i--;
repeat (100000) begin
`ifdef GUARD
if (i)
`endif
msg = $psprintf("%s, line %0d: Message #%0d at %t",
`__FILE__, `__LINE__, 0, $time());
end
end
endprogram
With `GUARD defined, which causes the $psprintf() call to be skipped, I get run-times of approximately 0.025 seconds. With `GUARD undefined, which causes the $psprintf() call to be executed, I get run-times of approximately 0.230 second or 10x slower simulation performance.
Personally, I think the performance gain is worth the little extra bit of code to write. Remember to always optimize the right thing: you’ll write that code once but you’ll run it thousands and thousands of times. So saving a few lines of codes is not always the right decision.
1 I use a convoluted way to set i to 0 to prevent an optimizing compiler from optimizing the entire if statement away.
Posted in Debug, Messaging, Optimization/Performance | 2 Comments »