Anatomy of a Tool Log

Part II · Module 29 · Chapter 29.1 · Anatomy of a Tool Log

Module 28 kept the logs deliberately, on the grounds that they are the one artifact a rerun cannot reproduce and the only place the verdict lives. This module reads them. The first thing to establish is that a log is not prose: it has regions, and almost every question has a region it lives in.

1. A Log Is a Document With Named Regions

Every tool log, whatever the vendor, is some arrangement of five things:

A banner — the tool, its version, the date, the command. Two to twenty lines at the top, almost always skipped by a human and almost always the thing you need three weeks later.

An environment echo — the licence server, the library paths, the include directories, sometimes the whole environment. Large, usually ignored, and the only record of the conditions if Chapter 27.9's capture was not in place.

Phase or stage markers — "elaboration", "run phase", "optimisation". These are the index: they tell you which part of the work a message belongs to.

The messages — the body, and by far the bulk. Severity-tagged, timestamped, and overwhelmingly repetitive.

A summary — counts by severity, a verdict, a final timestamp. Small, at the end, and the reason tail is a better first command than head.

The regions are not decoration. They decide where to look, and §2 measures how extreme that is.

2. Where the Answer Actually Is

A real log from a regression run — 4,021 lines:

$ grep -c . axi_burst_test.log
4021
$ head -2 axi_burst_test.log
UVM_INFO @ 0: reporter [RNTST] Running test axi_burst_test...
UVM_INFO tb/tests/tb_regress.sv(8) @ 0: uvm_test_top [BUILD] building env
$ tail -8 axi_burst_test.log
UVM_INFO @ 40000: reporter [TEST_DONE] 'run' phase is ready to proceed
--- UVM Report Summary ---
** Report counts by severity
UVM_INFO :  4002
UVM_WARNING : 8
UVM_ERROR : 2
UVM_FATAL : 0
TEST FAILED

Find the boundary by line number rather than by eye:

$ grep -n 'Report Summary' axi_burst_test.log | head -1
4014:--- UVM Report Summary ---

The summary begins on line 4014 of 4021. Everything a reader wants first — did it pass, how many errors, how long — is in the last eight lines, and the preceding 4,013 are the body.

Now measure what the body is actually made of. UVM-style messages carry an id tag in brackets, which makes that a one-liner:

$ head -4013 axi_burst_test.log | grep -E '^UVM_INFO ' \
>   | sed 's/.*\[\([A-Z_]*\)\].*/\1/' | sort | uniq -c | sort -rn
4000 AXI_MON
   1 TEST_DONE
   1 RNTST
   1 BUILD

Four thousand of the 4,003 informational lines are one message from one monitor. 99.9% of the log is a single $display in a loop. That is not a badly written testbench — it is what a monitor is for — and it is why reading a log from the top is the wrong instinct: you are reading one sentence four thousand times.

3. The Punctuation That Breaks grep

The line that marks the summary begins with three hyphens, and that is enough to stop the obvious command from running:

