Part 6. Practice · lesson 39 of 42

39. Finding a bug¶

When a command does not finish, the card's report says which kernel of which core was waiting, and for what; with that line you can find the missing step in a kernel. This lesson relies on lesson 10, When it goes wrong, lesson 19, Circular buffers and lesson 18, The three kernels.

Why a report¶

A kernel that waits for something that never comes does not fail with a message of its own: it waits. Looking at the code for the mistake is slow, because a copy is a loop of five calls in two kernels, and the mistake is one missing call. The card helps. When the deadline passes (lesson 10, When it goes wrong), it stops the cores, and each kernel that had not finished says where it was. That report ends in the message of CommandTimeout.

The general form¶

The message has this shape:

command N timed out: slot S, sequence Q, group first F count C; not reported:
    core X reader gave up (WHY) in WHERE writer gave up (WHY) in WHERE

command N is the handle of the command that did not finish, group first F count C the cores it was for (lesson 4, Hello, core). slot S and sequence Q are the card's own numbers for it, and you do not need them.
not reported: core X names a core of the group that had not reported when the deadline passed. Cores of the group that had reported are not named.
reader gave up and writer gave up say, for each of the core's two data-moving kernels, where it was and why it gave up. If a kernel is not named, it was not stuck.
WHY is the reason. stop is the one in this lesson: the card told the kernel to stop at the deadline, and the kernel obeyed.
WHERE is the step the kernel was in. Three matter here:
- next: waiting for its next command. The kernel had finished this command.
- data: waiting on a circular buffer: writer.cpp for a tile to be there (wait_front), reader.cpp for room to put one (reserve).
- cdone: writer.cpp, at the end of its work, waiting for the other kernels' work to end.

Other steps exist, and the message names them in the same way.

Two bugs, one at a time¶

The kernels of this lesson are the copy of lesson 19, Circular buffers, with two switches. Argument a5 of the command turns a bug on. In reader.cpp:

reader.run([&](const km_command_t& command) {
    if (km::handler(command) == kHandlerCopy) {
        const uint32_t source_address = command.a0;
        const uint32_t first_tile = command.a1;
        const uint32_t tile_count = command.a4;
        const bool forget_push = command.a5 == kBugForgetPush;
        const auto source = TensorAccessor(source_arguments, source_address);
        for (uint32_t index = 0; index < tile_count; index++) {
            if (!reader.reserve(kTileBuffer, 1)) {
                return;
            }
            noc_async_read_page(
                first_tile + index, source, get_write_ptr(kTileBuffer)
            );
            noc_async_read_barrier();
            if (!forget_push) {
                cb_push_back(kTileBuffer, 1);
            }
        }
    }
});

With a5 equal to 1 reader.cpp never calls cb_push_back: it reads each tile into the buffer, and never says that the tile is there. In writer.cpp, a5 equal to 2 skips cb_pop_front: writer.cpp copies each tile out, and never says that the page is free again.

try:
    event = run.wait(handle, timeout=10.0)
except km.CommandTimeout as error:
    print(f"with bug {bug}: {error}")
    continue

The program runs the copy three times, with bug 1, bug 2 and no bug. The deadline of each is one second (lesson 10, When it goes wrong). When the card gives up, the program prints the message and goes on to the next load.

Read what the card said about bug 1:

not reported: core 0 reader gave up (stop) in next writer gave up (stop) in data

reader.cpp was in next: it had run its whole loop and was waiting for another command. The writer was in data: it was waiting for a tile to be there. So the tile was read but never announced. The place to look is where reader.cpp hands a tile on: the cb_push_back.

Bug 2:

not reported: core 0 reader gave up (stop) in data writer gave up (stop) in cdone

Now reader.cpp was the one in data: it was waiting for room to put a tile. writer.cpp was in cdone: it had written all its tiles and was waiting for reader.cpp to end. reader.cpp waited for room that writer.cpp should have made, so look at where writer.cpp is done with a tile: the cb_pop_front.

From the message to the line of code.

The whole program¶

finding_a_bug.pykernels/handlers.hkernels/reader.cppkernels/writer.cpp

"""Finding a bug: two copies that go wrong, and what the card says about each."""

from pathlib import Path

import numpy as np

import komorebi as km

HERE = Path(__file__).resolve().parent
TILES = 8

