UVM Log Filtering and Normalization

Part IV · Module 10 · Chapter 10.2 · UVM Log Filtering and Normalization

1. The Log

cat -n logs/sim.log

     1	UVM_INFO /proj/tb/base_test.sv(88) @ 0: uvm_test_top [TEST] starting
     2	UVM_INFO /proj/tb/driver.sv(51) @ 120: uvm_test_top.env.agt.drv [DRV] reset done
     3	UVM_ERROR /proj/tb/scoreboard.sv(142) @ 980: uvm_test_top.env.sb [CMP] data mismatch exp=8'hA5 act=8'h5A
     4	UVM_WARNING /proj/tb/monitor.sv(77) @ 1200: uvm_test_top.env.agt.mon [MON] late sample
     5	UVM_ERROR /proj/tb/scoreboard.sv(142) @ 1510: uvm_test_top.env.sb [CMP] timeout waiting for ready
     6	UVM_FATAL /proj/tb/base_test.sv(203) @ 2000: uvm_test_top [TEST] too many errors

Every line has the same six parts:

   UVM_ERROR  /proj/tb/scoreboard.sv(142)  @ 980:  uvm_test_top.env.sb  [CMP]  data mismatch …
   └───┬───┘  └──────────┬──────────────┘  └─┬──┘  └────────┬────────┘  └─┬─┘  └──────┬──────┘
   severity      file and line               time        hierarchy        ID      message

Four of those six change between runs for reasons that have nothing to do with whether the test passed: the file line number moves when somebody edits the testbench, the time shifts with any timing change, and the hierarchy and ID are stable only while the environment is.

2. Two Jobs, Not One

   FILTERING     fewer lines, same detail      "what went wrong?"
   NORMALISING   same lines, fewer differences "what changed since last night?"

A filtered log is for a human reading it now. A normalised log is for diff. Trying to do both at once gives you a file that is neither: too reduced to diff meaningfully, still too noisy to read.

Sections 3 and 4 are filtering. Section 5 is normalising. Section 6 composes them, deliberately, in that order.

3. Filtering — Severity, and the Census First

The registered selection keeps errors and fatals:

sed -n -E '/UVM_(ERROR|FATAL)/p' logs/sim.log

UVM_ERROR /proj/tb/scoreboard.sv(142) @ 980: uvm_test_top.env.sb [CMP] data mismatch exp=8'hA5 act=8'h5A
UVM_ERROR /proj/tb/scoreboard.sv(142) @ 1510: uvm_test_top.env.sb [CMP] timeout waiting for ready
UVM_FATAL /proj/tb/base_test.sv(203) @ 2000: uvm_test_top [TEST] too many errors

Three of six. This needs -E for the alternation — Chapter 4.1's case where extended mode is genuinely the right choice, and note the contrast with Chapter 10.1, where basic mode was right because the text was full of +.

Before reading those three lines, though, run the census. It is one command and it is the step most triages skip:

sed -n -E 's/^(UVM_[A-Z]+) .*/\1/p' logs/sim.log | sort | uniq -c

   2 UVM_ERROR
   1 UVM_FATAL
   2 UVM_INFO
   1 UVM_WARNING

Now you know the shape of the failure before you read a word of it. Two errors and one fatal is a different problem from two hundred errors and one fatal, and the filtered output looks similar in both cases until you scroll.

That pattern replaces the whole line with its first field and prints only lines that matched, so anything not in UVM message format is silently excluded — which is itself informative if the count is lower than the file's line count.

4. Filtering — Strip What You Are Not Reading

The file-and-line prefix and the timestamp are useful when you are debugging the testbench and pure noise when you are triaging the design. The registered command removes both:

sed -E 's/^(UVM_[A-Z]+) [^ ]+\([0-9]+\) @ [0-9]+:/\1:/' logs/sim.log

UVM_INFO: uvm_test_top [TEST] starting
UVM_INFO: uvm_test_top.env.agt.drv [DRV] reset done
UVM_ERROR: uvm_test_top.env.sb [CMP] data mismatch exp=8'hA5 act=8'h5A
UVM_WARNING: uvm_test_top.env.agt.mon [MON] late sample
UVM_ERROR: uvm_test_top.env.sb [CMP] timeout waiting for ready
UVM_FATAL: uvm_test_top [TEST] too many errors

Six lines in, six out — this is a rewrite, not a filter, so no line is lost. Reading the pattern:

   ^(UVM_[A-Z]+)   capture the severity                    -> \1
    [^ ]+          the file path, up to the first space
    \([0-9]+\)     the (line number), parens escaped
    @ [0-9]+:      the timestamp

[^ ]+ is Chapter 4.2's negated class doing the work a greedy .* would botch — it stops at the first space, so a path containing no spaces is consumed exactly. And \( \) are escaped because this is -E, where bare parentheses group; Chapter 4.1's inversion, arriving where it matters.

5. Normalising — and Why You Cannot Copy One

Now the other job. To compare last night's log with tonight's, the things that differ for uninteresting reasons must become identical text.

The registered normaliser masks the simulation time:

sed 's/@ [0-9]* ns/@ <time>/g' logs/sim.log | head -3

UVM_INFO /proj/tb/base_test.sv(88) @ 0: uvm_test_top [TEST] starting
UVM_INFO /proj/tb/driver.sv(51) @ 120: uvm_test_top.env.agt.drv [DRV] reset done
UVM_ERROR /proj/tb/scoreboard.sv(142) @ 980: uvm_test_top.env.sb [CMP] data mismatch exp=8'hA5 act=8'h5A

