Timeouts and Missing End-of-Simulation Markers

Part II · Module 20 · Chapter 20.12 · Timeouts and Missing End-of-Simulation Markers

1. Nothing Is the Signal

A failing test writes UVM_ERROR. A fatal writes UVM_FATAL. An assertion writes its own line. A hang writes nothing at all — the last entry in the log is whatever the testbench happened to be doing, and then the file stops.

So the detection is inverted. Every other check in this module asks is this thing present; this one asks is this thing absent, and the thing is the end-of-simulation marker:

TEST DONE
Simulation complete via $finish(1) at time 200000 NS

A testbench writes one or both when it reaches the end of the test. Their absence means the test did not get there.

2. The Marker Is in the Tail

The canonical annotation says so in one line:

finished = any("TEST DONE" in l or "Simulation complete" in l for l in tail)

That is a generator expression, which this module introduces two chapters from now in Chapters 20.13 and 20.14. Carried as a sketch it is exactly right and this chapter executes the explicit form, in the same way Chapter 20.1 kept open() in the sketch and wrote with in the code:

UVM_INFO @ 0: reporter [RNTST] Running test axi_burst_test...
UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [WR] issuing write 0x40001000
UVM_INFO drv.sv(60) @ 141800: uvm_test_top.env.agt.drv [WR] waiting for response

UVM_INFO @ 0: reporter [RNTST] Running test axi_reset_test...
UVM_INFO scb.sv(120) @ 160000: uvm_test_top.env.scb [CHK] 96 compared
TEST DONE
Simulation complete via $finish(1) at time 200000 NS

MARKERS = ["TEST DONE", "Simulation complete", "$finish"]
TAIL = 5


def tail_lines(path, count):
    """The last `count` lines, holding no more than that at a time."""
    ring = []
    with open(path, encoding="utf-8") as handle:
        for line in handle:
            ring.append(line.rstrip())
            if len(ring) > count:
                ring.pop(0)
    return ring


def finished(path):
    for line in tail_lines(path, TAIL):
        for marker in MARKERS:
            if marker in line:
                return True
    return False


for path in ["done.log", "hang.log"]:
    print(f"{path:<10} finished={finished(path)}  last line={tail_lines(path, 1)[0][:44]!r}")

done.log   finished=True  last line='Simulation complete via $finish(1) at time 2'
hang.log   finished=False  last line='UVM_INFO drv.sv(60) @ 141800: uvm_test_top.e'

MARKERS is a list for Chapter 20.8's reason — the spelling is the testbench's and the tool's, not the methodology's. TEST DONE is something a project's base test prints; Simulation complete and $finish come from the simulator.

And tail_lines is Chapter 20.10's ring buffer again, holding five lines on a log of any length.

3. Reading the Tail Without Reading the Log

The ring buffer is bounded in memory and still reads every line. For a fact that lives in the last few hundred bytes, that is work you can skip entirely — seek backwards from the end:

import io
import os

LINES = 50000
with io.open("big.log", "w", encoding="utf-8") as handle:
    for i in range(1, LINES + 1):
        handle.write(f"UVM_INFO drv.sv(60) @ {i * 100}: uvm_test_top.env.agt.drv [WR] step {i}\n")
    handle.write("TEST DONE\n")
    handle.write("Simulation complete via $finish(1) at time 5000000 NS\n")

BUDGET = 400


def tail_bytes(path, budget):
    """The end of a file, without reading the rest of it."""
    with io.open(path, "rb") as handle:
        handle.seek(0, os.SEEK_END)
        size = handle.tell()
        back = min(budget, size)
        handle.seek(size - back)
        chunk = handle.read()
    return chunk.decode("utf-8", errors="replace").splitlines(), back


lines, read = tail_bytes("big.log", BUDGET)
print("lines in the log :", LINES + 2)
print("bytes read       :", read)
print("last two lines   :", lines[-2:])

lines in the log : 50002
bytes read       : 400
last two lines   : ['TEST DONE', 'Simulation complete via $finish(1) at time 5000000 NS']

Fifty thousand lines in the file, four hundred bytes read, and the same answer. That number is fixed: it is four hundred bytes for a 50,000-line log and four hundred bytes for a twenty-million-line one, because it is a property of the algorithm rather than of the file.