with km.Session() as session:
    numbers = np.arange(TILES * 32 * 32, dtype=np.uint32).reshape(TILES * 32, 32)
    source = session.tensor(numbers, "uint32", "tile")
    destination = session.tensor(np.zeros_like(numbers), "uint32", "tile")
    program = km.Program(
        "finding_a_bug",
        kernels=HERE / "kernels",
        handlers=HERE / "kernels" / "handlers.h",
        buffers=[
            km.Buffer(index=0, format="uint32", page_bytes=source.page_bytes, pages=2)
        ],
        compile_args={
            "reader": source.accessor_args(),
            "writer": destination.accessor_args(),
        },
    )
    for bug in (1, 2, 0):
        run = session.load(program, deadline=1.0)
        arguments = [source.address, 0, destination.address, 0, TILES, bug]
        handle = run.submit("copy", group=(0, 1), args=arguments)
        try:
            event = run.wait(handle, timeout=10.0)
        except km.CommandTimeout as error:
            print(f"with bug {bug}: {error}")
            continue
        run.stop()
        print(f"with bug {bug}: the command is {event.kind}")
        (source_pages,) = session.read(source)
        (destination_pages,) = session.read(destination)
        assert (destination_pages == source_pages).all()

// What the kernels and Python agree on: the handler, and the number of the buffer in L1
// in which the tile waits between the reader and the writer.
#pragma once

#include <stdint.h>

constexpr uint32_t kHandlerCopy = 1;
constexpr uint32_t kTileBuffer = 0;

// The value of a5 that switches a bug on: the reader leaves out cb_push_back, or the
// writer leaves out cb_pop_front. Any other value: no bug.
constexpr uint32_t kBugForgetPush = 1;
constexpr uint32_t kBugForgetPop = 2;

// The reader kernel: copies tile_count tiles from DRAM through the buffer in L1. When
// the command's a5 is 1 it leaves out cb_push_back, on purpose: a bug to look for.
#include "api/dataflow/dataflow_api.h"
#include "komorebi/device/km_worker.hpp"
#include "handlers.h"

void kernel_main() {
    constexpr auto source_arguments = TensorAccessorArgs<0>();
    km::Reader reader;
    reader.run([&](const km_command_t& command) {
        if (km::handler(command) == kHandlerCopy) {
            const uint32_t source_address = command.a0;
            const uint32_t first_tile = command.a1;
            const uint32_t tile_count = command.a4;
            const bool forget_push = command.a5 == kBugForgetPush;
            const auto source = TensorAccessor(source_arguments, source_address);
            for (uint32_t index = 0; index < tile_count; index++) {
                if (!reader.reserve(kTileBuffer, 1)) {
                    return;
                }
                noc_async_read_page(
                    first_tile + index, source, get_write_ptr(kTileBuffer)
                );
                noc_async_read_barrier();
                if (!forget_push) {
                    cb_push_back(kTileBuffer, 1);
                }
            }
        }
    });
}

// The writer kernel: writes the tiles to another tensor. When the command's a5 is 2 it
// leaves out cb_pop_front, on purpose: another bug to look for.
#include "api/dataflow/dataflow_api.h"
#include "komorebi/device/km_worker.hpp"
#include "handlers.h"

void kernel_main() {
    constexpr auto destination_arguments = TensorAccessorArgs<0>();
    km::Writer writer;
    writer.run([&](const km_command_t& command) {
        if (km::handler(command) == kHandlerCopy) {
            const uint32_t destination_address = command.a2;
            const uint32_t first_tile = command.a3;
            const uint32_t tile_count = command.a4;
            const bool forget_pop = command.a5 == kBugForgetPop;
            const auto destination = (
                TensorAccessor(destination_arguments, destination_address)
            );
            for (uint32_t index = 0; index < tile_count; index++) {
                if (!writer.wait_front(kTileBuffer, 1)) {
                    return false;
                }
                noc_async_write_page(
                    first_tile + index, destination, get_read_ptr(kTileBuffer)
                );
                noc_async_write_barrier();
                if (!forget_pop) {
                    cb_pop_front(kTileBuffer, 1);
                }
            }
        }
        return true;
    });
}

The compute file is the empty one. Run it from the folder tutorial/39_finding_a_bug:

python finding_a_bug.py

with bug 1: command 1 timed out: slot 0, sequence 1, group first 0 count 1; not reported: core 0 reader gave up (stop) in next writer gave up (stop) in data
with bug 2: command 1 timed out: slot 0, sequence 1, group first 0 count 1; not reported: core 0 reader gave up (stop) in data writer gave up (stop) in cdone
with bug 0: the command is done

The two bugs were found from the messages alone, and the run without a bug copied all eight tiles and the program's check passed.

Common mistakes¶

Reading stop as the cause. It says only that the card ended the wait at the deadline. The cause is where the kernel was: the WHERE.
Looking only at the kernel that is in data. In bug 1 it was writer.cpp that was in data, and the mistake was in reader.cpp. The one that waits is the victim; the one that did not send what it should is the cause.
Sending the next command after a CommandTimeout. The run is over (lesson 10, When it goes wrong): load again.
A deadline too short for honest work. The card then reports a kernel that was working. Check the time of the command with lesson 38, Measuring before you suspect a bug.

Next: lesson 40, A whole program puts the parts of the tutorial together in one program.