Skip to content

Add an I/O observation facility - #1033

Merged
rapids-bot[bot] merged 14 commits into
rapidsai:mainfrom
madsbk:logical-observations
Aug 18, 2026
Merged

Add an I/O observation facility#1033
rapids-bot[bot] merged 14 commits into
rapidsai:mainfrom
madsbk:logical-observations

Conversation

@madsbk

@madsbk madsbk commented Aug 14, 2026

Copy link
Copy Markdown
Member

This PR introduces a hook into monitoring KvikIO operations, with the goal of building statistics, Quent timelines, and whatever else wants to know what the I/O layer is doing. This PR is the base. A follow-up introduces a concrete Monitor that makes statistics easy to get.

The hook reports whole KvikIO operations (the logical level) so a pread() is a single observation however many reads the thread pool issued underneath. Physical operations can be added along the same path later, which could be the basis of #1016.

Each call produces a kvikio::Observation: its span, the offset and size etc. To receive them, derive from kvikio::Monitor and register it. A monitor is told when an operation starts as well as when it finishes.

// Example of a Monitor that tracks how many KvikIO operations are in flight at any moment.
class QueueDepth : public kvikio::Monitor {
  void on_start(kvikio::Observation const&) noexcept override { ++_in_flight; }
  void on_finish(kvikio::Observation const&) noexcept override { --_in_flight; }
  std::atomic<int> _in_flight{0};
};

QueueDepth gauge;
auto id = kvikio::register_monitor(&gauge);

Overhead

Measured on my local workstation:

  • ~3 ns per call when nobody is observing, which is a gate check and a branch.
  • ~60 ns per call when somebody is, or 1 % of a 64 KiB pread(), and nothing detectable at a megabyte.

Confirmed against a real workload: cudf-polars PDS-H query 1 at scale 10, with and without a monitor attached, showed no difference outside noise.

What is not observed

The cuFile asynchronous API on a GDS system, and the batch API, complete without KvikIO seeing it, so they emit nothing. Handling those needs a stream-completion callback, which is future work.

Follow-up: statistics

The next PR adds kvikio::statistics::SummaryMonitor, which is a Monitor and nothing more:

monitor = kvikio.SummaryMonitor()   # statistics are now on
...
print(monitor.get())
KvikIO I/O summary
  wall time            1.876 s
  busy time            366.592 ms (19.54 % of the wall time)
  busy bandwidth       8.95 GB/s
  operations           7970
  bytes requested      3.06 GiB
  bytes transferred    3.06 GiB
  errors               0

Those are real numbers, from a cudf-polars run, and they show a very useful busy bandwidth. 8.95 GB/s is the rate while KvikIO actually had work in flight, where dividing the same bytes by the wall clock would have said 1.75 GB/s and described the query rather than the storage.

A TimelineMonitor, for when things happened rather than how much, is planned after that.

@madsbk madsbk self-assigned this Aug 14, 2026
@madsbk madsbk added improvement Improves an existing functionality non-breaking Introduces a non-breaking change labels Aug 14, 2026
@madsbk
madsbk force-pushed the logical-observations branch 3 times, most recently from d42da15 to 0dece5b Compare August 14, 2026 10:50
`nbytes()` caches the file size and `write()` invalidates it, but two
`pwrite()` paths never go through `write()`: the host path and the
sub-threshold device shortcut. So `nbytes()` could report a stale size
after a write.

Both now invalidate the cache once the write has completed, so a
`nbytes()` call racing with an in-flight `pwrite()` cannot leave a stale
size cached either.

Unrelated to the rest of this branch.
@madsbk
madsbk force-pushed the logical-observations branch 2 times, most recently from e1bf9bf to 7360ca8 Compare August 14, 2026 11:52
Comment thread cpp/src/remote_handle.cpp
Comment on lines -878 to -883
if (is_read_out_of_bounds(file_offset, size, _nbytes)) {
std::stringstream ss;
ss << "cannot read " << file_offset << "+" << size << " bytes into a " << _nbytes
<< " bytes file (" << _endpoint->str() << ")";
KVIKIO_FAIL(ss.str(), std::invalid_argument);
}

@madsbk madsbk Aug 14, 2026

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not removed, just moved to the top of read, before the buffer is classified.

Comment thread cpp/src/remote_handle.cpp
Comment on lines -784 to -789
if (is_read_out_of_bounds(file_offset, size, _nbytes)) {
std::stringstream ss;
ss << "cannot read " << file_offset << "+" << size << " bytes into a " << _nbytes
<< " bytes file (" << _endpoint->str() << ")";
KVIKIO_FAIL(ss.str(), std::invalid_argument);
}

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not removed, just moved to the top of read, before the buffer is classified.

@madsbk
madsbk force-pushed the logical-observations branch from 7360ca8 to 0846f46 Compare August 14, 2026 12:10
@madsbk
madsbk force-pushed the logical-observations branch from 0846f46 to 9a4fe49 Compare August 14, 2026 12:12
@madsbk
madsbk marked this pull request as ready for review August 14, 2026 12:55
@madsbk
madsbk requested review from a team as code owners August 14, 2026 12:55
@rapidsai rapidsai deleted a comment from copy-pr-bot Bot Aug 14, 2026

@wence- wence- left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Broadly looks good, I think.