$ grep "--- UVM Report" axi_burst_test.log
grep: unrecognized option `--- UVM Report'
usage: grep [-abcdDEFGHhIiJLlMmnOopqRSsUVvwXxZz] [-A num] [-B num] [-C[num]]
	[-e pattern] [-f file] …

The pattern starts with -, so grep reads it as an option bundle. Two fixes, both standard:

$ grep -e "--- UVM Report" axi_burst_test.log
--- UVM Report Summary ---
$ grep -- "--- UVM Report" axi_burst_test.log
--- UVM Report Summary ---

-e says explicitly "this is the pattern"; -- says "no more options follow". Either works, and the habit worth forming is to use -e whenever a pattern comes from a variable:

# a pattern you did not write is a pattern that might start with a dash
grep -e "$pat" "$log"

4. A Clean Stage Writes Nothing

The inverse structure is worth stating because it surprises people and because it changes how a wrapper should be written. On a successful compile of the fixture:

$ iverilog -g2012 -o logs/ok.vvp src/pkg.sv src/dut.sv src/tb.sv > logs/compile_ok.log 2>&1
$ echo $?
0
$ grep -c . logs/compile_ok.log
0

Zero lines. Chapter 28.1 measured the same for three stages and drew the retention conclusion; here the point is about reading. On this flow a non-empty compile log is itself the signal, which inverts the usual search:

# not "find the errors in the compile log" but "is there a compile log at all"
[ -s "$rundir/compile.log" ] && echo "compile had something to say -- read it"

And when it does speak, it ends by counting itself:

$ iverilog -g2012 -o /tmp/x.vvp src/dut.sv src/tb.sv
src/dut.sv:10: error: This assignment requires an explicit cast.
1 error(s) during elaboration.

Two lines: the message, and the tool's own total. That total is worth more than a grep -c of your own, and Chapter 29.3 measures the case where the two disagree.

5. Reading a Log in the Right Order

The order follows from §2, and it is four commands rather than one:

#!/bin/bash
# logpeek LOG — the regions of a log, in the order worth reading them.
set -u
log=${1:?usage: logpeek LOG}
[ -r "$log" ] || { echo "logpeek: cannot read $log" >&2; exit 2; }

n=$(grep -c . "$log")
printf '== %s, %s lines ==\n' "$log" "$n"

# 1. the verdict and the counts: the end of the file
printf '\n-- the last 10 lines --\n'
tail -10 "$log"

# 2. the first thing that went wrong, if anything did
printf '\n-- first error-ish line --\n'
first=$(grep -n -m1 -e '\*\* Error' -e '\*\* Fatal' -e 'UVM_ERROR' -e 'UVM_FATAL' \
                -e 'error:' -e '^ERROR' "$log" 2>/dev/null)
printf '%s\n' "${first:-(none)}"

# 3. what the body is made of, so you know whether to read it
printf '\n-- body composition, by message id --\n'
grep -oE '\[[A-Z_][A-Z_0-9]*\]' "$log" 2>/dev/null | sort | uniq -c | sort -rn | head -8
printf '   (no bracketed ids found)\n' 2>/dev/null

# 4. the banner, last, because it is the slowest-changing information
printf '\n-- the first 5 lines --\n'
head -5 "$log"

$ logpeek axi_burst_test.log
== axi_burst_test.log, 4021 lines ==

-- the last 10 lines --
UVM_INFO tb/agents/axi_mon.sv(142) @ 39990: … [AXI_MON] addr=0x0000f9f0 len=15 burst=INCR
UVM_INFO @ 40000: reporter [TEST_DONE] 'run' phase is ready to proceed
--- UVM Report Summary ---
** Report counts by severity
UVM_INFO :  4002
UVM_WARNING : 8
UVM_ERROR : 2
UVM_FATAL : 0
TEST FAILED
tb/tests/tb_regress.sv:33: $finish called at 0 (1s)

-- first error-ish line --
1344:UVM_ERROR tb/env/axi_sb.sv(201) @ 13370: uvm_test_top.env.sb [MISMATCH] expected 0xdeadbeef got 0xd…

-- body composition, by message id --
4000 [AXI_MON]
   8 [SB_LATE]
   2 [MISMATCH]
   1 [TEST_DONE]
   1 [RNTST]
   1 [BUILD]

-- the first 5 lines --
UVM_INFO @ 0: reporter [RNTST] Running test axi_burst_test...
UVM_INFO tb/tests/tb_regress.sv(8) @ 0: uvm_test_top [BUILD] building env
UVM_INFO tb/agents/axi_mon.sv(142) @ 0: … [AXI_MON] addr=0x00000000 len=0 burst=INCR
…

Four lines of that output carry everything. The verdict is TEST FAILED with two errors. The first error is at line 1344 — a third of the way in, not at the end, which is worth noticing because the instinct is to look near the bottom. The body is 4,000 monitor lines plus ten that matter: eight [SB_LATE] warnings and two [MISMATCH] errors. And the composition line pairs them, so the question "were the eight warnings related to the two errors" is now askable.

On a log with no structure at all the script degrades rather than failing:

$ logpeek logs/stall.log
== logs/stall.log, 2 lines ==

-- the last 10 lines --
TB  starting
TB  waiting for ready (no further events will occur)

-- first error-ish line --
(none)

-- body composition, by message id --
   (no bracketed ids found)

-- the first 5 lines --
TB  starting
TB  waiting for ready (no further events will occur)

Two lines, no errors, no ids — and no verdict either, which is the subject of Chapter 29.5.

Three design points.

The verdict comes first and the banner last. That is the opposite of the file's own order, and it is the whole value of the script.

grep -n -m1 with multiple -e patterns, so the search covers several tools' spellings and stops at the first hit. -m1 matters on a large file and matters more in Chapter 29.2, where the first hit is the answer and the rest are consequences.

The body is summarised, never printed. Four thousand lines of [AXI_MON] is a number, not reading material, and seeing 4000 [AXI_MON] next to 2 [SB_MISMATCH] tells you immediately which two lines matter.

6. When the Log Has No Structure At All

Not every tool is this well behaved, and the fallback is worth knowing. Logs with no severity tags, no ids and no summary still have one reliable structural property: the order things happened. Which means two techniques survive:

# where did the output stop? (a hang or a kill, Chapter 29.5)
tail -3 "$log"

# what changed between a passing run and a failing one?
diff <(sed 's/[0-9][0-9]*/N/g' pass/run.log) \
     <(sed 's/[0-9][0-9]*/N/g' fail/run.log) | head -20

The sed is the useful part: replacing every number with N removes timestamps, addresses and cycle counts, so the diff shows structural differences rather than the thousands of numeric ones. It is crude and it routinely reduces a 4,000-line diff to a dozen lines, which is the difference between a comparison you can read and one you cannot.

That technique is also the honest answer to a log you do not understand: you do not need to understand it to notice that the failing run stopped emitting a message the passing run emitted.

Practice

1. Count the lines in your largest simulation log, then find the line number where its summary begins. Express the summary as a percentage of the file.
2. Read the last ten lines first and write down which of your questions it already answered.
3. Group the body by message id and find out what fraction of the log is a single message.
4. Try grep "--- something" on a log and read the error. Then fix it two ways.
5. Write a grep whose pattern comes from a variable and decide where -e belongs.
6. Check whether your successful compile writes anything at all. If it does not, write the one-line check that treats a non-empty log as the signal.
7. Find your tool's own error count line and compare it with your own grep -c.
8. Write logpeek and run it on a passing log and a failing one.
9. Reorder it to print the banner first and decide which version you would rather have at 2am.
10. Take a log with no severity tags and find where its output stops.
11. Diff a passing and a failing log with numbers normalised, and compare the line count of that diff against the raw one.

Check Your Understanding

1. Name the five regions of a typical tool log.
2. In the measured log, which line does the summary begin on, and how many lines is the file?
3. What fraction of the informational lines were a single message, and from what?
4. Why is reading a log from the top the wrong instinct?
5. Why does grep "--- UVM Report" fail, and what are the two fixes?
6. Where should -e go when the pattern comes from a variable, and why?
7. How many lines did a successful compile write, and what does that invert?
8. Why prefer the tool's own error count to your own grep -c?
9. Why does logpeek print the regions in the opposite order to the file?
10. Why is -m1 important in the first-error search?
11. What is the one structural property even an untagged log has, and which two techniques does it support?
12. What does normalising numbers before a diff accomplish?

7. Remember

• A log is a document with regions: banner, environment, phase markers, messages, summary.
• The answer is at the end. In the measured log the summary begins on line 4014 of 4021 — tail beats head.
• 99.9% of the body was one message. Group by message id and read the counts, never the lines.
• A pattern beginning with - breaks grep. Use -e or --, and always -e when the pattern is in a variable.
• A successful stage writes nothing, which inverts the search: a non-empty compile log is the signal.
• Prefer the tool's own count to your own, and know that the two can disagree.
• Read the regions in the opposite order to the file: verdict, first error, body composition, banner.
• Even an untagged log has an order, which supports "where did it stop" and a normalised diff against a passing run.

8. What Is Next

The regions are identified and the first error-ish line is findable. Chapter 29.2 separates the originating error from its consequences — and finds a compile that produced 255 error messages and exited zero.