Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions .github/scripts/bpf_smoke.py
Original file line number Diff line number Diff line change
Expand Up @@ -98,6 +98,11 @@ def main():
(b"iomap_dio_rw", [("kprobe", "iomap_dio_rw", "trace_dio_entry_iomap"),
("kretprobe", "iomap_dio_rw", "trace_dio_return")]),
(b"__blockdev_direct_IO", [("kprobe", "__blockdev_direct_IO", "trace_dio_entry_blockdev")]),
# Swap-origin capture: the handler only exists when the kernel's
# headers define REQ_SWAP (4.19+; always true on CI runners), so a
# failed attach here catches a broken #ifdef guard that BPF() load
# alone would silently pass.
(b"blk_mq_start_request", [("kprobe", "blk_mq_start_request", "trace_blk_mq_start_request")]),
]
for symbol, symbol_probes in conditional_probes:
if BPF.get_kprobe_functions(symbol):
Expand Down
52 changes: 44 additions & 8 deletions docs/traces/BLOCK_IO_EVENTS.md
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@
| 7 | size | `u64` | I/O size in bytes |
| 8 | latency_ms | `float` | Device latency in milliseconds (issue → completion) |
| 9 | device | `string` | Device number as `major:minor` identifying the partition/device |
| 10 | flags | `string` | Pipe-separated rwbs sub-flags (`sync`, `meta`, `ahead`, …) split out of the `operation` column |
| 10 | flags | `string` | Pipe-separated rwbs sub-flags (`sync`, `meta`, `ahead`, …) split out of the `operation` column, plus `swap` for swap-out (`REQ_SWAP`) requests — see [Swap-origin tagging](#swap-origin-tagging-swap-flag) |
| 11 | cpu_id | `u32` | CPU where completion was processed |
| 12 | ppid | `u32` | Parent process ID |
| 13 | queue_latency_ms | `float` | Queue/scheduler latency in milliseconds (insert → issue); empty if unavailable |
Expand All @@ -61,11 +61,11 @@ I/O latency is tracked across the block layer request lifecycle using kernel tra
- **Meaning**: Represents the time the request spent queued up in the OS scheduler waiting to be dispatched to the device.

**Key Matching Mechanism**:
To accurately match corresponding `insert`, `issue`, and `complete` events for a single request, the tracer uses a composite key consisting of the block device number and starting sector (`(dev << 32) ^ sector`). CPU IDs are intentionally excluded from the correlation key, as an I/O request may be issued on one CPU but completed via an interrupt handled by a different CPU.
To accurately match corresponding `insert`, `issue`, and `complete` events for a single request, the tracer uses a composite key struct holding the block device number and the full 64-bit starting sector as separate fields (so distinct `(dev, sector)` pairs can never collide). CPU IDs are intentionally excluded from the correlation key, as an I/O request may be issued on one CPU but completed via an interrupt handled by a different CPU.

## Operation Types

Derived from the block layer `rwbs` string and normalized. When the rwbs string contains multiple flags (e.g., "WS", "RM"), the operation field contains pipe-separated values (e.g., "write|sync", "read|meta"):
Derived from the block layer `rwbs` string and normalized. When the rwbs string contains multiple flags (e.g., "WS", "RM"), the base operation goes in the operation column (field 2) and the remaining sub-flags go in the flags column (field 10) — e.g. "WS" → operation=`write`, flags=`sync`:

| Value | Description |
|-------|-------------|
Expand Down Expand Up @@ -128,15 +128,51 @@ Command flags captured in the `command_flags` field (field 14). Multiple flags a
| `0x2000` | `REQ_NOWAIT` | Don't wait if request cannot be issued |
| `0x4000` | `REQ_CGROUP_PUNT` | Cgroup accounting |

## Swap-origin tagging (`swap` flag)

Swap I/O goes through the block layer with no filesystem counterpart, so on
memory-constrained hosts it masquerades as filesystem block I/O (inflating
apparent write amplification and polluting cacheability analysis). To let
analysis subtract it, the tracer appends `swap` to the `flags` column (field
10) for requests that carried the kernel's `REQ_SWAP` command flag.

**How it is captured.** The rwbs string never encodes `REQ_SWAP`, and on
mainline kernels the `block_rq_*` tracepoint arguments carry no `cmd_flags` at
all (the `command_flags` column only populates on patched vendor kernels — see
the note under the field table), so the bit cannot come from the tracepoint
arguments. Instead a best-effort kprobe on `blk_mq_start_request()` — the
function that fires `block_rq_issue` — reads `cmd_flags` from `struct request`
at issue time and carries the bit to the completion event via a
`(device, sector)`-keyed map, mirroring the existing issue→completion
correlation. Because that key is reused over time, the marker is timestamped
and cross-checked against the matched issue context (and restricted to write
ops) before it is honored, so a marker orphaned by a missed completion cannot
mis-tag a later request.

**Caveats:**

- **Swap-out only.** The kernel sets `REQ_SWAP` exclusively on swap *writes*
(`mm/page_io.c` builds swap-in reads as plain `REQ_OP_READ`), so swap-in
reads are never tagged, on any kernel version.
- **Best-effort.** If the `blk_mq_start_request` symbol cannot be probed, or
the kernel's headers do not define `REQ_SWAP` (kernels < 4.19, where the
probe is skipped entirely), block events simply carry no `swap` tag; nothing
else is affected.
- **Request-based devices only.** Swap on bio-based devices (e.g. zram)
produces no `block_rq_*` events at all, so it never appears in this stream —
with or without tagging.