Comment thread cpp/include/kvikio/observation.hpp Outdated
Comment thread cpp/src/file_handle.cpp
Comment thread cpp/src/observation.cpp Outdated
Comment thread cpp/src/remote_handle.cpp Outdated
Comment thread cpp/tests/test_observation.cpp Outdated
@madsbk
madsbk requested a review from wence- August 14, 2026 14:20
Comment thread cpp/include/kvikio/observation.hpp
madsbk added 2 commits August 14, 2026 22:47
The number of `IoBackend` values, for a table with one entry per backend.
Derived from the last enumerator and placed next to the enum, so the two stay
together.
@madsbk
madsbk force-pushed the logical-observations branch from fc7f400 to d02ce30 Compare August 15, 2026 11:39
madsbk added 2 commits August 15, 2026 13:43
`Clock` is monotonic, so its timestamps cannot be compared with anything
outside the process. `ClockAnchor::now()` reads it together with the wall
clock, and `to_wall_clock()` maps a timestamp through that pair.

This keeps the measurements on a clock that cannot step while still allowing an
observation to be lined up with a log line, another process, or a profiler
trace.
@madsbk
madsbk force-pushed the logical-observations branch from d02ce30 to 219c84d Compare August 15, 2026 11:46
Both repeated what the documentation of the function beside them already says.

@vyasr vyasr left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Approving CMake (didn't review the C++).

Comment thread cpp/include/kvikio/detail/observation_recorder.hpp Outdated
Comment thread cpp/src/observation.cpp
@madsbk

madsbk commented Aug 18, 2026 via email

Copy link
Copy Markdown
Member Author

@kingcrimsontianyu

Copy link
Copy Markdown
Contributor

Oh I was commenting on the namespace detail part.

@madsbk

madsbk commented Aug 18, 2026 via email

Copy link
Copy Markdown
Member Author

@kingcrimsontianyu

Copy link
Copy Markdown
Contributor

It's up to you. We do have an existing src/detail directory containing code that otherwise goes to the detail namespace. Not a big deal though.

@madsbk

madsbk commented Aug 18, 2026 via email

Copy link
Copy Markdown
Member Author

Comment thread cpp/include/kvikio/observation.hpp

@kingcrimsontianyu kingcrimsontianyu left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks. Good design!

@madsbk

madsbk commented Aug 18, 2026

Copy link
Copy Markdown
Member Author

/merge

@rapids-bot
rapids-bot Bot merged commit b7b967e into rapidsai:main Aug 18, 2026
65 checks passed
@madsbk
madsbk deleted the logical-observations branch August 18, 2026 08:03
rapids-bot Bot pushed a commit that referenced this pull request Aug 22, 2026
Builds on the observation facility from #1033. That PR gives a callback per user-facing I/O call, and this one gives the answer most people actually want from it, which is what a run did in total.

`SummaryMonitor` registers itself on construction and accumulates while it exists. `Summary` carries the operations, the bytes, the errors, and the time at least one operation was in flight, which is what distinguishes an I/O-bound run from a compute-bound one.

### Using it

```python
with kvikio.SummaryMonitor() as monitor:
    ...
print(monitor.get())
```

In C++ the constructor takes an optional callback, which runs on destruction, so a program can report its own I/O without touching the code that performs it.

```c++
kvikio::statistics::SummaryMonitor const monitor{
  [](kvikio::statistics::Summary const& summary) { std::cout << summary.report(); }};
```

An interval is the difference of two readings, so periodic reporting takes one reading per tick and differences it against the last. Taking the reading and the interval separately would leave a gap that an operation could fall into twice.

```python
baseline = monitor.get()
while running:
    time.sleep(interval)
    now = monitor.get()
    report(now.since(baseline))
    baseline = now
```

### The report

Printing a summary, or `report()`, gives a report meant for a person, always the same shape so two runs can be compared line by line. This is `python/kvikio/examples/hello_world.py`:

```
KvikIO I/O summary
  wall time            251.72 ms
  busy time            5.95 ms (2.36 % of the wall time)
  busy bandwidth       538.15 kB/s
  operations           5 (4 read, 1 write)
  time per operation   1.19 ms mean, 3.19 ms longest
  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.95 ms, 538.15 kB/s
  backend GDS          unused
  backend MMAP         unused
  backend REMOTE_HTTP  unused
  backend REMOTE_HDFS  unused
```

Five operations for one write and four reads, however many reads KvikIO issued underneath, since the observations are logical.

**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 by that rather than by the wall time, so a program that reads for 10 ms and then computes for 90 ms is not reported as ten times slower than its storage really is. The **backend** rows are the only place the report says whether a read reached cuFile or fell back to POSIX, which compatibility mode decides per call.

### Overhead

On my local workstation, 32 cores, medians over two million observed operations, so an order of magnitude rather than a specification.

| per operation | |
|---|---|
| no monitor registered | 4.8 ns |
| `SummaryMonitor` | 64 to 79 ns |

This includes everything, both the observation facility from #1033 stamping and dispatching each operation, and the accumulation this PR adds on top. So a monitor costs about 2 % of a 4 KiB `pread()` and 0.25 % of a 1 MiB one. Registering none is the 4.8 ns row, one relaxed atomic load per operation.

Eight threads doing nothing but emitting observations cost 320 ns each, every operation taking the monitor's lock to add itself to the totals. Real work in between makes it disappear.


### Follow-ups

- **What KvikIO spends on itself**, the bounce buffers it allocates, the connections it opens, the time inside the file system. The next PR adds those counters and surfaces them on `Summary`.
- **A record per operation**, which a summary cannot give: a timeline monitor and a sampling monitor.
- **`ObservationKind::PHYSICAL`**. Everything here is logical, one user-facing call being one operation. When physical operations arrive, `Summary` stays one type rather than splitting in two, since the fields mean the same thing at either level.

Authors:
  - Mads R. B. Kristensen (https://github.com/madsbk)

Approvers:
  - Bradley Dice (https://github.com/bdice)
  - Tianyu Liu (https://github.com/kingcrimsontianyu)

URL: #1036
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

improvement Improves an existing functionality non-breaking Introduces a non-breaking change

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants