Merge pull request #35 from cacheMon/claude/charming-brown-jbpfzy

Capture io_uring SQE fields and mirror async I/O into the fs trace

Author: 1a1a11a

docs/traces/IO_URING_EVENTS.md

@@ -4,12 +4,25 @@
 
 **Kernel Probes Attached:**
 - `__io_uring_enter` / `__sys_io_uring_enter` — io_uring_enter syscall
+- `io_prep_rw` (or per-op `io_prep_read{,v,_fixed}` / `io_prep_write{,v,_fixed}`) — SQE field capture
 - `io_queue_sqe` / `io_submit_sqe` — SQE submission
 - `io_req_complete_post` / `io_req_complete` — Completion
 - `io_wq_submit_work` — Async worker execution
 
 > **Note:** The `io_uring:io_uring_submit_sqe` and `io_uring:io_uring_complete` tracepoints are disabled by default due to incompatible struct field layouts across kernel versions. The kprobe-based implementations above provide cross-kernel compatibility.
 
+### SQE field capture and file correlation
+
+The SUBMIT kprobe on `io_queue_sqe` only receives the internal `struct io_kiocb`, whose layout is **not** ABI-stable across kernel releases, so reading `opcode`/`fd`/`len`/`offset`/`user_data` from it directly is unreliable. Instead these fields are captured at request-**prep** time:
+
+- `trace_io_uring_prep_rw` attaches to the read/write prep handler (`io_prep_rw`), which is dispatched through the opcode table (`def->prep`) and therefore is not inlined. It receives the **UAPI `struct io_uring_sqe`** (PARM2), whose leading field offsets are stable for all io_uring kernels. A minimal mirror (`io_uring_sqe_min`) reads `opcode`, `flags`, `ioprio`, `fd`, `off`, `len`, `user_data` and `buf_index`.
+- The same probe reads `req->file` (the first member of `struct io_kiocb` on modern kernels) and, when it is a regular file on a real filesystem, records the backing **inode**, **device** and **superblock magic** via the same helpers used by the VFS probes.
+- These values are staged in the `io_uring_submit_map` (keyed by the `io_kiocb` pointer) and consumed by the SUBMIT, COMPLETE and WORKER probes.
+
+If the prep symbol is unavailable on a given kernel, the SUBMIT probe falls back to reading `req->file` directly for inode/device/fs, and the SQE-only fields (`opcode`, `len`, `offset`, `user_data`) simply remain empty — graceful degradation rather than failure.
+
+> **Note:** This captures SQE fields for the read/write opcode families (the bulk of filesystem I/O). Other opcodes (e.g. `OPENAT`, `STATX`) are not prepped through `io_prep_rw`, so their `opcode`/`fd`/`len`/`offset` columns may be empty.
+
 ## Data Captured
 
 | # | Field | Type | Description |
@@ -52,6 +65,12 @@
 | 36 | CQ Tail | `u32` | Completion queue tail (optional) |
 | 37 | SQ Depth | `u32` | SQ backlog (sq_tail - sq_head) |
 | 38 | CQ Depth | `u32` | CQ backlog (cq_tail - cq_head) |
+| 39 | Inode | `u64` | Backing file inode for file-backed ops; empty otherwise |
+| 40 | Filename | `string` | Resolved file path (from the inode→path cache populated by OPEN events); empty if unresolved |
+| 41 | Device | `string` | Backing device as `major:minor` (from `super_block->s_dev`); empty otherwise |
+| 42 | FS Type | `string` | Source filesystem name from the superblock magic (e.g. `EXT2/3/4`, `XFS`, `BTRFS`); empty otherwise |
+
+> Columns 39–42 are appended to the original 38-column schema, so parsers that read only the first 38 fields are unaffected.
 
 ## Event Types
 
