diff --git a/.github/scripts/bpf_smoke.py b/.github/scripts/bpf_smoke.py index 2573745..6daeee2 100644 --- a/.github/scripts/bpf_smoke.py +++ b/.github/scripts/bpf_smoke.py @@ -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): diff --git a/docs/traces/BLOCK_IO_EVENTS.md b/docs/traces/BLOCK_IO_EVENTS.md index ade26b7..3a528a2 100644 --- a/docs/traces/BLOCK_IO_EVENTS.md +++ b/docs/traces/BLOCK_IO_EVENTS.md @@ -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 | @@ -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 | |-------|-------------| @@ -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 | |------|------|-------------| diff --git a/src/tracer/FlagMapper.py b/src/tracer/FlagMapper.py index f4b97ad..fca024e 100644 --- a/src/tracer/FlagMapper.py +++ b/src/tracer/FlagMapper.py @@ -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. diff --git a/src/tracer/IOTracer.py b/src/tracer/IOTracer.py index b2b5670..14f2224 100644 --- a/src/tracer/IOTracer.py +++ b/src/tracer/IOTracer.py @@ -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 diff --git a/src/tracer/KernelProbeTracker.py b/src/tracer/KernelProbeTracker.py index c907b6d..c893059 100644 --- a/src/tracer/KernelProbeTracker.py +++ b/src/tracer/KernelProbeTracker.py @@ -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 # ===================================== diff --git a/src/tracer/prober/prober.c b/src/tracer/prober/prober.c index a22c255..d688eb8 100644 --- a/src/tracer/prober/prober.c +++ b/src/tracer/prober/prober.c @@ -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. */ }; /* ============================================================================ @@ -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 @@ -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) { + /* 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); + } 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 * @@ -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; } @@ -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; } @@ -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; } @@ -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_*) @@ -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. diff --git a/src/tracer/schema.py b/src/tracer/schema.py index 15f1ea9..f073deb 100644 --- a/src/tracer/schema.py +++ b/src/tracer/schema.py @@ -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"), diff --git a/tests/test_flag_mapper.py b/tests/test_flag_mapper.py index d4e6ce4..3b0e3d9 100644 --- a/tests/test_flag_mapper.py +++ b/tests/test_flag_mapper.py @@ -109,6 +109,33 @@ def test_no_map(self): self.assertEqual(self.m.format_mmap_map_flags(0), "NO_MAP") +class SwapFlagTests(unittest.TestCase): + """append_swap_flag merges the REQ_SWAP marker into the block flags column.""" + + def setUp(self): + self.m = FlagMapper() + + def test_no_swap_leaves_flags_unchanged(self): + self.assertEqual(self.m.append_swap_flag("", 0), "") + self.assertEqual(self.m.append_swap_flag("sync|meta", 0), "sync|meta") + + def test_swap_on_empty_flags(self): + self.assertEqual(self.m.append_swap_flag("", 1), "swap") + + def test_swap_appends_to_existing_flags(self): + # Lowercase and pipe-joined, consistent with the rwbs sub-flags. + self.assertEqual(self.m.append_swap_flag("sync", 1), "sync|swap") + self.assertEqual(self.m.append_swap_flag("sync|meta", 1), "sync|meta|swap") + + def test_matches_block_stream_pipeline(self): + # End-to-end shape of _print_event_block: format_block_ops decodes the + # rwbs string, the base op is split off, and the swap marker joins the + # remaining sub-flags. + parts = self.m.format_block_ops("WS").split("|") + op_flags = "|".join(parts[1:]) + self.assertEqual(self.m.append_swap_flag(op_flags, 1), "sync|swap") + + class ErrnoTests(unittest.TestCase): def test_zero_is_empty(self): self.assertEqual(FlagMapper.format_errno(0), "")