Three details make it work, and all three are the kind of thing that fails quietly if you get them wrong.

Binary mode. seek(0, os.SEEK_END) and a relative seek need "rb"; a text-mode handle cannot do it, because character positions and byte positions are not the same thing when an encoding is involved. Chapter 15.3's text-versus-binary distinction, with a consequence.

min(budget, size). A log shorter than the budget would otherwise seek to a negative position. Short logs are exactly the ones a failed run produces, so this is the common case rather than an edge case.

errors="replace". Seeking to an arbitrary byte offset usually lands in the middle of a character, and on a log truncated by a full disk it may land in the middle of one at the end too. Without this the decode raises on precisely the broken logs this function exists to examine.

4. What the Last Line Says

The absence is the verdict; the last line is the lead:

UVM_INFO @ 0: reporter [RNTST] Running test axi_burst_test...
UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [WR] issuing write 0x40001000
UVM_INFO drv.sv(60) @ 141800: uvm_test_top.env.agt.drv [WR] waiting for response

import re

UVM = re.compile(r"^UVM_\w+\s.*@\s+(?P<t>\d+):\s+(?P<scope>\S+)")

ring = []
with open("hang.log", encoding="utf-8") as handle:
    for line in handle:
        ring.append(line.rstrip())
        if len(ring) > 3:
            ring.pop(0)

print("last activity:")
for line in ring:
    print("   ", line[:58])

last = None
for line in ring:
    m = UVM.match(line)
    if m is not None:
        last = m

if last is not None:
    print()
    print("stopped at time :", int(last["t"]))
    print("last component  :", last["scope"])