@@ -141,6 +160,16 @@ SUBMIT and COMPLETE events share the same `Req Ptr`, enabling latency calculatio
 latency_ns = complete_ts_ns - submit_ts_ns
 ```
 
+## Mirroring into the fs/VFS trace
+
+io_uring read/write operations call `->read_iter`/`->write_iter` directly and **never pass through `vfs_read`/`vfs_write`**, so they are invisible to the VFS probes. To make async I/O visible alongside syscall I/O, each completed io_uring read/write is also emitted into the main **fs/VFS trace** (`fs/fs_*.csv`) using the standard VFS 22-column schema:
+
+- **Mirrored opcodes:** `READV`, `READ_FIXED`, `READ` → `READ`; `WRITEV`, `WRITE_FIXED`, `WRITE` → `WRITE`.
+- **Trigger:** COMPLETE events only (so `bytes_completed`/`duration_ns` are known), and only when a backing inode was resolved.
+- **Columns:** filename/inode/device/fs_type come from the prep-time file capture; `size` is the SQE length, `bytes_completed`/`errno` from the CQE result, `duration_ns` from the submit→complete latency. The generic `flags` column carries the decoded **SQE flags** (`FIXED_FILE|ASYNC|IO_LINK…`) in place of the open-file `O_*` flags, which are not available on the io_uring path.
+
+`fsync` is intentionally **not** mirrored: io_uring `FSYNC` calls `vfs_fsync` internally and is therefore already captured by the VFS fsync probe — mirroring it would double-count. The full async-specific detail (req_ptr, user_data, worker, queue depths) always remains in the dedicated io_uring CSV.
+
 ## Analysis Use Cases
 
 This data enables:

docs/traces/VFS_EVENTS.md

@@ -22,6 +22,8 @@
 - `vfs_fallocate` — File space pre-allocation operations
 - `do_sendfile` / `__do_sendfile` — Efficient file-to-file transfer operations
 
+> **io_uring-origin rows:** `READ`/`WRITE` operations issued via io_uring bypass `vfs_read`/`vfs_write` (they call `->read_iter`/`->write_iter` directly), so they are mirrored into this trace from the io_uring instrumentation rather than captured by a VFS probe. They use the same schema; their `flags` column carries io_uring SQE flags (`FIXED_FILE|ASYNC|…`) instead of `O_*` flags, and `ppid`/`container_id` are empty. See [IO_URING_EVENTS.md](IO_URING_EVENTS.md#mirroring-into-the-fsvfs-trace). Each such row also has a full-detail counterpart in the io_uring CSV.
+
 ## Filename Resolution
 
 The `filename` field contains the best available path for the file at event time. Full absolute paths are resolved entirely inside the kernel at probe time before the process can exit, so even output from short-lived processes (e.g. `cat`, `ls`) contains correct paths.

src/tracer/IOTracer.py

@@ -800,6 +800,31 @@ def _print_event_io_uring(self, cpu, data, size):
         sq_depth = str(e.sq_depth) if e.sq_depth else ""
         cq_depth = str(e.cq_depth) if e.cq_depth else ""
 
+        # File correlation — the prep probe records the backing file's inode,
+        # device and filesystem for file-backed ops. Resolve the path from the
+        # inode→path cache populated by OPEN events (same strategy as VFS events)
+        # so io_uring I/O carries the same file identity as the fs trace.
+        inode_val = e.inode if getattr(e, "inode", 0) else ""
+        dev_val = self._format_dev(e.dev) if getattr(e, "dev", 0) else ""
+        fs_type_val = (
+            self.flag_mapper.format_fs_type(e.fs_magic)
+            if getattr(e, "fs_magic", 0) else ""
+        )
+        filename = ""
+        if getattr(e, "inode", 0):
+            cached = self.path_resolver.inode_to_path.get(e.inode)
+            if cached:
+                filename = cached
+            if self.anonymous and filename:
+                filename = hash_filename_in_path(Path(filename))
+
+        # Surface io_uring file READ/WRITE in the main fs/VFS trace stream so
+        # async I/O appears alongside syscall reads/writes. Mirror only on
+        # COMPLETE (result/latency known) and only read/write opcodes, which
+        # bypass vfs_read/vfs_write and would otherwise be invisible there.
+        if e.event_type == 2:
+            self._mirror_io_uring_to_fs(e, comm, filename, ts, dev_val, fs_type_val)
+
         # Build CSV row matching the unified schema from the guide
         output = format_csv_row(
             ts.strftime("%Y-%m-%d %H:%M:%S.%f"),
@@ -840,9 +865,76 @@ def _print_event_io_uring(self, cpu, data, size):
             cq_tail,
             sq_depth,
             cq_depth,
+            inode_val,
+            filename,
+            dev_val,
+            fs_type_val,
         )
         self.writer.append_io_uring_log(output)
 
+    def _mirror_io_uring_to_fs(self, e, comm, filename, ts, dev_val, fs_type_val):
+        """
+        Emit an fs/VFS-shaped row for a completed io_uring file READ/WRITE.
+
+        io_uring read/write operations call ``->read_iter``/``->write_iter``
+        directly and never pass through ``vfs_read``/``vfs_write``, so they are
+        invisible to the VFS probes. To make async I/O visible alongside
+        syscall I/O, this mirrors COMPLETE events for the read/write opcode
+        families into the fs log using the same 22-column schema as
+        ``_print_event``.
+
+        fsync is intentionally not mirrored: io_uring FSYNC calls ``vfs_fsync``
+        internally and is therefore already captured by the VFS fsync probe;
+        mirroring it would double-count.
+
+        Args:
+            e: The io_uring perf event.
+            comm: Decoded process name.
+            filename: Resolved file path (may be empty).
+            ts: Event datetime (matches the fs-log timestamp format).
+            dev_val: Pre-formatted ``major:minor`` device string.
+            fs_type_val: Pre-formatted filesystem name.
+        """
+        # IORING_OP_* read/write opcode families → unified fs operation name.
+        op_map = {
+            1: "READ",   # READV
+            4: "READ",   # READ_FIXED
+            22: "READ",  # READ
+            2: "WRITE",  # WRITEV
+            5: "WRITE",  # WRITE_FIXED
+            23: "WRITE", # WRITE
+        }
+        op_name = op_map.get(e.opcode)
+        if not op_name or not getattr(e, "inode", 0):
+            return
+
+        ret = e.result
+        return_value = str(ret)
+        errno_val = ""
+        bytes_completed = ""
+        if ret < 0:
+            errno_val = self.flag_mapper.format_errno(-ret)
+        else:
+            bytes_completed = str(ret)
+        duration_ns = str(e.latency_ns) if e.latency_ns else ""
+
+        offset_val = e.offset if e.offset else ""
+        tid_val = e.tid if e.tid else ""
+        size_val = e.len if e.len else 0
+        # io_uring rows carry the SQE flags (FIXED_FILE|ASYNC|IO_LINK…) in the
+        # generic flags column in place of the open-file O_* flags, which are
+        # not available on the io_uring path.
+        flags_val = self.flag_mapper.format_io_uring_sqe_flags(e.sqe_flags)
+        cmdline = self._read_cmdline_cached(e.pid)
+
+        output = format_csv_row(
+            ts, op_name, e.pid, comm, filename, size_val, e.inode,
+            flags_val, offset_val, tid_val, "", "", "", cmdline,
+            return_value, errno_val, bytes_completed, duration_ns,
+            dev_val, "", "", fs_type_val
+        )
+        self.writer.append_fs_log(output)
+
     def _cleanup(self, signum, frame):
         self.running = False
         self.probe_tracker.detach_kprobes()

src/tracer/KernelProbeTracker.py

@@ -387,6 +387,33 @@ def attach_probes(self):
                 if self.developer_mode:
                     logger("warning", "io_uring_enter probe not available - ENTER events disabled")
 
+            # io_uring SQE field capture (opcode/fd/len/offset/user_data + backing
+            # file). The SUBMIT kprobe on io_queue_sqe only has the io_kiocb, whose
+            # layout is not ABI-stable; the read/write prep handler receives the
+            # UAPI io_uring_sqe (stable offsets) and the io_kiocb, so we capture the
+            # SQE fields there and stage them for the SUBMIT/COMPLETE probes. The
+            # shared helper io_prep_rw covers all rw opcodes; fall back to the
+            # per-op prep handlers when it is inlined/renamed on a given kernel.
+            prep_attached = False
+            for sym in (b'io_prep_rw', b'__io_prep_rw'):
+                if BPF.get_kprobe_functions(sym):
+                    self.add_kprobe(sym.decode(), "trace_io_uring_prep_rw")
+                    prep_attached = True
+                    if self.developer_mode:
+                        logger("info", f"io_uring SQE capture enabled via {sym.decode()}")
+                    break
+            if not prep_attached:
+                for sym in (b'io_prep_readv', b'io_prep_writev',
+                            b'io_prep_read', b'io_prep_write',
+                            b'io_prep_read_fixed', b'io_prep_write_fixed'):
+                    if BPF.get_kprobe_functions(sym):
+                        self.add_kprobe(sym.decode(), "trace_io_uring_prep_rw")
+                        prep_attached = True
+                if self.developer_mode and prep_attached:
+                    logger("info", "io_uring SQE capture enabled via per-op prep handlers")
+            if not prep_attached and self.developer_mode:
+                logger("warning", "io_uring SQE prep probe not available - opcode/fd/len/offset may be empty")
+
             # io_uring SQE submission probe (kprobe fallback for SUBMIT events)
             # Note: TRACEPOINT_PROBE(io_uring, io_uring_submit_sqe) in BPF is preferred
             if BPF.get_kprobe_functions(b'io_queue_sqe'):