Python Part II · Module 20 · Simulation and UVM Log Parsing
Turning One Log Into a Result Record
Fifteen chapters have each added one fact the parser can extract. This one puts them together and defines the thing the rest of the curriculum consumes: a single dictionary per log, with every field present on every run, collected in one pass over the file, holding a few lines of state whatever the log's size. The interesting decisions at this point are not about parsing any more — they are about what belongs in the record, what belongs to whoever calls it, and the one field the canonical purpose asks for that the log genuinely cannot supply.
Intermediate18 min readPythonPart IILog ParsingUVMVerification Flow
Part II · Module 20 · Chapter 20.16 · Turning One Log Into a Result Record
1. The Product
Chapter 20.2 built a checker that printed FAIL. Everything since has been about what else is in the log and how to get it out without reading the file twice or holding it in memory. What comes out the far end is one value:
{"test": name, "seed": seed, "status": status,
"errors": n_err, "first_failure": first}That is the canonical annotation, and it is the shape rather than the full list — the record this chapter ships has seventeen keys, and Section 3 names the chapter that earned each one.
The reason to care about the shape is what happens next. Chapter 21.1 designs a result record for CSV and JSON; Chapter 25.6 returns one from a simulation runner; Chapter 26.6 aggregates them across a regression; Chapter 30.2 decides what a report shows. All four are downstream of this dictionary, so a field missing here is a field missing from the whole flow, and a field whose meaning is vague here is vague everywhere.
2. Four Groups of Field
The split matters because the groups have different owners. Counts and evidence are measurements — they change when the tool's output format changes. The verdict is policy — it changes when the project decides what counts as a failure. Chapter 20.1 Section 4 made that argument on a five-line script; here it is a property of the record, and it is why status sits beside the counts rather than replacing them.
3. Every Field, and the Chapter That Earned It
| Field | Type | From |
|---|---|---|
log | str | 20.4 — report the input you actually read |
test | str or None | 20.8 — the plusarg or the RNTST banner |
seed | int or None | 20.8 — a list of simulator spellings |
errors | int | 20.7 — messages, not summary tallies |
fatals | int | 20.7 |
warnings | int | 20.7 |
assertions | int | 20.9 — SVA failures carry no UVM severity |
first_failure | str or None | 20.7 — the first, by the is None guard |
first_failure_time | int or None | 20.9 — earliest by time, not file position |
context | list of str | 20.10 — before, the failure, after |
context_marker | int or None | 20.10 — which element is the failure |
started | bool | 20.11 — the RNTST banner |
finished | bool | 20.11/20.12 — an end-of-sim marker |
unparsed | int | 20.6 — lines nothing recognised |
counts_agree | bool or None | 20.7 — our counts versus the tool's |
status | str | 20.11 — PASS, FAIL, NO_FINISH, NO_RUN |
runtime_s | float or None | not from the log — Section 6 |
Seventeen fields and sixteen chapters. A field with no chapter behind it is not in the record — that is the rule that keeps a result record from accumulating things somebody once needed, and it is worth applying literally when you extend this for your own flow.
4. The Parser
xcelium: *N,RUNCMD: run -f cmd.f +UVM_TESTNAME=axi_smoke_test
Simulation random seed = 1839274
UVM_INFO @ 0: reporter [RNTST] Running test axi_smoke_test...
UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [WR] issuing write
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] bad handshake
UVM_INFO drv.sv(92) @ 142000: uvm_test_top.env.agt.drv [WR] retrying
UVM_ERROR drv.sv(104) @ 180400: uvm_test_top.env.agt.drv [WR] timeout
--- UVM Report Summary ---
UVM_INFO : 3
UVM_WARNING : 0
UVM_ERROR : 2
UVM_FATAL : 0
TEST DONExcelium: *N,RUNCMD: run -f cmd.f +UVM_TESTNAME=axi_reset_test
Simulation random seed = 771002
UVM_INFO @ 0: reporter [RNTST] Running test axi_reset_test...
UVM_INFO scb.sv(120) @ 160000: uvm_test_top.env.scb [CHK] 96 compared
--- UVM Report Summary ---
UVM_INFO : 2
UVM_WARNING : 0
UVM_ERROR : 0
UVM_FATAL : 0
TEST DONExcelium: *N,RUNCMD: run -f cmd.f +UVM_TESTNAME=axi_burst_test
Simulation random seed = 904113
UVM_INFO @ 0: reporter [RNTST] Running test axi_burst_test...
UVM_INFO drv.sv(60) @ 141800: uvm_test_top.env.agt.drv [WR] waitingxmelab: *E,CUVWSP: module worklib.tb_top not found
xcelium: *F,NOELAB: elaboration failedimport re
UVM = re.compile(
r"^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL)"
r"(?:\s+(?P<file>\S+\.sv)\((?P<line>\d+)\))?"
r"\s+@\s+(?P<time>\d+):\s+(?P<scope>\S+)"
r"(?:\s+\[(?P<id>[^\]]+)\])?\s*(?P<msg>.*)$"
)
TALLY = re.compile(r"^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL)\s*:\s*(?P<n>\d+)\s*$")
SVA = re.compile(r"Assertion (?P<name>[\w.]+) failed at time (?P<t>\d+)")
TESTNAME = re.compile(r"\+UVM_TESTNAME=(\w+)")
BANNER = re.compile(r"\[RNTST\] Running test (\w+)")
FINISH = re.compile(r"TEST DONE|Simulation complete|\$finish")
SEED_PATTERNS = [re.compile(r"random seed\s*=\s*(\d+)"),
re.compile(r"\+ntb_random_seed=(\d+)")]
SEVERITIES = ["INFO", "WARNING", "ERROR", "FATAL"]
BEFORE = 2
AFTER = 1
def new_record(path):
"""Every key, present from the start. Chapter 20.6's rule."""
return {"log": path, "test": None, "seed": None,
"errors": 0, "fatals": 0, "warnings": 0, "assertions": 0,
"first_failure": None, "first_failure_time": None,
"context": [], "context_marker": None,
"started": False, "finished": False, "unparsed": 0,
"counts_agree": None, "status": "UNKNOWN", "runtime_s": None}
def parse_sim_log(path):
"""One UVM simulation log, one pass, one record. Raises FileNotFoundError."""
record = new_record(path)
counted = dict.fromkeys(SEVERITIES, 0)
reported = {}
recent, after, pending = [], [], 0
def note_failure(line, time):
if record["first_failure"] is None:
record["first_failure"] = line
record["first_failure_time"] = time
record["context"] = recent[-BEFORE:]
record["context_marker"] = len(record["context"])
return AFTER
return 0
with open(path, encoding="utf-8") as handle:
for raw in handle:
line = raw.rstrip()
if pending:
after.append(line)
pending -= 1
if record["test"] is None:
m = TESTNAME.search(line) or BANNER.search(line)
if m is not None:
record["test"] = m.group(1)
if record["seed"] is None:
for pattern in SEED_PATTERNS:
m = pattern.search(line)
if m is not None:
record["seed"] = int(m.group(1))
break
if BANNER.search(line):
record["started"] = True
if FINISH.search(line):
record["finished"] = True
m = UVM.match(line)
if m is not None:
counted[m["sev"]] += 1
if m["sev"] in ("ERROR", "FATAL"):
key = "errors" if m["sev"] == "ERROR" else "fatals"
record[key] += 1
pending = note_failure(line, int(m["time"])) or pending
elif m["sev"] == "WARNING":
record["warnings"] += 1
else:
t = TALLY.match(line)
a = SVA.search(line)
if t is not None:
reported[t["sev"]] = int(t["n"])
elif a is not None:
record["assertions"] += 1
pending = note_failure(line, int(a["t"])) or pending
elif line.strip():
record["unparsed"] += 1
recent.append(line)
if len(recent) > BEFORE:
recent.pop(0)
if record["first_failure"] is not None:
record["context"] = record["context"] + [record["first_failure"]] + after
if reported:
record["counts_agree"] = reported == counted
if not record["started"]:
record["status"] = "NO_RUN"
elif not record["finished"]:
record["status"] = "NO_FINISH"
elif record["errors"] or record["fatals"] or record["assertions"]:
record["status"] = "FAIL"
else:
record["status"] = "PASS"
return recordfrom parser import parse_sim_log
LOGS = ["smoke.log", "reset.log", "hang.log", "norun.log"]
print(f"{'log':<11} {'status':<10} {'test':<16} {'seed':>8} {'err':>4} "
f"{'agree':>6} {'ctx':>4}")
for path in LOGS:
r = parse_sim_log(path)
print(f"{path:<11} {r['status']:<10} {str(r['test']):<16} {str(r['seed']):>8} "
f"{r['errors']:>4} {str(r['counts_agree']):>6} {len(r['context']):>4}")log status test seed err agree ctx
smoke.log FAIL axi_smoke_test 1839274 2 True 4
reset.log PASS axi_reset_test 771002 0 True 0
hang.log NO_FINISH axi_burst_test 904113 0 None 0
norun.log NO_RUN None None 0 None 0Four logs, four statuses, every field filled or honestly None.
Read the agree column: True on the two logs that contain a report summary, and None on the two that do not — Chapter 20.7's self-check, with None distinguishing we checked and agreed from there was nothing to check against. A False there would mean the parser and the simulator disagree, which Chapter 20.7 said is a parser bug until proved otherwise.
And hang.log keeps its test name and seed. A hung run is still reproducible, which is often the most useful thing about the record.
5. One Record in Full
xcelium: *N,RUNCMD: run -f cmd.f +UVM_TESTNAME=axi_smoke_test
Simulation random seed = 1839274
UVM_INFO @ 0: reporter [RNTST] Running test axi_smoke_test...
UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [WR] issuing write
UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] bad handshake
UVM_INFO drv.sv(92) @ 142000: uvm_test_top.env.agt.drv [WR] retrying
UVM_ERROR drv.sv(104) @ 180400: uvm_test_top.env.agt.drv [WR] timeout
--- UVM Report Summary ---
UVM_INFO : 3
UVM_WARNING : 0
UVM_ERROR : 2
UVM_FATAL : 0
TEST DONEimport re
UVM = re.compile(
r"^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL)"
r"(?:\s+(?P<file>\S+\.sv)\((?P<line>\d+)\))?"
r"\s+@\s+(?P<time>\d+):\s+(?P<scope>\S+)"
r"(?:\s+\[(?P<id>[^\]]+)\])?\s*(?P<msg>.*)$"
)
TALLY = re.compile(r"^UVM_(?P<sev>INFO|WARNING|ERROR|FATAL)\s*:\s*(?P<n>\d+)\s*$")
SVA = re.compile(r"Assertion (?P<name>[\w.]+) failed at time (?P<t>\d+)")
TESTNAME = re.compile(r"\+UVM_TESTNAME=(\w+)")
BANNER = re.compile(r"\[RNTST\] Running test (\w+)")
FINISH = re.compile(r"TEST DONE|Simulation complete|\$finish")
SEED_PATTERNS = [re.compile(r"random seed\s*=\s*(\d+)")]
SEVERITIES = ["INFO", "WARNING", "ERROR", "FATAL"]
BEFORE = 2
AFTER = 1
def parse_sim_log(path):
record = {"log": path, "test": None, "seed": None,
"errors": 0, "fatals": 0, "warnings": 0, "assertions": 0,
"first_failure": None, "first_failure_time": None,
"context": [], "context_marker": None,
"started": False, "finished": False, "unparsed": 0,
"counts_agree": None, "status": "UNKNOWN", "runtime_s": None}
counted = dict.fromkeys(SEVERITIES, 0)
reported = {}
recent, after, pending = [], [], 0
with open(path, encoding="utf-8") as handle:
for raw in handle:
line = raw.rstrip()
if pending:
after.append(line)
pending -= 1
if record["test"] is None:
m = TESTNAME.search(line) or BANNER.search(line)
if m is not None:
record["test"] = m.group(1)
if record["seed"] is None:
for pattern in SEED_PATTERNS:
m = pattern.search(line)
if m is not None:
record["seed"] = int(m.group(1))
break
if BANNER.search(line):
record["started"] = True
if FINISH.search(line):
record["finished"] = True
m = UVM.match(line)
if m is not None:
counted[m["sev"]] += 1
if m["sev"] in ("ERROR", "FATAL"):
record["errors" if m["sev"] == "ERROR" else "fatals"] += 1
if record["first_failure"] is None:
record["first_failure"] = line
record["first_failure_time"] = int(m["time"])
record["context"] = recent[-BEFORE:]
record["context_marker"] = len(record["context"])
pending = AFTER
elif m["sev"] == "WARNING":
record["warnings"] += 1
else:
t = TALLY.match(line)
if t is not None:
reported[t["sev"]] = int(t["n"])
elif line.strip():
record["unparsed"] += 1
recent.append(line)
if len(recent) > BEFORE:
recent.pop(0)
if record["first_failure"] is not None:
record["context"] = record["context"] + [record["first_failure"]] + after
if reported:
record["counts_agree"] = reported == counted
if not record["started"]:
record["status"] = "NO_RUN"
elif not record["finished"]:
record["status"] = "NO_FINISH"
elif record["errors"] or record["fatals"] or record["assertions"]:
record["status"] = "FAIL"
else:
record["status"] = "PASS"
return recordfrom parser import parse_sim_log
record = parse_sim_log("smoke.log")
for key in sorted(record):
if key == "context":
continue
print(f" {key:<20} {record[key]!r}")
print()
print(" context:")
for index, line in enumerate(record["context"]):
marker = ">>>" if index == record["context_marker"] else " "
print(f" {marker} {line[:50]}") assertions 0
context_marker 2
counts_agree True
errors 2
fatals 0
finished True
first_failure 'UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.agt.drv [WR] bad handshake'
first_failure_time 141900
log 'smoke.log'
runtime_s None
seed 1839274
started True
status 'FAIL'
test 'axi_smoke_test'
unparsed 4
warnings 0
context:
UVM_INFO @ 0: reporter [RNTST] Running test axi_sm
UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt
>>> UVM_ERROR drv.sv(88) @ 141900: uvm_test_top.env.ag
UVM_INFO drv.sv(92) @ 142000: uvm_test_top.env.agtEverything a triage report needs, from one pass over one file.
unparsed: 4 on a perfectly healthy log is worth explaining rather than treating as a defect. Those four are the xcelium RUNCMD line, the seed line, the --- UVM Report Summary --- banner and TEST DONE — real lines the parser extracts facts from but does not classify as messages. Chapter 20.6 Section 4 said the number only means something as a ratio: four out of twelve is normal, twelve out of twelve is a format change.
6. The Field the Log Cannot Fill
The canonical purpose lists runtime among the record's contents, and runtime_s is in the record as None. That is deliberate.
Wall-clock runtime is not in the log. The log contains simulation time — @ 180400 — which is a count of picoseconds in a simulated world and has no fixed relationship to seconds on a wall. A test that simulates 200 microseconds might take nine seconds or four hours depending on the design size, the machine and whether waveform dumping was on.
Deriving one from the other would be a fabrication, and a precise-looking one. So the record reserves the key and leaves it for whoever ran the simulation:
def parsed(path):
"""Stand-in for parse_sim_log, so this example needs no log file."""
return {"log": path, "test": "axi_smoke_test", "status": "FAIL",
"errors": 2, "runtime_s": None}
record = parsed("smoke.log")
print("from the log alone:", record["runtime_s"])
record["runtime_s"] = 143.2
print("after the runner :", record["runtime_s"])
print()
print("reproduce:", f"run_sim.py --test {record['test']} --seed 1839274")from the log alone: None
after the runner : 143.2
reproduce: run_sim.py --test axi_smoke_test --seed 1839274The same applies to the runner's exit status and to Chapter 20.12's timeout reason: facts the launcher has and the log does not. Chapter 25.6 is where the runner fills them in, and the record is designed so it can — a reserved key with an honest None rather than a missing key or an invented number.
7. A Dict, Not a Dataclass
Chapter 16.15 introduced dataclasses and Chapter 16.16 gave the test for when a class earns its place. Applied here, the answer is a dict, and the reasoning is worth being explicit about because the opposite choice is defensible later.
The record has no behaviour. It is seventeen values and no methods. Chapter 16.16 Section 3 said the test is behaviour, and there is none.
It goes straight into formats that want a mapping. Chapter 21.2's csv.DictWriter takes a dict; json.dump takes a dict. A dataclass would be converted back at the boundary.
Its fields change as a flow grows. Chapter 25.6 adds the runner's facts, Chapter 26.6 adds the job id. With a dict that is an assignment; with a dataclass it is an edit to a shared type that every other consumer must be rebuilt against.
It is data in transit, not a thing with an identity. Nobody asks whether two records are the same object.
What would change the answer: the moment the record grows methods — is_reproducible(), summary_line(), worse_than(other) — a dataclass stops the methods being scattered across the modules that use it. That is Chapter 25.6's situation and not this one.
8. What It Deliberately Does Not Contain
Four things a reader might expect, and why each is absent:
Every failing line. Only the first, plus context. A log with forty thousand errors would otherwise make the record bigger than the summary it feeds, and Chapter 20.10 Section 6 argued that a report nobody opens is a report that does not work. The log path is in the record; everything else is one less away.
The full severity tallies as a sub-dict. counted exists inside the parser and only counts_agree comes out. The four counts the caller needs are already top-level fields, and a nested dict would complicate every CSV writer downstream for no new information.
The assertion names. Chapter 20.9 parsed them and the record keeps only the count, because a list of them is unbounded. If a flow needs them, they belong in a second record type — one per assertion failure, as Chapter 20.9 Section 4 produced — not crammed into this one.
A pass/fail boolean. status has four values and a boolean would throw away two of them. Chapter 20.11 Section 1's three-passes-out-of-four is what a boolean costs, and any consumer wanting one can write record["status"] == "PASS" for itself.
The pattern across all four: the record carries what is bounded and summarises what is not. That is Chapter 15.7 Section 5's bounded summary, applied one level up — not to the lines of a log, but to the shape of a result.
9. Predict, Run, Observe
def new_record(path):
return {"log": path, "test": None, "seed": None, "errors": 0,
"first_failure": None, "status": "UNKNOWN", "runtime_s": None}
def classify(record):
if not record.get("started"):
return "NO_RUN"
if not record.get("finished"):
return "NO_FINISH"
return "FAIL" if record["errors"] else "PASS"
a = new_record("a.log")
b = new_record("b.log")
# A
print("A:", sorted(a) == sorted(b))
# B
print("B:", a["seed"], a["runtime_s"])
# C
a.update({"started": True, "finished": True, "errors": 0})
print("C:", classify(a))
# D
b.update({"started": True, "finished": False, "errors": 7})
print("D:", classify(b))
# E
a["errrors"] = 99
print("E:", a["errors"], len(a))
# F
try:
print(a["runtime"])
except KeyError as exc:
print("F: KeyError", exc)
# G
print("G:", a["runtime_s"] is None, a["runtime_s"] == 0)The verified output:
A: True
B: None None
C: PASS
D: NO_FINISH
E: 0 10
F: KeyError 'runtime'
G: True FalseA — two records from different logs have the same keys. That is the property every consumer relies on, and it is one line to check.
B — unfilled fields are None, not zero and not absent.
C and D — the verdict comes from facts the record already holds, and D is NO_FINISH despite seven errors. Chapter 20.11's ordering.
E — the misspelled key was accepted silently, errors is untouched at 0, and the record now carries ten keys where new_record created seven. The dict's real cost, and the reason new_record exists.
F — reading a key that was never created raises, which is how the Section E typo eventually surfaces — somewhere else, later.
G — None is not 0. A consumer averaging runtime_s must skip the Nones rather than treat them as zero-second runs.
10. Exercises
Exercise 1 — the product. Write down the four groups of field for a report format in your own flow, and one field in each.
Exercise 2 — earn every field. List the fields of your own result record and name the reason each exists. Delete any you cannot justify.
Exercise 3 — one pass. Write parse_sim_log for your format. Confirm it reads the file once and name every piece of state it holds.
Exercise 4 — bounded. Say which of your state variables could grow with the log, and what stops each one.
Exercise 5 — four logs. Run your parser over a passing log, a failing one, a truncated one and a log from a run that never started. Print one row each.
Exercise 6 — the agree column. Produce a record with counts_agree of True, one with None, and say what a False would mean.
Exercise 7 — a hung run is reproducible. Confirm your NO_FINISH record still carries its test and seed, and say why that matters.
Exercise 8 — the unparsed ratio. Report unparsed and the total line count for a healthy log. Choose a ratio that would make you suspicious.
Exercise 9 — the reserved key. Add runtime_s: None and fill it from outside. Say what omitting the key would cost, and what filling it with 0 would cost.
Exercise 10 — dict or dataclass. Apply Chapter 16.16's test to your record and justify the answer in three sentences. Then name the change that would flip it.
Exercise 11 — the silent typo. Misspell a key on write and show that nothing raises. Then show where it surfaces.
Exercise 12 — what you left out. Name one thing you considered putting in the record and did not. Say what is unbounded about it and where it should live instead.
11. Summary
- The record is the module's product, and Chapters 21.1, 25.6, 26.6 and 30.2 are all downstream of its shape.
- Four groups: identity, counts, evidence, verdict — and only the verdict is policy.
- Counts and evidence change when the tool changes; the verdict changes when the project does.
- Every field names the chapter that earned it. A field with no chapter behind it does not go in.
- Every key is present on every log, built complete by
new_recordbefore the loop starts. - One pass, bounded state: a ring buffer, two count dicts, a pending countdown. Nothing grows with the log.
counts_agreeisTrue,FalseorNone— agreed, disagreed, or there was no summary block to check against.- A hung run keeps its test and seed, so it is still reproducible.
unparsedon a healthy log is not zero. It only means something as a ratio.runtime_sisNonebecause the log does not contain it — simulation time is not wall time, and deriving one from the other is a precise-looking fabrication.- A reserved key is a promise: omitting it gives a
KeyErroron unenriched records, and filling it with0puts a fake value into an average. - A dict, not a dataclass — no behaviour, goes straight into
csv.DictWriterandjson.dump, and gains fields as the flow grows. - The dict's cost is the silent typo on write, which
new_recordturns into aKeyErroron read. - The record carries what is bounded and summarises what is not — the first failure rather than all of them, a count rather than a list of assertion names, four statuses rather than a boolean.
That completes the parser. Module 21 takes this record and gives it somewhere to live: a result table other tools can read, a configuration humans can edit, and the formats a flow exchanges data in.
Where this fits
Part of the Python curriculum.