last activity:
    UVM_INFO @ 0: reporter [RNTST] Running test axi_burst_test
    UVM_INFO drv.sv(60) @ 141700: uvm_test_top.env.agt.drv [WR
    UVM_INFO drv.sv(60) @ 141800: uvm_test_top.env.agt.drv [WR

stopped at time : 141800
last component  : uvm_test_top.env.agt.drv

Two facts worth more than the status: the simulation stopped at 141800, and the last component to say anything was the driver, waiting for a response. That is a specific thing to investigate — and it is the same instinct as Chapter 20.10's context block, applied to the end of the log instead of to a failure in the middle.

The simulation time matters separately from the wall clock. A run that hung at simulation time 141800 after an hour of wall time was running and got stuck; a run that hung at time 0 never got past reset.

5. Four Runs That Look Identical

Now the limit Chapter 20.11 Section 7 flagged. Here are five runs as the log sees them:

RUNS = [
    {"log": "pass.log", "finished": True},
    {"log": "hang.log", "finished": False},
    {"log": "crash.log", "finished": False},
    {"log": "disk.log", "finished": False},
    {"log": "norun.log", "finished": False},
]

for run in RUNS:
    status = "FINISHED" if run["finished"] else "NO_FINISH"
    print(f"{run['log']:<11} {status}")

pass.log    FINISHED
hang.log    NO_FINISH
crash.log   NO_FINISH
disk.log    NO_FINISH
norun.log   NO_FINISH

Four identical answers for four different events:

• hang.log — the testbench deadlocked and the scheduler killed it at the timeout.
• crash.log — the simulator segfaulted nine seconds in.
• disk.log — the test ran fine and the filesystem filled, so the last writes never landed.
• norun.log — the tool refused to start and exited immediately.

The log cannot separate them, and no pattern will, because the evidence that distinguishes them was never written to the log. A parser that guesses here produces a confident wrong diagnosis, which Chapter 20.11 argued is worse than an honest NO_FINISH.

6. Two Facts From Outside

Whatever launched the simulation knows two things the log does not: how long it ran, and what exit status it returned. Those two numbers split the four cases apart:

TIMEOUT_S = 7200

RUNS = [
    {"log": "pass.log", "finished": True, "wall_s": 143, "rc": 0},
    {"log": "hang.log", "finished": False, "wall_s": 7200, "rc": 124},
    {"log": "crash.log", "finished": False, "wall_s": 9, "rc": 139},
    {"log": "disk.log", "finished": False, "wall_s": 612, "rc": 0},
    {"log": "norun.log", "finished": False, "wall_s": 3, "rc": 1},
]


def diagnose(run, timeout_s):
    """Why the end-of-simulation marker is missing, using the runner's facts."""
    if run["finished"]:
        return "FINISHED"
    if run["wall_s"] >= timeout_s:
        return "TIMEOUT"
    if run["rc"] not in (0, 1):
        return "KILLED"
    if run["rc"] == 0:
        return "TRUNCATED"
    return "NO_FINISH"


print(f"{'log':<11} {'finished':>9} {'wall_s':>7} {'rc':>4}  diagnosis")
for run in RUNS:
    print(f"{run['log']:<11} {str(run['finished']):>9} {run['wall_s']:>7} "
          f"{run['rc']:>4}  {diagnose(run, TIMEOUT_S)}")

log          finished  wall_s   rc  diagnosis
pass.log         True     143    0  FINISHED
hang.log        False    7200  124  TIMEOUT
crash.log       False       9  139  KILLED
disk.log        False     612    0  TRUNCATED
norun.log       False       3    1  NO_FINISH

Five distinct answers from the same five logs, and each reading is a different investigation:

TIMEOUT — ran for the full limit. The test is stuck; look at Section 4's last activity, or the limit is too low for this test.

KILLED — rc 139 is the shape a process killed by a signal reports, and it stopped in nine seconds. Look at the simulator, not the testbench.

TRUNCATED — the tool exited successfully and the banner is missing anyway. The output did not land: a full disk, an NFS write that failed, or a log copied while it was being written. Nothing is wrong with the test.

NO_FINISH — exited 1, quickly, with no banner. The tool refused; its own error output is where to look.

TRUNCATED is the one worth dwelling on. Exit status 0 and no end-of-simulation banner is a contradiction, and a contradiction is a strong signal: the two sources of evidence disagree, so one of them is lying, and it is almost always the file. A parser that only read the log would call this a hang and send someone to debug a testbench that worked perfectly.

7. Folding It Into the Record

def classify(facts, runner=None, timeout_s=7200):
    """Four outcomes from the log; a reason when the runner's facts are there."""
    if not facts["started"]:
        return "NO_RUN", None
    if not facts["finished"]:
        if runner is None:
            return "NO_FINISH", None
        if runner["wall_s"] >= timeout_s:
            return "NO_FINISH", "TIMEOUT"
        if runner["rc"] not in (0, 1):
            return "NO_FINISH", "KILLED"
        if runner["rc"] == 0:
            return "NO_FINISH", "TRUNCATED"
        return "NO_FINISH", "TOOL_REFUSED"
    return ("FAIL" if (facts["errors"] or facts["fatals"]) else "PASS"), None


LOG_ONLY = {"started": True, "finished": False, "errors": 0, "fatals": 0}

print("log only      :", classify(LOG_ONLY))
print("with timeout  :", classify(LOG_ONLY, {"wall_s": 7200, "rc": 124}))
print("with crash    :", classify(LOG_ONLY, {"wall_s": 9, "rc": 139}))
print("with full disk:", classify(LOG_ONLY, {"wall_s": 612, "rc": 0}))

log only      : ('NO_FINISH', None)
with timeout  : ('NO_FINISH', 'TIMEOUT')
with crash    : ('NO_FINISH', 'KILLED')
with full disk: ('NO_FINISH', 'TRUNCATED')

The status does not change. NO_FINISH is what the log observed, and more evidence does not make it a different observation — it adds a reason, in a second field, which is None when nobody supplied the evidence.

That shape is worth copying. A record with status and reason keeps Chapter 20.11's four values stable — so a summary can count them without knowing anything about runners — while letting a richer caller say more. Collapsing TIMEOUT into the status instead would give the summary five values, then six, and every consumer would need updating each time a new reason was identified.

runner=None as the default is Chapter 11.5's optional argument doing real work: the parser is usable with the log alone, and better with more.

8. Predict, Run, Observe

MARKERS = ["TEST DONE", "Simulation complete", "$finish"]


def finished(lines):
    for line in lines:
        for marker in MARKERS:
            if marker in line:
                return True
    return False


# A
print("A:", finished(["UVM_INFO a", "TEST DONE"]))

# B
print("B:", finished(["UVM_INFO a", "UVM_INFO b"]))

# C
print("C:", finished([]))

# D
print("D:", finished(["note: the test prints TEST DONE at the end"]))

# E
ring = []
for item in ["a", "b", "c", "d", "e"]:
    ring.append(item)
    if len(ring) > 2:
        ring.pop(0)
print("E:", ring)

# F
print("F:", min(400, 120), min(400, 9000))

# G
print("G:", b"ab\xffcd".decode("utf-8", errors="replace"))

The verified output:

A: True
B: False
C: False
D: True
E: ['d', 'e']
F: 120 400
G: ab�cd

A and B — present and absent.

C — an empty log is not finished, which is the right default and the one Chapter 20.11 relies on.

D — a false positive: a line of prose mentioning the marker. Chapter 19.7's \b and an anchor would help; whether it is worth it depends on whether your logs contain commentary, and most do not.

E — the ring holds two, and they are the last two.

F — min picks the file size when the file is smaller than the budget, which is what stops a negative seek.

G — an undecodable byte becomes the replacement character instead of raising, which is what keeps the tail read working on a truncated log.

9. Exercises

Exercise 1 — absence. List every marker your own flow writes at the end of a simulation. Say which come from the testbench and which from the simulator.

Exercise 2 — the tail ring. Write tail_lines and confirm it holds a fixed number of lines on a long log.

Exercise 3 — seek backwards. Write tail_bytes and report how many bytes it reads on a 50,000-line log and on a 10-line one.

Exercise 4 — binary mode. Try a relative seek from the end on a text-mode handle. Record the error and say why the restriction exists.

Exercise 5 — the short log. Remove min(budget, size) and run it on a 40-byte file. Record what happens.

Exercise 6 — the broken character. Decode a tail chunk without errors="replace" on bytes that start mid-character. Say why this is the common case rather than an edge case.

Exercise 7 — the fragment. Print lines[0] from a tail read of a long log. Say what it is and write the conditional discard.

Exercise 8 — the last activity. From a hung log, report the last simulation time and the last component. Say what a stop at time 0 would suggest instead.

Exercise 9 — four identical answers. Build four logs representing a hang, a crash, a truncation and a refusal. Confirm your log-only check gives the same answer for all four.

Exercise 10 — two more facts. Add a wall clock and an exit status to each and write diagnose. Confirm you now get four different answers.

Exercise 11 — the contradiction. Explain in two sentences why exit status 0 with no end-of-simulation banner is strong evidence rather than a confusing case.

Exercise 12 — status and reason. Argue in three sentences for keeping TIMEOUT in a reason field rather than making it a fifth status.

10. Summary

• A hang writes nothing, so it is detected from the absence of an end-of-simulation marker rather than the presence of anything.
• Marker spellings are tool- and testbench-specific — TEST DONE, Simulation complete, $finish — so a list, as for Chapter 20.8's seed.
• The canonical one-liner uses a generator expression, which this module teaches in Chapters 20.13 and 20.14; the explicit loop is executed here.
• The marker is in the tail, so a ring buffer finds it with bounded memory and a backwards seek finds it in a fixed four hundred bytes whatever the file size.
• A relative seek from the end needs binary mode, because character and byte positions differ under an encoding.
• min(budget, size) stops a negative seek on the short logs that failed runs produce.
• errors="replace" keeps the decode working when the chunk starts — or ends — mid-character.
• The first line of a backwards chunk is usually a fragment, so discard it when the full budget was read.
• The last line is the lead: the simulation time it stopped at and the last component to speak.
• Simulation time and wall time are different evidence. Stuck at time 0 is reset; stuck at 141800 after an hour was running.
• Four different events produce an identical missing marker — a hang, a crash, a truncation and a tool that refused.
• The log cannot separate them, and no pattern will, because the distinguishing evidence was never written to it.
• The runner's wall clock and exit status split all four, and rc == 0 with no banner means the output did not land rather than the test hanging.
• Keep the status at NO_FINISH and put the cause in a reason field, so a summary's four values stay stable as reasons multiply.

The next chapter changes how the parser hands its results back — one record at a time, as it finds them, so a report over a thousand logs never holds a thousand logs at once.