**Example** `flags` values: `swap`, `sync|swap`, `meta` (no swap).

## RWBS Flags

Character flags from the block layer tracepoint `rwbs` string. Each character in the rwbs string is decoded to its corresponding flag name, and when multiple characters are present, they are concatenated with pipes in the Operation field (field 2).
Character flags from the block layer tracepoint `rwbs` string. Each character in the rwbs string is decoded to its corresponding flag name; the first (the base operation) lands in the Operation column (field 2) and any remaining sub-flags are pipe-concatenated into the flags column (field 10).

**Examples:**
- `"R"` → `"read"`
- `"WS"` → `"write|sync"`
- `"RM"` → `"read|meta"`
- `"WMA"` → `"write|meta|ahead"`
- `"R"` → operation=`read`, flags empty
- `"WS"` → operation=`write`, flags=`sync`
- `"RM"` → operation=`read`, flags=`meta`
- `"WMA"` → operation=`write`, flags=`meta|ahead`

| Char | Name | Description |
|------|------|-------------|
Expand Down
22 changes: 22 additions & 0 deletions src/tracer/FlagMapper.py
Original file line number Diff line number Diff line change
Expand Up @@ -514,6 +514,28 @@ def decode_rwbs(self, rwbs_str):

return "|".join(result) if result else "UNKNOWN"

def append_swap_flag(self, flags_str, is_swap):
"""
Append the swap-origin tag to a block flags string.

Swap-out block I/O carries REQ_SWAP in the kernel, which the rwbs
string never encodes; the tracer captures it as a separate boolean at
request-issue time and merges it into the pipe-joined ``flags`` column
here (lowercase, consistent with the rwbs-derived sub-flags such as
``sync``/``meta``/``ahead``).

Args:
flags_str: Existing pipe-joined block flags ("" when none).
is_swap: Truthy when the request carried REQ_SWAP.

Returns:
str: The flags string with ``swap`` appended when is_swap is
truthy, otherwise unchanged.
"""
if not is_swap:
return flags_str
return f"{flags_str}|swap" if flags_str else "swap"