Nothing changed. Exit status 0.

The pattern is correct for a log that writes @ 980 ns. This log writes @ 980: — no unit, a colon instead. The command is not broken; it is describing a different format.

The working version for this format:

sed 's/@ [0-9]*:/@ <time>:/' logs/sim.log | head -3

UVM_INFO /proj/tb/base_test.sv(88) @ <time>: uvm_test_top [TEST] starting
UVM_INFO /proj/tb/driver.sv(51) @ <time>: uvm_test_top.env.agt.drv [DRV] reset done
UVM_ERROR /proj/tb/scoreboard.sv(142) @ <time>: uvm_test_top.env.sb [CMP] data mismatch exp=8'hA5 act=8'h5A

What else to mask. Anything that differs between runs for a reason you do not care about:

   @ [0-9]*:                  simulation time
   ([0-9]+)                   testbench line numbers
   seed=[0-9]+                the seed
   /runs/[0-9_]*              the run directory
   [0-9]{2}:[0-9]{2}:[0-9]{2} wall-clock timestamps

The judgement is which of those are noise for this comparison. Masking the time is right when comparing functional behaviour and wrong when investigating a timing-dependent failure — at which point the time is the signal.

6. Composing Them, in the Right Order

Filter first, then normalise. The block form from Chapter 5.4 does both in one pass:

sed -n -E '/UVM_(ERROR|FATAL)/{ s/^(UVM_[A-Z]+) [^ ]+\([0-9]+\) @ [0-9]+:/\1:/; p; }' logs/sim.log

UVM_ERROR: uvm_test_top.env.sb [CMP] data mismatch exp=8'hA5 act=8'h5A
UVM_ERROR: uvm_test_top.env.sb [CMP] timeout waiting for ready
UVM_FATAL: uvm_test_top [TEST] too many errors

Three lines, each reduced to severity, hierarchy, ID and message. That is a triage summary: short enough to read, and stable enough that tonight's version can be diffed against last night's.

Reading it: -n suppresses auto-print, the address selects errors and fatals, the braces scope both commands to those lines, the substitution strips the prefix, and p emits the result. Every piece is from Part II.

Order matters for a practical reason: filtering first means the substitution runs on three lines instead of six. On a six-line log that is irrelevant; on a 400 MB regression log it is not.

7. Think It Through

1. What is the difference between filtering and normalising?

Filtering removes lines — fewer lines, same detail, for a human reading now. Normalising rewrites within lines — same lines, fewer differences, for diff. A filtered log is hard to compare across runs; a normalised log is still too long to read.

2. Your time-masking command produces output identical to its input. What is the first thing to check?

Whether the pattern describes your log's format. Section 5 measured @ [0-9]* ns matching nothing on a log that writes @ 980:. Run grep -c with the pattern first: a before-count of zero means the mask is a no-op, and nothing else will tell you.

3. Why does severity selection need -E when Chapter 10.1 insisted on basic mode?

Because the jobs differ. UVM_(ERROR|FATAL) needs alternation, which basic mode spells with a GNU-only \| — Chapter 4.1 measured that failing silently on BSD. Run scripts needed basic mode because they are full of literal +. Choose the dialect per command, not per project.

4. Write the census command and say what it tells you that the filtered log does not.

sed -n -E 's/^(UVM_[A-Z]+) .*/\1/p' log | sort | uniq -c. It gives the count per severity before you read anything, so you know whether you are looking at two errors or two hundred — a distinction the first screen of a filtered log hides. It also reveals lines that are not in UVM format at all, by their absence from the total.

5. When is masking the simulation time the wrong thing to do?

When the time is the signal — a timing-dependent failure, a race, a test that passes or fails depending on when a transaction lands. Normalisation is lossy on purpose; the question is always whether the thing you are erasing is noise for this comparison.

6. Why filter before normalising rather than after?

Correctness is the same either way; cost is not. Filtering first means the rewrite runs on the lines you kept rather than on every line in the file, which matters once logs reach hundreds of megabytes. It also keeps the script readable, since the address states the scope once for every command in the block.

8. Summary

• A log is tool output — flat, generated, uncompiled — so Chapter 9.3's cautions do not apply. This is sed's natural territory.
• Filtering and normalising are different jobs. Fewer lines for a human; fewer differences for diff.
• Run the census first: sed -n -E 's/^(UVM_[A-Z]+) .*/\1/p' | sort | uniq -c gave 2 errors, 1 fatal, 2 info, 1 warning. Shape before detail.
• Severity selection needs -E for the alternation — the opposite dialect choice from Chapter 10.1, for a good reason.
• The prefix strip is a rewrite, not a filter: six lines in, six out, with [^ ]+ stopping at the first space where .* would overrun.
• The registered time mask matched nothing on this log, exit 0 — because this format writes @ 980: and the pattern expects @ 980 ns. The command was right about a different simulator.
• Unlike every other silent no-op in this track, that one is not a bug — it is the normal condition of log processing, and the defence is grep -c before and after.
• Mask only what is noise for this comparison. Time is noise when comparing behaviour and signal when chasing a race.
• Filter first, then normalise, so the rewrite runs on fewer lines.

One log is a triage. A regression is hundreds of them, each with its own run directory and seed, and the question stops being "what went wrong in this run" and becomes "what is different from last night". Chapter 10.3 — Regression Log Processing scales this up, and it runs straight into a problem Chapter 2.4 measured long ago: several files given to one sed are a single stream, and a per-file range does not do what it looks like.