Part 6. Practice · lesson 38 of 42

38. Measuring¶

A time of a command means something only when you know whose clock measured it and how many runs it comes from. This lesson relies on lesson 5, Commands, lesson 9, Many commands and lesson 19, Circular buffers.

Why two clocks¶

Every number in this tutorial so far that ended in "microseconds" was the card's. The card starts a clock when a command begins and stops it when the cores have reported, and the event carries the result: event.microseconds. Python has a clock of its own, and it sees more: the trip from Python to the card, the trip back, and the work of submit and wait. The two numbers answer two questions. The card's says how long the cores worked. The host's says how long your program waited. A kernel that you tune is judged by the first; a program that you tune is judged by the second.

One run of a command is also a poor measure. The first command after a load can be slow, and any run can be disturbed by something else. A program that measures sends the command many times, and reads the middle value, the median: half the runs were faster, half slower. The smallest and the largest show how much the runs differ.

The general form¶

import statistics
import time

started = time.perf_counter()
handle = run.submit(...)
event = run.wait(handle, timeout=SECONDS)
host_microseconds = (time.perf_counter() - started) * 1e6
card_microseconds = event.microseconds

middle = statistics.median(LIST)

time.perf_counter() is Python's clock for timing. It returns seconds, as a decimal number; only the difference of two readings means something.
(... - started) * 1e6 turns seconds into microseconds: 1e6 is 1,000,000.
event.microseconds is the card's clock for the same command.
LIST is the list of times of all the runs. statistics.median returns the middle one. min and max give the smallest and the largest.

One line at a time¶

card = []
host = []
for _ in range(REPEATS):
    started = time.perf_counter()
    handle = run.submit("copy", group=(0, 1), args=arguments)
    event = run.wait(handle, timeout=10.0)
    host.append((time.perf_counter() - started) * 1e6)
    card.append(event.microseconds)

Twenty copies of the 64 tiles of lesson 19, Circular buffers, one command after the other. For each run the program reads Python's clock before submit and after wait, and the card's clock from the event, and keeps both in lists.

print(f"{REPEATS} copies of {TILES} tiles")
print(
    f"card clock: first {card[0]:.1f}, middle {statistics.median(card):.1f}, "
    f"smallest {min(card):.1f}, largest {max(card):.1f} microseconds"
)
print(
    f"host clock: first {host[0]:.1f}, middle {statistics.median(host):.1f}, "
    f"smallest {min(host):.1f}, largest {max(host):.1f} microseconds"
)

For each clock, the first run, the middle, the smallest and the largest.

The card's clock covers only the middle step; the host's covers all five.

The whole program¶

measuring.py

"""Measuring: how long a command takes, by the card's clock and by the host's."""

import statistics
import time
from pathlib import Path

import numpy as np

import komorebi as km

HERE = Path(__file__).resolve().parent
TILES = 64
REPEATS = 20

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(
        "measuring",
        kernels=HERE / "kernels",
        handlers=HERE / "kernels" / "handlers.h",
        buffers=[
            km.Buffer(index=0, format="uint32", page_bytes=source.page_bytes, pages=8)
        ],
        compile_args={
            "reader": source.accessor_args(),
            "writer": destination.accessor_args(),
        },
    )
    run = session.load(program)
    arguments = [source.address, 0, destination.address, 0, TILES]

    card = []
    host = []
    for _ in range(REPEATS):
        started = time.perf_counter()
        handle = run.submit("copy", group=(0, 1), args=arguments)
        event = run.wait(handle, timeout=10.0)
        host.append((time.perf_counter() - started) * 1e6)
        card.append(event.microseconds)
    run.stop()

    (source_pages,) = session.read(source)
    (destination_pages,) = session.read(destination)
    assert (destination_pages == source_pages).all()

print(f"{REPEATS} copies of {TILES} tiles")
print(
    f"card clock: first {card[0]:.1f}, middle {statistics.median(card):.1f}, "
    f"smallest {min(card):.1f}, largest {max(card):.1f} microseconds"
)
print(
    f"host clock: first {host[0]:.1f}, middle {statistics.median(host):.1f}, "
    f"smallest {min(host):.1f}, largest {max(host):.1f} microseconds"
)

The kernels are those of lesson 19, Circular buffers, with 8 pages in the buffer. Run it from the folder tutorial/38_measuring:

python measuring.py

20 copies of 64 tiles
card clock: first 32.8, middle 32.2, smallest 32.1, largest 32.8 microseconds
host clock: first 594.8, middle 161.1, smallest 159.1, largest 594.8 microseconds

Read the two lines.

On the card's clock the 20 runs agree to within a microsecond: 32.1 to 32.8. The first is no different from the others. The copy is steady work, and the card's clock sees nothing else.
On the host's clock the middle run takes about 161 microseconds, five times the card's
The 130 or so microseconds more are the trips and the calls of Python. They are there for every command, however short it is.
The first run on the host's clock took 595 microseconds, nearly four times the middle. Run it again and the first is again the slowest, by about as much. A program that times one run, and happens to time the first, reports a number that is not the cost of a command.

When commands do not depend on each other, lesson 9, Many commands hides the trips: the card works while Python sends the next one.

Common mistakes¶

Timing one run. Time many, and give the middle, with the smallest and largest.
Comparing a card time with a host time. Say which clock a number is from.
Timing a program that includes load. Loading takes about a second (lesson 5, Commands), and it swamps the commands that follow. Start the clock after load.
Taking the first run as typical. On the host's clock it was nearly four times the middle.

Next: lesson 39, Finding a bug is about the other thing a command can do: not finish.