Is this page helpful?

Statistics#

KvikIO can report what a run did: how many operations, how many bytes, how long it was busy, and which backend carried the work.

A monitor accumulates for as long as it exists, and get() reads the totals so far.

import cupy

import kvikio


def main(path):
    # Statistics are off until a monitor exists. This one counts every operation below.
    monitor = kvikio.SummaryMonitor()

    a = cupy.arange(100)
    f = kvikio.CuFile(path, "w")
    # Write whole array to file
    f.write(a)
    f.close()

    b = cupy.empty_like(a)
    f = kvikio.CuFile(path, "r")
    # Read whole array from file
    f.read(b)
    assert all(a == b)

    # Use contexmanager
    c = cupy.empty_like(a)
    with kvikio.CuFile(path, "r") as f:
        f.read(c)
    assert all(a == c)

    # Non-blocking read
    d = cupy.empty_like(a)
    with kvikio.CuFile(path, "r") as f:
        future1 = f.pread(d[:50])
        future2 = f.pread(d[50:], file_offset=d[:50].nbytes)
        future1.get()  # Wait for first read
        future2.get()  # Wait for second read
    assert all(a == d)

    # Five calls, one write and four reads, however many reads KvikIO issued underneath.
    # The two `pread()`s above are one operation each, not one per thread-pool task.
    summary = monitor.get()
    assert summary.num_ops == 5
    print(summary)
    print(f"{summary.bytes_transferred} bytes in {summary.num_ops} operations")


if __name__ == "__main__":
    main("/tmp/kvikio-hello-world-file")

Printing a summary, or calling report(), gives a report meant to be read by a person:

KvikIO I/O summary (LOGICAL)
  wall time            238.22 ms
  busy time            5.66 ms (2.38 % of the wall time)
  busy bandwidth       565.50 kB/s
  operations           5 (4 read, 1 write)
  mean duration        1.13 ms
  bytes                3.12 KiB of 3.12 KiB requested (2.34 KiB read, 800 B written)
  errors               0
  backend POSIX        3.12 KiB in 5 ops, 5.66 ms, 565.50 kB/s

A report holds what the run used, so a backend it never reached and a subsystem it never touched are left out. To print every row whatever the run did:

print(summary.report(all_rows=True))

Busy time and bandwidth#

Busy time is the union of the operations’ spans, so overlapping work counts once and the gaps between calls count as idle.

Busy bandwidth divides the bytes by that rather than by the wall time. A program that reads for 10 ms and then computes for 90 ms is doing I/O at its storage’s speed for a tenth of its life, and dividing by the wall time would report it as ten times slower than it is. Multiply by busy_fraction to recover the whole-span rate.

Calls or transfers#

A monitor counts one operation per user-facing call by default. A call that KvikIO splits across its thread pool is one row, however many reads it issued underneath, and its span runs from submission to completion. Under load most of that span is the wait for a worker rather than the transfer.

Passing ObservationKind.PHYSICAL counts one operation per transfer instead: one thread-pool task locally, one HTTP range request remotely. Its span starts when a worker picks the task up, or when the request goes on the wire.

calls = kvikio.SummaryMonitor(kvikio.ObservationKind.LOGICAL)
transfers = kvikio.SummaryMonitor(kvikio.ObservationKind.PHYSICAL)

Summary.kind says which a summary is over, and the report leads with it, so two summaries in a log are never confused for one another.

Both see the same bytes and the same errors. What differs is the count and the durations, so eight concurrent reads over a two-thread pool look like this:

                         calls      transfers
num_ops                      8             64
busy (ms)               14.657         14.581
total_duration (ms)     79.383         28.941

busy, the union of the spans, is the same because the calls and the transfers are in flight over the same stretch of wall clock. total_duration, the sum of the spans, is not. The 50 ms between the two is what the calls spent queueing.

Which to pick follows from the question. Use the calls for how many I/Os a program issued and how long each took as it experienced them. Use the transfers for how well the device or the link was kept busy, and for bandwidth over time, since a call’s bytes would otherwise be charged to the moment it returned rather than to the moments they moved.

Running one of each, as above, gives two summaries over the same span, and the counters are the same in both. They belong to the process rather than to either kind of observation, so the bytes and the operations of the two summaries describe different things and the counters describe the same thing twice. Add the summaries and the connection costs are counted twice over.

Two things to know. A physical monitor pays its per-observation cost once per task rather than once per call, so watching a run of large split reads costs proportionally more. And the two remote backends describe a retried request differently. MULTI_POLL reports one transfer per attempt, so the backoff between them belongs to neither. EASY_THREADPOOL retries inside the call that the transfer is measured around, so the attempts and the waits between them are one transfer, and that transfer’s duration includes time when nothing was on the wire.

Getting a summary out of the process#

to_json() gives the same content for anything that would rather parse it, with the timestamps against the wall clock so another program can line the summary up with its own log.

serialize() and deserialize() move a summary between processes. They are exact, so one that has been through a pipe is still a valid previous for since(), and they are what pickling uses.

raw = summary.serialize()
assert kvikio.Summary.deserialize(raw) == summary

The bytes are not a wire format. They are a copy of the C++ struct, readable only by the same architecture and the same build of KvikIO, and anything else is refused rather than misread.

Summaries are not additive. Most fields could be added across processes, but busy time cannot, since two processes are genuinely busy at the same moment.