def decode_block_req_flags(self, flags):
"""
Decode block request command flags.
Expand Down
6 changes: 6 additions & 0 deletions src/tracer/IOTracer.py
Original file line number Diff line number Diff line change
Expand Up @@ -1178,6 +1178,12 @@ def _print_event_block(self, cpu, data, size):
_op_parts = ops_str.split("|")
op_base = _op_parts[0]
op_flags = "|".join(_op_parts[1:])
# Swap-origin marker (REQ_SWAP, captured at issue time by the
# blk_mq_start_request kprobe — rwbs never encodes it) joins the
# rwbs-derived sub-flags so swap-out traffic can be separated from
# filesystem-origin block I/O.
op_flags = self.flag_mapper.append_swap_flag(
op_flags, getattr(event, 'is_swap', 0))
latency_ns = event.latency_ns
latency_ms = latency_ns / 1_000_000.0
cpu_id = event.cpu_id
Expand Down
27 changes: 27 additions & 0 deletions src/tracer/KernelProbeTracker.py
Original file line number Diff line number Diff line change
Expand Up @@ -405,6 +405,33 @@ def attach_probes(self):
elif self.developer_mode:
logger("warning", "No reclaim probe available, reclaim events will not be traced")

# =====================================
# Block-layer swap-origin capture
# =====================================
# The block_rq_* tracepoints auto-attach, but they cannot see
# REQ_SWAP: rwbs never encodes it, and on mainline kernels the
# tracepoint args carry no cmd_flags at all (only some patched
# vendor kernels expose it — see the HAS_CMD_FLAGS sniffing in
# IOTracer). A best-effort kprobe on blk_mq_start_request (the
# function that fires trace_block_rq_issue) reads the bit from
# struct request so the block stream can tag swap-out I/O with a
# `swap` flag. The BPF handler only exists when the kernel's
# headers define REQ_SWAP (4.19+); load_func failing means it was
# compiled out, and attaching an empty program would charge every
# block request a kprobe trap for nothing, so skip it. If
# anything here is unavailable, block events simply carry no swap
# tag — nothing else is affected.
if BPF.get_kprobe_functions(b'blk_mq_start_request'):
try:
self.b.load_func("trace_blk_mq_start_request", BPF.KPROBE)
except Exception:
if self.developer_mode:
logger("warning", "swap-origin BPF handler unavailable (REQ_SWAP undefined on this kernel, or load failed) - swap tagging disabled")
else:
self.add_kprobe("blk_mq_start_request", "trace_blk_mq_start_request")
elif self.developer_mode:
logger("warning", "blk_mq_start_request not available - swap-origin tagging disabled")

# =====================================
# io_uring probes for async I/O tracing
# =====================================
Expand Down
118 changes: 116 additions & 2 deletions src/tracer/prober/prober.c
Original file line number Diff line number Diff line change
Expand Up @@ -377,6 +377,9 @@ struct block_event {
* (CPU id in the high 16 bits, per-CPU sequence
* in the low 48). Disambiguates distinct I/Os
* that reuse the same (dev, sector). */
u8 is_swap; /**< 1 when the request carried REQ_SWAP (swap-out
* I/O). The kernel only sets REQ_SWAP on swap
* writes, so swap-in reads are never tagged. */
};

/* ============================================================================
Expand Down Expand Up @@ -728,6 +731,30 @@ struct block_rq_key_t {
BPF_TABLE("lru_hash", struct block_rq_key_t, struct block_issue_ctx, block_start_times, 65536); /**< Issue time + submitter, keyed by dev+sector */
BPF_TABLE("lru_hash", struct block_rq_key_t, u64, block_insert_times, 65536); /**< Tracks block request insert time (queue latency) */

/* Swap-origin (REQ_SWAP) markers, keyed like block_start_times and consumed
* at completion. Populated by the best-effort blk_mq_start_request kprobe:
* rwbs never encodes REQ_SWAP, and on mainline kernels the block tracepoint
* args carry no cmd_flags at all (see HAS_CMD_FLAGS), so the bit has to be
* read from struct request itself. The value is the marker's capture
* timestamp, cross-checked against the matched issue ctx at completion to
* reject markers left behind by requests that never completed; non-swap
* requests scrub the key at start (mirroring how the sibling maps are
* refreshed by every new claimant of (dev, sector)). Sized like the sibling
* maps: the resident population is only in-flight swap writes, but the
* common-LRU allocator hands out free nodes in per-CPU batches (~128/CPU),
* so a small ceiling starts evicting live markers on many-CPU hosts during
* swap storms — exactly the workload this tagging exists to measure. */
BPF_TABLE("lru_hash", struct block_rq_key_t, u64, block_swap_flags, 65536);

/* A genuine swap marker is written at blk_mq_start_request entry, moments
* before the same invocation fires block_rq_issue (which stores ictx->ts) —
* so marker_ts <= ictx->ts, with a gap of microseconds unless the task is
* preempted between the two. Anything newer than ictx belongs to a later
* request at a reused (dev, sector) key; anything older than this bound is
* residue of a request whose completion was never seen. 1s absorbs
* preemption and requeue latency with orders of magnitude to spare. */
#define SWAP_MARKER_MAX_AGE_NS (1ULL * 1000000000ULL) /* 1 second */

/* Per-request ID generator (see block_event.req_id). A per-CPU u64 counter
* bumped at issue time; the emitted req_id folds the CPU id into the high bits
* so ids stay unique across CPUs without an atomic fetch-and-add. A global
Expand Down Expand Up @@ -3044,6 +3071,69 @@ TRACEPOINT_PROBE(block, block_rq_issue) {
return 0;
}

/**
* @brief Swap-origin capture at request start (kprobe on blk_mq_start_request)
*
* Swap-out I/O reaches the block layer with REQ_SWAP set, but that bit is
* invisible to the tracepoint handlers above: the rwbs string never encodes
* it, and on mainline kernels the tracepoint args carry no cmd_flags at all
* (only some patched vendor kernels expose it — see HAS_CMD_FLAGS). It has
* to be read from struct request itself, which the tracepoint args do not
* carry — hence this kprobe on blk_mq_start_request(), the exported function
* that fires trace_block_rq_issue for every request-based driver since the
* legacy request path was removed in 5.0. Attachment is best-effort in
* KernelProbeTracker: if the symbol is missing, block events simply carry no
* swap tag.
*
* Swap-flagged requests store a timestamped marker; every other request
* scrubs the key, so a marker left behind by a swap write that never
* completed cannot mis-tag a later request reusing the same (dev, sector).
*
* NOTE: the kernel sets REQ_SWAP only on swap WRITES (mm/page_io.c builds
* swap-in reads as plain REQ_OP_READ), so swap-in traffic is never tagged.
*
* The whole handler is compiled out on kernels whose headers do not define
* REQ_SWAP (< 4.19): KernelProbeTracker probes for the function before
* attaching, so those kernels do not pay a per-request kprobe trap for a
* guaranteed no-op.
*/
#ifdef REQ_SWAP
int trace_blk_mq_start_request(struct pt_regs *ctx, struct request *rq) {

Copy link
Copy Markdown

Choose a reason for hiding this comment

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

medium

For defensive programming and consistency with other probe entry points in prober.c, it is highly recommended to explicitly check if the rq pointer is NULL before performing any member accesses or dereferences.

int trace_blk_mq_start_request(struct pt_regs *ctx, struct request *rq) {
  if (!rq)
    return 0;

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.

Declining this one: the kernel never calls blk_mq_start_request() with a NULL rq (the function unconditionally dereferences it), and under BCC every member access in a kprobe handler is rewritten into bpf_probe_read_kernel(), which fails safely on a bad pointer — disk would then read as NULL and the existing if (!disk) guard returns. An explicit if (!rq) would be unreachable code.


Generated by Claude Code

/* Mirror the block_rq_issue/complete tracepoints' key fields so the
* completion handler's block_rq_key() lookup matches:
* dev = disk_devt(disk) = MKDEV(major, first_minor), MINORBITS = 20.
* The tracepoints read the disk from rq->q->disk since the
* 5.17 removal of rq->rq_disk (f3fa33acca9f), and from
* rq->rq_disk before that.
* sector = blk_rq_trace_sector(rq), which is blk_rq_pos(rq) ==
* rq->__sector except for passthrough requests — and swap I/O
* is never passthrough. */
#if LINUX_VERSION_CODE >= KERNEL_VERSION(5, 17, 0)
struct gendisk *disk = rq->q->disk;
#else
struct gendisk *disk = rq->rq_disk;
#endif
if (!disk)
return 0;
u32 dev = ((u32)disk->major << 20) | (u32)disk->first_minor;
struct block_rq_key_t key = block_rq_key(dev, rq->__sector);

if (rq->cmd_flags & REQ_SWAP) {
u64 ts = bpf_ktime_get_ns();
block_swap_flags.update(&key, &ts);
Comment on lines +3111 to +3123

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.

This is already what happens under the hood: the tracer is BCC-based, and BCC's Clang rewriter converts member accesses on kprobe arguments into bpf_probe_read_kernel() calls automatically, one per hop of a multi-level chain (rq->q->disk included), compiled against the running kernel's headers. Direct-deref style is the file's existing idiom for kprobe handlers (e.g. file && file->f_inode in the VFS handlers); explicit bpf_probe_read_kernel() appears where the rewriter can't transform the access (array copies out of tracepoint args). Hand-written probe reads here would produce the same bytecode with more code. The BPF Compile CI job builds this handler as-is.


Generated by Claude Code

} else {
/* Scrub any stale marker at this key: (dev, sector) is not unique over
* time, and unlike the sibling maps (overwritten by every insert/issue)
* this map is only ever written by swap requests, so without the scrub a
* marker orphaned by a missed completion would tag the next request that
* reuses the key — however much later that is. Deleting a missing key is
* a cheap hash miss, so the common case stays inexpensive. */
block_swap_flags.delete(&key);
}
return 0;
}
#endif /* REQ_SWAP */

/**
* @brief Block request completion tracepoint
*
Expand All @@ -3065,8 +3155,10 @@ TRACEPOINT_PROBE(block, block_rq_complete) {
// Drop any insert timestamp for this key too — without the issue ctx we
// can't emit an event, and leaving it behind lets a later request that
// reuses the same (dev,sector) key read a stale insert_ts and report a
// wildly inflated queue latency.
// wildly inflated queue latency. Same for a stale swap marker, which
// would mis-tag a later non-swap request reusing the key.
block_insert_times.delete(&key);
block_swap_flags.delete(&key);
return 0;
}

Expand All @@ -3077,6 +3169,7 @@ TRACEPOINT_PROBE(block, block_rq_complete) {
if (tracer_pid && ictx->pid == *tracer_pid) {
block_start_times.delete(&key);
block_insert_times.delete(&key);
block_swap_flags.delete(&key);
return 0;
}

Expand All @@ -3095,6 +3188,7 @@ TRACEPOINT_PROBE(block, block_rq_complete) {
*stale += 1;
block_start_times.delete(&key);
block_insert_times.delete(&key);
block_swap_flags.delete(&key);
return 0;
}

Expand Down Expand Up @@ -3133,7 +3227,7 @@ TRACEPOINT_PROBE(block, block_rq_complete) {
event.latency_ns = latency;
event.queue_time_ns = queue_time; // New: queue time
event.req_id = ictx->req_id; // Stable per-request id

#ifdef HAS_CMD_FLAGS
event.cmd_flags = args->cmd_flags; // Capture REQ_* command flags
// Extract raw operation code from cmd_flags (lower 8 bits contain REQ_OP_*)
Expand All @@ -3150,6 +3244,26 @@ TRACEPOINT_PROBE(block, block_rq_complete) {

bpf_probe_read_kernel(&event.op, sizeof(event.op), &args->rwbs);

// Swap-origin marker captured by the blk_mq_start_request kprobe (the
// tracepoint args carry neither the rwbs-invisible REQ_SWAP nor, on
// mainline kernels, cmd_flags at all). (dev, sector) keys are reused over
// time, so — mirroring the ictx staleness guards above — the marker is
// honored only when it is consistent with the matched issue ctx: a genuine
// marker is written at blk_mq_start_request entry, moments before the same
// invocation fires block_rq_issue, so it must be no newer than ictx->ts
// (newer = a later request's marker) and not much older (older = residue
// of a request whose completion was missed). The kernel sets REQ_SWAP only
// on writes, so a non-write rwbs can never legitimately match. Deleted on
// every path so a later request cannot inherit it.
u64 *swap_ts = block_swap_flags.lookup(&key);
if (swap_ts) {
if (*swap_ts <= ictx->ts &&
ictx->ts - *swap_ts < SWAP_MARKER_MAX_AGE_NS &&
event.op[0] == 'W')
event.is_swap = 1;
block_swap_flags.delete(&key);
}

bl_events.perf_submit(args, &event, sizeof(event));

// Diagnostics: count completed (emitted) requests.
Expand Down
2 changes: 1 addition & 1 deletion src/tracer/schema.py
Original file line number Diff line number Diff line change
Expand Up @@ -105,7 +105,7 @@ def _stream(subdir, prefix, description, clock, columns):
_col("size", "u64", "bytes", "I/O size."),
_col("latency_ms", "float", "milliseconds", "Device latency (issue->completion)."),
_col("device", "string", "", "Device major:minor (Windows: disk index)."),
_col("flags", "string", "", "rwbs sub-flags (sync|meta|ahead|...); empty when none."),
_col("flags", "string", "", "rwbs sub-flags (sync|meta|ahead|...) plus swap for REQ_SWAP (swap-out) requests; empty when none."),
# --- Linux-only extras (columns 11+) --- #
_col("cpu_id", "u32", "", "CPU that processed completion."),
_col("ppid", "u32"),
Expand Down
Loading
Loading