Topic — Debugging and profiling a multi-PE run

Needs: Lesson 3 — How a PE runs a loop: vector instructions and cycles, Lesson 6 — Blocking, buffering and deadlock.

A multi-PE program goes wrong in one of three ways. It stops, because a PE waits for data that never comes. It finishes with wrong values. Or it is correct and slower than you expect. In each case the test tells you only that the result differs. This topic shows how to make a program report, PE by PE, how far it got, what it received and where its cycles went. It ships a correct program that does this, and three faults for you to apply and find.

What you will be able to do

• Read each PE's progress marker and received count after a run, and find the first link that did not deliver.
• Read from the build log which physical color Paint gave each socket.
• Find an out-of-bounds array write with the compiler option fsanitize=bounds.
• Program a PE's two performance counters, and use them with the phase times to find which PE limits a run.

The program

Three PEs in a row compute a histogram and its running sum:

     x=0             x=1               x=2
  +-------+  ab   +--------+   bc   +-------+
  |  src  | ----> |  hist  | -----> |  dst  |
  +-------+       +--------+        +-------+
  N samples       NB bins           running sum of the bins

• src sends N samples. Each is an integer from 0 to 2·NB − 1. ref.py makes them, with a fixed seed, and the Makefile loads them into src.a with miset.
• hist receives the samples into a, counts each one into bin a[i] >> 1 of h, so each bin is two values wide, and sends the NB counts on.
• dst receives the counts into r and stores their running sum in c. The last element of c is N.

The test compares hist.h and dst.c with the histogram that check.py computes from the same samples. Before it compares, it prints one line per PE.

The code

Progress markers and counters: perf.w

