Building a Pipeline Incrementally

Part I · Module 13 · Chapter 13.9 · Building a Pipeline Incrementally

You now know the tools. This chapter is about the thing that goes wrong anyway.

1. The Failure Mode

Somebody needs the ten most common errors across a regression. They know every tool required, so they write it:

grep -h ERROR runs/*/sim.log | sed 's/.*ERROR: //' | sort | uniq -c | sort -rn | head -10

And it prints nothing.

Now what? Six stages, any of which could be wrong. The logs might be somewhere else. The word might be Error. The messages might not contain ERROR: with that exact spacing. sort might be fine and uniq might be fine and the whole thing might be failing at stage one.

The usual response is to stare at it, change something, run it again, and repeat. That can take an hour, and at the end you often still do not know which stage was wrong — only that it works now.

2. The Method, Applied

The same problem, built properly. Each step is one keystroke of growth and one look.

Stage 1 — does the input exist at all?

$ grep -h ERROR runs/*/sim.log | head -3
[12:04:11] ERROR: timeout after 1203 cycles in alu_tb
[12:04:55] ERROR: assertion failed at fifo.sv:214
[12:09:02] ERROR: timeout after 1891 cycles in alu_tb

Three lines, which answers several questions at once: the logs are where I thought, the word is spelled that way, and the messages have a [timestamp] ERROR: prefix. Had this printed nothing, I would be debugging one command.

Stage 2 — strip the prefix.

$ grep -h ERROR runs/*/sim.log | sed 's/.*ERROR: //' | head -3
timeout after 1203 cycles in alu_tb
assertion failed at fifo.sv:214
timeout after 1891 cycles in alu_tb

Working. And now I can see the problem the naive version would have hit: the two timeouts differ only by a cycle count. Counting these as they stand gives every message a count of 1.

Stage 3 — normalise the numbers. (Chapter 13.4 and 13.6.)

$ grep -h ERROR runs/*/sim.log | sed 's/.*ERROR: //' | sed 's/[0-9][0-9]*/N/g' | head -3
timeout after N cycles in alu_tb
assertion failed at fifo.sv:N
timeout after N cycles in alu_tb

Two identical lines where there were two different ones. That step only exists because I looked at stage 2.

Stage 4 — group and count.

$ ... | sort | uniq -c | head -3
   2 timeout after N cycles in alu_tb
   1 assertion failed at fifo.sv:N

Stage 5 — rank.

$ ... | sort -rn | head -10

Done, in five looks, with a normalisation step the "write it all at once" approach would have missed entirely — and would not have noticed missing, because the output would have been a plausible list of distinct errors.

3. Four Practices

Keep | head on the end while developing

grep -h ERROR runs/*/sim.log | sed 's/.*ERROR: //' | head

A stage that produces forty thousand lines tells you nothing on screen and takes a while. head makes every iteration instant and the output readable.

Remove it at the end — and remember Chapter 12.8's warning that | head under pipefail can report 141.

Work on a small sample

head -1000 enormous.log > /tmp/sample.log

Then develop against /tmp/sample.log and switch to the real input once it works. Iterating against four gigabytes is how a ninety-second job becomes an afternoon.

Make sure the sample is representative — head takes the beginning, which may be all startup banner. shuf -n 1000 takes a random selection where it is available.

Use tee to inspect the middle

grep -h ERROR *.log \
  | tee /tmp/s1.txt \
  | sed 's/.*ERROR: //' \
  | tee /tmp/s2.txt \
  | sort | uniq -c | sort -rn

When a finished pipeline is wrong and you want to find where, taps let you look at every intermediate without rerunning anything (Chapter 12.6). Remove them once you know.

Count at each stage

$ grep -h ERROR runs/*/sim.log | wc -l
847
$ grep -h ERROR runs/*/sim.log | sed 's/.*ERROR: //' | wc -l
847
$ grep -h ERROR runs/*/sim.log | sed 's/.*ERROR: //' | sort -u | wc -l
12

A line count at each stage tells you where records disappeared. 847 in, 847 after the substitution — good, sed transforms rather than filters. Then 12 distinct messages, which is the answer taking shape.

A stage that unexpectedly drops to zero, or to a suspiciously round number, is the one to look at.

4. Ask for Machine-Readable Output First

Chapter 13.1 raised this and it belongs here, because it is a decision made before the first stage.

$ df -h | head -3
Filesystem      Size  Used Avail Capacity  Mounted on
/dev/disk3s1s1  926Gi  9.6Gi  317Gi     3%    /
/dev/disk3s6    926Gi  1.0Gi  317Gi     1%    /System/Volumes/VM

Aligned for a person: a header, variable spacing, a % suffix, units attached to numbers. Parsing it means tail -n +2, then awk for the runs of spaces, then tr -d '%' or sed for the units — three stages of undoing the formatting before you start.

$ df -P | head -3

The POSIX format is one line per filesystem with predictable fields. Most tools have an equivalent:

5. Finishing a Pipeline

Once it works, three things make it worth keeping.

Break it across lines.

grep -h ERROR runs/*/sim.log \
  | sed 's/.*ERROR: //' \
  | sed 's/[0-9][0-9]*/N/g' \
  | sort \
  | uniq -c \
  | sort -rn \
  | head -10

One stage per line, with the backslashes from Chapter 9.3. Now it is reviewable, each stage can be commented, and a stage can be removed by deleting a line.

Remove the stages that were scaffolding. The head you were developing with, the cat at the front, the tee taps. And check for pairs that collapse:

That last one matters under pipefail (Chapter 12.8).

Say what it does.

# The ten most frequent error messages across all runs, with embedded
# numbers normalised so that the same error with different cycle counts
# is counted once rather than as many distinct messages.
grep -h ERROR runs/*/sim.log \
  | sed 's/.*ERROR: //' \
  ...

A pipeline is dense. Three lines of comment explaining the intent — especially any step whose reason is not obvious, like the normalisation — is what makes it maintainable. The code says what; the comment says why.

6. Debugging One That Is Already Broken

Inheriting a pipeline that does not work is the common case, and the method is the same in reverse: cut it down until it works, then add forwards.

# the whole thing — nothing
grep -h ERROR runs/*/sim.log | sed 's/.*ERROR: //' | sort | uniq -c | sort -rn | head

# first stage only
grep -h ERROR runs/*/sim.log | head

If stage one gives nothing, you have found it in one step. If it gives output, add the second and continue. Bisect if it is long — run the first three stages, and depending on what you see, look in the first half or the second.

A checklist of what usually turns out to be wrong:

Every row of that table is a chapter of this module, which is a reasonable summary of what the module was for.

7. A Worked Example, End to End

The question: across a regression, which tests failed most often, and how much simulation time did the failures waste?

Step 1 — find the inputs and look at one.

$ ls runs/ | head -3
run_alu_seed3
run_alu_seed7
run_fifo_seed3

$ head -3 runs/run_alu_seed3/sim.log
[00:00:01] starting alu_tb
[00:04:22] TEST FAILED: assertion at alu.sv:88
[00:04:22] SIMULATION TIME 262.4 seconds

Step 2 — find the failures.

$ grep -l 'TEST FAILED' runs/*/sim.log | head -3
runs/run_alu_seed3/sim.log
runs/run_alu_seed11/sim.log
runs/run_fifo_seed9/sim.log

-l gives names rather than lines, which is what "which tests" needs.

Step 3 — reduce a path to a test name.

$ grep -l 'TEST FAILED' runs/*/sim.log | sed 's|runs/run_||; s|/sim.log||' | head -3
alu_seed3
alu_seed11
fifo_seed9

Step 4 — drop the seed, since the question is about tests.

$ ... | sed 's/_seed[0-9]*$//' | head -3
alu
alu
fifo

Step 5 — count and rank.

$ ... | sort | uniq -c | sort -rn
   2 alu
   1 fifo

Step 6 — the second half of the question, separately.

$ grep -h 'SIMULATION TIME' $(grep -l 'TEST FAILED' runs/*/sim.log) \
  | awk '{s += $3} END {printf "%.1f minutes wasted\n", s/60}'
8.7 minutes wasted

The finished pair, commented:

# Which tests failed most often, ignoring the seed.
grep -l 'TEST FAILED' runs/*/sim.log \
  | sed 's|runs/run_||; s|/sim.log||; s/_seed[0-9]*$//' \
  | sort | uniq -c | sort -rn

# How much simulation time the failing runs consumed.
grep -h 'SIMULATION TIME' $(grep -l 'TEST FAILED' runs/*/sim.log) \
  | awk '{s += $3} END {printf "%.1f minutes\n", s/60}'

Six looks, two answers, and the three sed expressions collapsed into one at the end — which was safe to do only because each had been verified separately.

Practice

mkdir -p /tmp/bp/runs/run_alu_seed3 /tmp/bp/runs/run_alu_seed11 /tmp/bp/runs/run_fifo_seed9 /tmp/bp/runs/run_uart_seed1
cd /tmp/bp
printf '[00:00:01] starting\n[00:04:22] TEST FAILED: assertion at alu.sv:88\n[00:04:22] SIMULATION TIME 262.4 seconds\n' > runs/run_alu_seed3/sim.log
printf '[00:00:01] starting\n[00:03:02] TEST FAILED: timeout after 1891 cycles\n[00:03:02] SIMULATION TIME 182.0 seconds\n' > runs/run_alu_seed11/sim.log
printf '[00:00:01] starting\n[00:01:40] TEST FAILED: timeout after 1203 cycles\n[00:01:40] SIMULATION TIME 100.1 seconds\n' > runs/run_fifo_seed9/sim.log
printf '[00:00:01] starting\n[00:02:10] TEST PASSED\n[00:02:10] SIMULATION TIME 130.0 seconds\n' > runs/run_uart_seed1/sim.log

1 — Build §7 yourself, one stage at a time. Run each of these and look before typing the next:

grep -l 'TEST FAILED' runs/*/sim.log
grep -l 'TEST FAILED' runs/*/sim.log | sed 's|runs/run_||'
grep -l 'TEST FAILED' runs/*/sim.log | sed 's|runs/run_||; s|/sim.log||'
grep -l 'TEST FAILED' runs/*/sim.log | sed 's|runs/run_||; s|/sim.log||; s/_seed[0-9]*$//'
grep -l 'TEST FAILED' runs/*/sim.log | sed 's|runs/run_||; s|/sim.log||; s/_seed[0-9]*$//' | sort | uniq -c | sort -rn

2 — Count at each stage.

grep -h 'TEST FAILED' runs/*/sim.log | wc -l
grep -h 'TEST FAILED' runs/*/sim.log | sed 's/.*FAILED: //' | wc -l
grep -h 'TEST FAILED' runs/*/sim.log | sed 's/.*FAILED: //' | sort -u | wc -l

3 — Discover the need for normalisation.

grep -h 'TEST FAILED' runs/*/sim.log | sed 's/.*FAILED: //' | sort | uniq -c
echo "--- normalised ---"
grep -h 'TEST FAILED' runs/*/sim.log | sed 's/.*FAILED: //; s/[0-9][0-9]*/N/g' | sort | uniq -c

4 — Tap the middle with tee.

grep -h 'TEST FAILED' runs/*/sim.log \
  | tee /tmp/bp/s1.txt \
  | sed 's/.*FAILED: //' \
  | tee /tmp/bp/s2.txt \
  | sort | uniq -c
cat /tmp/bp/s1.txt; echo "---"; cat /tmp/bp/s2.txt

5 — Sum a field.

grep -h 'SIMULATION TIME' runs/*/sim.log | awk '{s += $3} END {printf "%.1f\n", s}'

6 — Collapse redundant stages.

grep 'TEST FAILED' runs/*/sim.log | wc -l
grep -c 'TEST FAILED' runs/*/sim.log | awk -F: '{s+=$2} END {print s}'
cat runs/run_alu_seed3/sim.log | grep FAILED
grep FAILED runs/run_alu_seed3/sim.log

7 — Compare human and machine formats.

df -h | head -3
df -P | head -3
ps -eo pid,user,etime | head -3
ps -eo pid,user,etime | tail -n +2 | head -2

8 — Debug a broken one by bisecting.

grep -h 'Test Failed' runs/*/sim.log | sed 's/.*: //' | sort | uniq -c
grep -h 'Test Failed' runs/*/sim.log
grep -hi 'test failed' runs/*/sim.log | head -2

The first gives nothing. Two more commands find out why.

9 — Clean up. cd /tmp && rm -rf /tmp/bp

Check Your Understanding

1. What is the one rule for building a pipeline?

2. Why does building incrementally find problems that writing it all at once does not?

3. Why keep | head on the end while developing, and what must you remember when removing it?

4. A six-stage pipeline returns nothing. What is the first command you run?

5. Why prefer a tool's machine-readable format beyond it being easier to parse?

6. When should a pipeline become a script?

8. Remember

• Add one stage, look, repeat. That is the method, and it is faster than it feels.
• Looking is how you find the problem you did not know you had — a timestamp, a varying number, a header line.
• Keep | head on while developing, and remember it can report 141 under pipefail once you take it off.
• Work on a small, representative sample before the real input.
• tee in the middle lets you inspect a finished pipeline without rerunning it.
• Count lines at each stage to see where records disappeared.
• Ask for machine-readable output before writing anything — it is a documented interface, while the aligned format is presentation and will change.
• Break a finished pipeline across lines, one stage each, with backslashes.
• Remove the scaffolding and collapse pairs: sort -u, grep -c, grep -m1, no leading cat.
• Comment the intent, especially any step whose reason is not obvious.
• Debug by cutting back to one stage and adding forwards, or by bisecting a long one.
• Six stages is about the limit. Beyond that, write a script — and Chapter 14.8 returns to where that line sits.

That completes Module 13, and with it the text-processing toolkit. You can take a stream of machine output apart by column or by field, reorder it, count what repeats, substitute and normalise, calculate across it, combine it with a second source, and assemble the whole thing without guessing.

Module 14 adds the two tools that find the text in the first place — grep for searching inside files and find for locating the files themselves — along with the pattern language both of them share, which this module has been using in small pieces and never explained.