Skip to content

Add structured, physical read traces - #1016

Open
TomAugspurger wants to merge 4 commits into
rapidsai:mainfrom
TomAugspurger:tom/read-log-traces
Open

Add structured, physical read traces#1016
TomAugspurger wants to merge 4 commits into
rapidsai:mainfrom
TomAugspurger:tom/read-log-traces

Conversation

@TomAugspurger

@TomAugspurger TomAugspurger commented Jul 28, 2026 •
edited
Loading

Copy link
Copy Markdown
Contributor

This updates our logging setup to optionally emit structured, physical traces.

There are two main sets of changes:

  1. Log physical reads at a TRACE level. This takes the "logical" reads from the user's program and traces the actual reads done by kvikio, which might be smaller thanks to kvikio's read splitting
  2. Optionally output to a structured ndjson format, which is easier for downstream tools to parse.

Here's an example program:

import kvikio
import cupy as cp


remote_file = kvikio.RemoteFile.open_s3_url("s3://rapids-tpch/tpch-rs/scale-1/nation/part.0.parquet")
buf = cp.empty(remote_file.nbytes(), dtype=cp.uint8)

size = 1024

remote_file.read(buf, size, 0)
remote_file.read(buf, remote_file.nbytes() - size, size)

print("done")

When run with KVIKIO_LOG_LEVEL=TRACE KVIKIO_LOG_FORMAT=JSON KVIKIO_LOG_FILE=trace.ndjson python test_remote.py that writes

$ cat trace.ndjson 
{"event":"http","level":"trace","source":"https://rapids-tpch.s3.us-east-2.amazonaws.com/tpch-rs/scale-1/nation/part.0.parquet","start":1785255602404710891,"end":1785255602626790456,"threadId":4621804004366526777,"method":"HEAD","status":"ok","purpose":"metadata"}
{"event":"read","level":"trace","source":"https://rapids-tpch.s3.us-east-2.amazonaws.com/tpch-rs/scale-1/nation/part.0.parquet","start":1785255603191754437,"end":1785255603272868402,"offset":0,"size":1024,"threadId":6135855871742540183,"bytesRead":1024,"backend":"remote","status":"ok","isDeviceBuffer":true,"requestId":1,"method":"GET"}
{"event":"read","level":"trace","source":"https://rapids-tpch.s3.us-east-2.amazonaws.com/tpch-rs/scale-1/nation/part.0.parquet","start":1785255603273011822,"end":1785255603349365176,"offset":1024,"size":1226,"threadId":6135855871742540183,"bytesRead":1226,"backend":"remote","status":"ok","isDeviceBuffer":true,"requestId":2,"method":"GET"}

Closes #967

@copy-pr-bot

copy-pr-bot Bot commented Jul 28, 2026

Copy link
Copy Markdown

Auto-sync is disabled for draft pull requests in this repository. Workflows must be run manually.

Contributors can view more details about this message here.

@TomAugspurger

TomAugspurger commented Jul 28, 2026

Copy link
Copy Markdown
Contributor Author

/ok to test 19db970

@TomAugspurger

TomAugspurger commented Jul 28, 2026

Copy link
Copy Markdown
Contributor Author

/ok to test 908041a

@TomAugspurger TomAugspurger added improvement Improves an existing functionality non-breaking Introduces a non-breaking change labels Jul 28, 2026
@TomAugspurger
TomAugspurger marked this pull request as ready for review July 29, 2026 17:17
@TomAugspurger
TomAugspurger requested review from a team as code owners July 29, 2026 17:17
TomAugspurger
TomAugspurger commented Jul 29, 2026
View reviewed changes
Comment thread python/kvikio/kvikio/_readlog_to_trace.py

@TomAugspurger TomAugspurger Jul 29, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

This is deliberately private. It's been useful for me, and might be useful for others, but I don't think we should commit to maintaining it.

Comment thread docs/source/runtime_settings.rst

{"event":"read","level":"trace","source":"s3://bucket/data.parquet","start":1747901139123456789,"end":1747901139127890123,"offset":4194304,"size":1048576,"threadId":17390204170953158183,"bytesRead":1048576,"backend":"remote","status":"ok","isDeviceBuffer":true,"requestId":42,"method":"GET"}

HTTP metadata JSON objects have ``"event":"http"`` and the following fields:

@TomAugspurger TomAugspurger Jul 29, 2026

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

I wonder if this should just go under event: read with method: HEAD. Why split it out into its own thing?

@TomAugspurger

TomAugspurger commented Jul 29, 2026

Copy link
Copy Markdown
Contributor Author

This will need to be benchmarked to see how much overhead we've introduced.

@madsbk madsbk mentioned this pull request Aug 14, 2026
Merged
rapids-bot Bot pushed a commit that referenced this pull request Aug 18, 2026
@madsbk
Add an I/O observation facility (#1033)
b7b967e 
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.

```c++
// 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:

```python
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.

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

Approvers:
  - Lawrence Mitchell (https://github.com/wence-)
  - Vyas Ramasubramani (https://github.com/vyasr)
  - Tianyu Liu (https://github.com/kingcrimsontianyu)

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

Reviewers

No reviews

Assignees

No one assigned

Labels

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

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

Structured logs for each read request

1 participant

@TomAugspurger