Every kernel imports perf.w (lesson 2's import):

xp tsc[3] address(0x7b30);
xp counter[8] address(0x7b20);
xp counter_control[1] address(0x7b34);
xp counter_config[4] address(0x7b38);
xp step[1];
xp stamp[n=6];
xp count[n=2];

function mark(xp k) {
    step[0] = k;
    stamp[k] = tsc[0];
}

function counters_start() {
    counter_config[0] = 1 | (1 << 14);
    counter_config[1] = 0;
    counter_config[2] = 17 | (31 << 5);
    counter_config[3] = 0;
    counter[0] = 0;
    counter[4] = 0;
    counter_control[0] = 7;
    mark(0);
}

function counters_stop() {
    count[0] = counter[0];
    count[1] = counter[4];
}

A function without -> type returns nothing. mark(k) records that the PE has reached phase k. It writes k into step and the low 16 bits of the timestamp counter (lesson 3) into stamp[k]. After the run, step holds the last phase the PE reached, and the difference of two stamps is the length of a phase in cycles.

The markers are one-element arrays because miget reads memory. The compiler may keep a global scalar such as xp step; in a register. It then has no entry in bench.map, and miget cannot read it: a version of this program that declared xp step; had no step in its map.

Each PE has two performance counters besides the timestamp counter. They live at fixed addresses, like the timestamp counter, and the address() arrays above map them:

Array	Address	What it holds
counter[0..3]	0x7b20	counter 0, 48 bits in three words, low word first; the fourth word is always 0
counter[4..7]	0x7b24	counter 1, the same layout
counter_control[0]	0x7b34	bit 0 enables counter 0, bit 1 counter 1, bit 2 the timestamp counter
counter_config[0..1]	0x7b38	what counter 0 counts: a 32-bit word, low half first
counter_config[2..3]	0x7b3a	what counter 1 counts

In a configuration word, bits 4 to 0 select an event type and bits 20 to 5 refine it. counters_start() selects two events:

• Counter 0, 1 | (1 << 14). Event type 1 counts cycles by how many operations the PE's core executed in them. Bit 14 selects the cycles in which it executed none, because it was idle or its pipeline was stalled. This is the idle column below.
• Counter 1, 17 | (31 << 5). Event type 17 counts cycles in which a color's buffer in this PE's router held a wavelet it could not pass on, toward a neighbour or into this PE's core. Bits 9 to 5 select the color, and 31 selects all colors. This is the stalled column.

counters_start() clears the low words of both counters, then writes 7 to the control register, which starts both counters and the timestamp counter. counters_stop() copies the low words into count, an ordinary array, where the test can read them. Read the low word of a counter first: reading a higher word first returns undefined data. A 16-bit count wraps after 65,536, which the runs here stay far below. The counters start with the timestamp counter, at the write of 7, and stop being read a few instructions after the last stamp, so they cover a few cycles more than the cycles column. Compare the two only roughly.

The kernels

hist.w shows the pattern every kernel follows:

import perf;

xp param N;
xp param NB;
socket rx;
socket tx;
xp a[n=N];
xp h[n=NB];

main {
    let i in [0, N);
    let b in [0, NB);
    counters_start();
    ∀i a[i] = -1;
    mark(1);
    ∀i a[i] <- rx[];
    mark(2);
    ∀i h[a[i] >> 1] += 1;
    mark(3);
    ∀b tx[] <- h[b];
    mark(4);
    counters_stop();
}

• ∀i a[i] = -1; fills the receive buffer with a value no sample can take. After a run, the number of entries that are no longer −1 is the number of samples that arrived. dst fills r the same way.
• mark(1) to mark(4) divide the work into phases: receiving, binning, sending and finished. src has the phases sending and finished, and dst receiving, summing and finished.
• The table's first phase, start, runs from mark(0), the last step of counters_start(), to mark(1). In hist and dst it fills the receive buffer with −1.
• counters_stop() runs only if the PE gets to the end. A PE that stops early leaves its markers, but no counts.

The layout

bench.paint is lesson 4's pipeline with three PEs:

let ab = color()
let bc = color()

let src = tile()
src : code('src [tx:ab N:N])
src : paint(ab [C>R])
src : name('src)

let hist = tile()
hist : code('hist [rx:ab tx:bc N:N NB:NB])
hist : paint(ab [L>C])
hist : paint(bc [C>R])
hist : name('hist)

let dst = tile()
dst : code('dst [rx:bc NB:NB])
dst : paint(bc [L>C])
dst : name('dst)

hstack(src hist dst)

The test

The Makefile reads every symbol the check needs from the final memory, one file per symbol, and runs check.py on them:

SYMBOLS=src.step hist.step dst.step src.stamp hist.stamp dst.stamp src.count hist.count dst.count hist.a hist.h dst.r dst.c

test/$(MODE): bench-$(MODE).core bench.map
	for s in $(SYMBOLS); do miget image=$< map=bench.map symbol=$$s data=$$s.bin || exit 1; done
	python3 ../check.py $(N) $(NB)

check.py prints a table. step and phase are the last marker. received counts the entries of hist.a and dst.r that are no longer −1. cycles, idle and stalled are shown only for a PE that finished: cycles is from its first stamp to its last, and the other two are the counters. The last column gives the cycles of each phase the PE completed.

The rows are tutorial (N=64, NB=8) and n256 (N=256, NB=16). The cycle cap is 8000 cycles.

Run it

In your copy of the tutorial (see Lesson 1):

cd tutorial/ext-layouts-debugging/debugging
make TEST=tutorial
(cd test-tutorial && python3 ../check.py 64 8)

The last line runs check.py again in the row's directory, where the Makefile left the files it read. This Makefile names bench-$(MODE).core in its test rule, so make also keeps the simulated memory, test-tutorial/bench-sim.core, for your own miget commands; lesson 4's Makefile does not.

make prints a line ending in PASS tutorial [ N=64 NB=8 ARCH=sdr ]. The table:

PE    step  phase      received  cycles   idle stalled  cycles per phase
src      2  finished                 40     21       0  start 3, sending 37
hist     4  finished      64/64     837    348       0  start 13, receiving 42, binning 778, sending 4
dst      3  finished        8/8     890    846       0  start 6, receiving 850, summing 34
hist.h matches
dst.c matches

make TEST=n256 runs the second row; check.py then takes 256 16.

Reading a profile

The table answers "which PE limits this run":

• hist is busy: its core executes something in about 490 of its 837 cycles, and binning takes 778 of them, about 12 cycles per sample. Each sample's bin address comes from the data, so the compiler builds a loop that reads a sample, reads its bin, and writes the bin back, one sample at a time. The listing in test-tutorial/hist_artefacts/ shows the loop (lesson 3 shows how to read a listing). Part of hist's idle count is that loop's pipeline stalls, not waiting for data: counter 0 counts both.
• dst is idle for 846 of its 890 cycles. It waits 850 cycles in receiving, for counts that come only after hist has binned every sample.
• src finishes after 40 cycles. hist receives the samples as fast as src sends them, so src never waits for room.
• stalled is 0 everywhere: no wavelet sat in a router. At N=256, src and hist show 8 and 9 stalled cycles, and binning grows to 3082 cycles for 256 samples.

So hist's binning loop is the work to speed up. The phase times and the order of the streams show it: dst's long receiving phase waits for hist's binning, and nothing waits for src. Counter 0 alone does not identify such work, because it counts pipeline stalls together with waiting. When a PE consumes its input more slowly than it arrives, the buffers in front of it fill, and the routers on the way to it, its own included, show stalled cycles.

Find three faults

faults/ holds three changed files. Each makes one mistake that is easy to make and that the build does not report. Each replaces one file of the topic, so save that file first and put it back afterwards. For fault 1, in tutorial/ext-layouts-debugging/debugging:

cp bench.paint bench.paint.orig
cp faults/1-wrong-color/bench.paint .
make clean
make TEST=tutorial
(cd test-tutorial && python3 ../check.py 64 8)
cp bench.paint.orig bench.paint

Faults 2 and 3 replace hist.w: save it with cp hist.w hist.w.orig, apply faults/2-off-by-one/hist.w or faults/3-out-of-bounds/hist.w the same way, and copy hist.w.orig back when you are done. make clean comes before every run after a change, because make does not rebuild an existing test-tutorial/.

Each fault makes make print FAIL tutorial. A run that stops runs to the cycle cap, so a faulty run takes longer than a correct one. Work out each fault from the table before you read the answers below. The method:

1. Did every PE reach its last phase? A PE that did not is waiting for something.
2. Start at src and walk along the data's path. The first PE that did not finish, and its received count, tell you which link failed and how many values crossed it.
3. Compare the count with the count the sender should send. None means a route or a color; all but a few means a count; all of them means the receiver itself.
4. Check the colors of that link: the build log lists them (fault 1).
5. Only then read the sender's and the receiver's code.

Fault 1

PE    step  phase      received  cycles   idle stalled  cycles per phase
src      2  finished                 40     21       0  start 3, sending 37
hist     4  finished      64/64     837    348       0  start 13, receiving 42, binning 778, sending 4
dst      1  receiving       0/8       -      -       -  start 6
hist.h matches
dst.c expected [6, 12, 20, 30, 39, 44, 56, 64]
dst.c got      [0, 0, 0, 0, 0, 0, 0, 0]

hist sent all its counts and finished; dst received none. Where did the eight counts go?

Fault 2

PE    step  phase      received  cycles   idle stalled  cycles per phase
src      2  finished                 40     21       0  start 3, sending 37
hist     4  finished      64/64     837    348       0  start 13, receiving 42, binning 778, sending 4
dst      1  receiving       7/8       -      -       -  start 6
hist.h matches
dst.c expected [6, 12, 20, 30, 39, 44, 56, 64]
dst.c got      [0, 0, 0, 0, 0, 0, 0, 0]

dst received seven of its eight counts.

Fault 3

PE    step  phase      received  cycles   idle stalled  cycles per phase
src      2  finished                 40     21       0  start 3, sending 37
hist     4  finished      64/64     837    348       0  start 13, receiving 42, binning 778, sending 4
dst      3  finished        8/8     890    846       0  start 6, receiving 850, summing 34
hist.h expected [6, 6, 8, 10, 9, 5, 12, 8]
hist.h got      [4, 2, 3, 3, 6, 2, 1, 9]
dst.c expected [6, 12, 20, 30, 39, 44, 56, 64]
dst.c got      [4, 6, 9, 12, 18, 20, 21, 30]

Every PE finished, but the bins add up to 30, not 64. Where did 34 samples go? Run make clean, then build it again with the bounds check:

make TEST=tutorial PAINTOPTS='toolflag w fsanitize=bounds'

PAINTOPTS is added to Paint's command line by the Makefile. toolflag w passes the option to the compiler for every .w kernel, next to the options the build passes itself.

Checking array bounds

The compiler checks array indices in one case only: it rejects a ∑ whose subscripts read outside an operand array. Every other out-of-bounds access compiles without a message, a constant index too: with xp a[n=4]; xp b[n=4];, a[7] = 9; writes b[3] (see Array Bounds Verification). An out-of-bounds write is not an error: it writes the memory after the array, whatever that holds. fsanitize=bounds adds a check before every array access the compiler cannot prove in bounds. A failed check stops the PE at a breakpoint instruction, followed by a jump to itself, so the PE never runs past it. In the listing it looks like this:

handler main_bb5  {
	brk ;
	jmp main_bb5;

}

The check makes code slower. With it, the correct program's binning takes 2316 cycles instead of 778 at N=64. At N=256 binning no longer fits in the 8000-cycle cap: the run stops while hist is still binning, which looks like a fault. Check with the tutorial row, or raise the cap for one run:

make clean
make TEST=n256 PAINTOPTS='toolflag w fsanitize=bounds' CYCLES=20000

The Makefile sets the cap with CYCLES ?= 8000, so CYCLES= on the command line or in a row of test.rc replaces it. The check does not cover accesses inside parallel arms.

Pitfalls

• A sender that finished proves nothing about delivery. Its wavelets can sit in queues and router buffers. In fault 1, hist finished while all eight counts sat in buffers on the way to dst.
• A run that reaches the cycle cap looks like a stopped run. Before you look for a deadlock, check whether the slowest PE was still making progress: its marker, its partial results.
• Paint does not check that a sender and a receiver use the same color. The build log does show it: see the answer to fault 1.
• Without the bounds check, an out-of-bounds write changes whatever follows the array. Here it happened to be unused memory; elsewhere it is another variable or the program's code.
• Keep markers in memory. Use one-element arrays, not scalar globals.
• Copy counters to memory before the PE stops. counters_stop() must run; a PE that waits forever never reports its counts.

Other tools

The debugging guide describes tools that read a log of the whole simulation rather than the final memory: a debug build with GOAL=debugx, the Portrait viewer, pipeline traces, wavelet landing records with debug=landing, and meminsp, which replays memory writes cycle by cycle. They depend on what the simulator records, so they are not shown here. The markers and counters of this topic need only the final memory, and the counters are part of every PE.

Exercise

Make counter 0 count the wavelets this PE's router delivers to its own core: in perf.w, set counter_config[0] = 15 | (1 << 9);. Event type 15 counts the wavelets the router sends out of the ports that bits 9 to 5 select, and bit 9 is the port into the core. Run the tutorial row again. The idle column now holds that count: why does hist, which received 64 samples, show 32, and dst 4?

Answers

Fault 1, wrong color. faults/1-wrong-color/bench.paint binds dst's rx to ab, the color src sends on, instead of bc:

dst : code('dst [rx:ab NB:NB])

Paint accepts it without a message. dst's input queue now takes ab, which has no route on its PE, and the counts arriving on bc have no queue to enter. The build log shows the physical color each socket got. With verbose, which the Makefile passes, it lists one compiler command per kernel:

grep 'ucid=[1-9]' test-tutorial/make-log | grep -o 'set=[rt]x={.color=[0-9]*\|source=[^ ]*'

Each kernel's colors come before its source= line. In fault 1 the command prints:

set=tx={.color=23
source=../src.w
set=rx={.color=23
set=tx={.color=22
source=../hist.w
set=rx={.color=23
source=../dst.w

hist sends on physical color 22, but dst receives on 23, src's color. In the correct build dst's rx is 22. Each link must have one color at both ends, unless a color swap changes it on the way (lesson 8).

Fault 2, count off by one. faults/2-off-by-one/hist.w declares the send range as let b in [0, NB - 1);. A range is half-open, so it ends before NB − 1, and hist sends seven counts. A C loop for (b = 0; b <= NB - 1; b++) becomes [0, NB). dst waits for the eighth count forever. A received count that is short by one points at a loop bound on either side.

Fault 3, out-of-bounds write. faults/3-out-of-bounds/hist.w drops the bin width:

    ∀i h[a[i]] += 1;

Samples 8 to 15 index past the eight bins of h, and their counts go to the memory after it. With fsanitize=bounds, hist stops in binning with every bin still 0:

PE    step  phase      received  cycles   idle stalled  cycles per phase
src      2  finished                 40     21       0  start 3, sending 37
hist     2  binning       64/64       -      -       -  start 13, receiving 35
dst      1  receiving       0/8       -      -       -  start 6

No bin was counted, so the check failed on the first sample. miget image=test-tutorial/bench-sim.core map=test-tutorial/bench.map symbol=hist.a decimal prints the samples; the first is 15, and bin 15 does not exist.

Exercise. Two 16-bit values travel in one wavelet when the output queue can pack them (lesson 4), so 64 samples arrive as 32 wavelets and 8 counts as 4.

Next

This is the last extension topic. Back to the tutorial index.