Lab 7.1: Trace a Virtio-Block I/O End to End

Background

This is a trace-it lab. You will follow a single guest disk read from the moment the guest kernel issues it to the moment the guest sees the data come back — through the virtqueue, across the virtio-MMIO transport, into Firecracker's block device, down to a host pread on the backing file, and back via the used ring and an injected interrupt. By the end you will have seen, with your own tracing, every hop in the diagram from the Level 7 overview, and a guest disk read will no longer be a black box.

The virtio-block device is the right place to start because it is the simplest interesting device: one request queue (net has two, vsock has more, and a complex per-connection state machine), a fixed three-descriptor request shape (header / data / status), and a host side that is little more than "pop a chain, pread/pwrite, write the status byte." If you can trace block, every other virtio device is the same skeleton with different flesh.

Why This Lab Matters for Contributors

  • Almost every real block-device issue — a hang, a wrong byte count, a rate-limiter accounting bug, an io_uring vs Sync discrepancy — is debugged by walking exactly this path. You cannot fix what you cannot trace.
  • It makes the activate → process flow concrete: you will watch the device sit inert at boot and then come alive when the guest sets DRIVER_OK.
  • It connects three deep dives you must internalize: the virtqueues deep dive (the rings), virtio-transport-mmio (the doorbell), and virtio-block (the request semantics). Read them alongside this lab, not after.

Prerequisites

  • Levels 1–6 complete: you can build with tools/devtool, boot a microVM by hand, and read the vCPU run loop and VM exits (Level 4).
  • A built firecracker and a kernel + rootfs you can boot (from Lab 1.3).
  • Verify your checkout has the block device and the queue code:
# From the repo root. All three must return hits.
rg -l "impl VirtioDevice" src/vmm/src/devices/virtio/block/
rg -n "struct Queue\b"    src/vmm/src/devices/virtio/
rg -n "fn pread\|read_exact_at\|read_at\|pwrite" src/vmm/src/devices/virtio/block/

If a path is empty, the layout moved on your branch — find it by role (rg -l "impl VirtioDevice" src/vmm/src/devices/virtio/) rather than assuming the device is gone.

The Path You Are Tracing

sequenceDiagram
    participant GK as Guest kernel (virtio-blk driver)
    participant GM as Guest memory (virtqueue)
    participant KVM as KVM
    participant EM as EventManager (VMM thread)
    participant BLK as Block device (VirtioDevice)
    participant FS as Backing file (host)

    GK->>GM: 1. build descriptor chain: header | data(WRITE) | status(WRITE)
    GK->>GM: 2. avail.ring[idx]=head; avail.idx++
    GK->>KVM: 3. MMIO write to QueueNotify  (the "kick")
    KVM-->>EM: 4. ioeventfd signals -> epoll wakes the VMM thread
    EM->>BLK: 5. call the queue event handler (process_queue)
    BLK->>GM: 6. queue.pop(): read avail ring, walk descriptor chain
    BLK->>BLK: 7. parse virtio_blk_req header (type, sector)
    BLK->>FS: 8. pread(fd, data_buf, len, sector*512)   (or io_uring submit)
    FS-->>BLK: 9. bytes
    BLK->>GM: 10. write data into the WRITE descriptor's guest buffer
    BLK->>GM: 11. write status byte = VIRTIO_BLK_S_OK
    BLK->>GM: 12. queue.add_used(head, len); used.idx++
    BLK->>KVM: 13. raise IRQ via irqfd (InterruptStatus |= USED_RING)
    KVM-->>GK: 14. guest interrupt; driver reaps used ring -> read() returns

Keep this diagram open. Each step below maps to a number here.

Step-by-Step Tasks

Step 1: Find the block device and its entry points

You are mapping the device before you instrument it. The block device is split across a few files; find them by role, not by name.

# The device struct and its VirtioDevice impl.
rg -n "pub struct Block\b"        src/vmm/src/devices/virtio/block/
rg -n "impl VirtioDevice for"     src/vmm/src/devices/virtio/block/

# The activate() that wires the queue into the event loop (step 5 in the diagram).
rg -n "fn activate"               src/vmm/src/devices/virtio/block/

# The queue event handler — the function the EventManager calls on a kick.
# Names drift: try several.
rg -n "fn process_queue\|fn process\|fn handle_.*event\|fn request_queue" \
   src/vmm/src/devices/virtio/block/

# The request parsing + host I/O (header/data/status, pread/pwrite).
rg -n "VIRTIO_BLK_T_IN\|VIRTIO_BLK_T_OUT\|VIRTIO_BLK_S_OK\|struct RequestHeader\|fn execute" \
   src/vmm/src/devices/virtio/block/

Note: Firecracker's block device has historically had two backends selected by io_engine: Sync (plain pread/pwrite) and Async (io_uring). The synchronous path is the one to trace first — it is linear. Confirm which exist on your branch:

rg -n "io_engine\|IoEngine\|FileEngine\|Sync\|Async\|io_uring" src/vmm/src/devices/virtio/block/

Write down, in your reading log, the file:function for each of: the Block struct, its activate, its queue handler, and the function that does the actual pread/pwrite.

Step 2: Read the Queue type — how a chain is popped

Open the Queue and DescriptorChain code and answer three questions before you instrument anything.

rg -n "struct Queue\b"            src/vmm/src/devices/virtio/
rg -n "fn pop\b\|fn iter\|fn add_used\|next_descriptor\|DescriptorChain" \
   src/vmm/src/devices/virtio/
  • Where does pop read from? It reads avail.idx from guest memory, compares it to the queue's own next_avail cursor, and if there is new work, returns the head DescriptorChain — confirm by reading pop (or its equivalent).
  • How is the chain walked? DescriptorChain reads each virtq_desc (addr/len/flags/next) out of guest memory and follows next while the NEXT flag is set. The WRITE flag tells the device which descriptors it is allowed to write.
  • Where does completion go? add_used writes a virtq_used_elem{id,len} at used.ring[used.idx % size] and bumps used.idx — confirm the guest-memory writes.

Cross-reference the rust-vmm virtio-queue chapter: Firecracker's in-tree Queue and the rust-vmm crate implement the same spec logic; reading both makes the rules stick.

Step 3: Confirm the activate → process wiring

The device is built at boot but does not start processing until the guest finishes negotiation. Find the seam.

# activate() registers the queue eventfd(s) with the EventManager. Find what it subscribes.
rg -n "fn activate" -A 30 src/vmm/src/devices/virtio/block/ | rg -n "register\|subscribe\|Subscriber\|EventSet\|queue_evt"

# Where the device's queue eventfd is created and exposed (the ioeventfd the kick fires).
rg -n "queue_evt\|EventFd::new\|queue_events" src/vmm/src/devices/virtio/block/

Now connect it to KVM: the queue eventfd is registered with KVM as an ioeventfd so that a guest write to QueueNotify for that queue signals the eventfd without a userspace VM exit. Find where that registration happens (it is in the device manager / transport, not the device):

rg -n "register_ioevent\|IoEventAddress\|KVM_IOEVENTFD\|ioeventfd" src/vmm/src/

Tip: This is the single most important optimization in the whole device model. A naive design would take a KVM_EXIT_MMIO on every kick, exit to userspace, dispatch through the bus, and call the device. With ioeventfd, the kick is a kernel-side eventfd signal that the EventManager epoll loop is already waiting on — the vCPU thread barely pauses. See interrupts-and-irqchip and the-event-manager.

Step 4: Add tracing to the host side

You will instrument the block device's queue handler so you can see each I/O. The cleanest, no-recompile-of-the-world option is Firecracker's own logging — but for a trace you typically want explicit prints at the hops. Add temporary log calls (or eprintln!) at three points; keep them minimal and remove them before any PR.

#![allow(unused)]
fn main() {
// Inside the block device's queue handler (the fn you found in Step 1).
// 1. At the top of the handler, when the EventManager wakes us:
log::warn!("[trace] block kick: queue event fired");

// 2. Each time you pop a chain, after parsing the request header:
log::warn!(
    "[trace] block request: type={:?} sector={} data_len={}",
    request.r#type, request.sector, data_len
);

// 3. Right after the host read/write completes, before add_used:
log::warn!("[trace] block io done: status=OK len={}", len);
}

Find the exact struct field names first (request.sector etc. are illustrative — they will differ):

rg -n "struct Request\b\|struct RequestHeader\|sector\|r#type\|request_type" \
   src/vmm/src/devices/virtio/block/

Build with logging on:

tools/devtool build            # debug build is fine for tracing
ARCH=$(uname -m)
BIN=build/cargo_target/${ARCH}-unknown-linux-musl/debug/firecracker
ls -l "$BIN"

Warning: log::warn! lines only appear if you configure a logger. When you boot, point /logger at a file (or use --log-path) so you can tail -f it. The handler runs on the VMM thread; do not put blocking or slow code in it — you would stall the entire data plane.

Step 5: Boot with logging and watch the device activate

Boot a microVM from your traced build, with a logger so you can see the trace.

API=/tmp/fc-trace.sock
LOG=/tmp/fc-trace.log
rm -f "$API" "$LOG"; : > "$LOG"
sudo "$BIN" --api-sock "$API" &

curl -X PUT --unix-socket "$API" --data \
  '{"log_path":"'"$LOG"'","level":"Warning","show_level":true,"show_log_origin":true}' \
  http://localhost/logger

curl -X PUT --unix-socket "$API" --data \
  '{"kernel_image_path":"./vmlinux-6.1.x","boot_args":"console=ttyS0 reboot=k panic=1"}' \
  http://localhost/boot-source

curl -X PUT --unix-socket "$API" --data \
  '{"drive_id":"rootfs","path_on_host":"./ubuntu-24.04.ext4","is_root_device":true,"is_read_only":false}' \
  http://localhost/drives/rootfs

curl -X PUT --unix-socket "$API" --data \
  '{"vcpu_count":1,"mem_size_mib":1024}' http://localhost/machine-config

# In another terminal, watch the trace as the guest boots:
tail -f "$LOG"

curl -X PUT --unix-socket "$API" --data '{"action_type":"InstanceStart"}' http://localhost/actions

As the guest kernel boots, it mounts the rootfs — which is a virtio-block read. You should see a burst of [trace] block kick / block request / block io done lines as the kernel reads the filesystem. The first kicks appear only after the guest driver has negotiated features and set DRIVER_OK — i.e., after activate() ran. That ordering is the activate → process flow made visible.

Step 6: Generate a deliberate read and correlate it

Log into the guest over the serial console and issue a read you control, then find it in the trace.

# Inside the guest:
dd if=/dev/vda of=/dev/null bs=4096 count=256 iflag=direct
#   iflag=direct bypasses the page cache so each block actually hits the device.
# Or, if fio is present:
fio --name=r --filename=/dev/vda --rw=read --bs=4k --size=4m --direct=1

On the host, in the trace log, you will see a run of block requests with type=IN (read) and ascending sector values. Note the data_len — for a 4 KiB direct read you expect descriptor data lengths of 4096 (or 512-multiples), and the chain has the header descriptor, one or more data descriptors with the WRITE flag, and the status descriptor.

Step 7: Confirm the host-side I/O call

The last hop to nail down is the actual host syscall. You traced that it happened; now confirm which call. With the VMM thread's PID, watch the syscalls during a guest read:

# Find the firecracker process and its threads:
pgrep -a firecracker
# Strace the I/O syscalls on the backing file (run during a guest `dd`):
sudo strace -f -e trace=pread64,pwrite64,preadv,pwritev,io_uring_enter \
  -p "$(pgrep -n firecracker)" 2>&1 | head -40

You should see pread64/preadv (Sync engine) or io_uring_enter (Async engine) on the backing file's fd during the guest read. Match the offset to sector * 512 from your trace. That is step 8 of the sequence diagram: the guest's read() became a host pread on a flat file.

Note: Under the jailer the process is chrooted and may be PID-namespaced; for this lab run firecracker directly (no jailer) so strace -p and the backing-file path are straightforward. The jailer is Level 9.

Implementation Requirements / Deliverables

  • A reading log naming the file:function for each hop: Block struct, activate, the queue handler, the request parser, and the pread/pwrite call — each with the rg you used.
  • Trace output captured from a real guest boot, showing block kicks beginning only after the device activated.
  • Trace output from a deliberate dd/fio read, with type=IN, ascending sectors, and the data length you expected.
  • strace (or equivalent) output showing the host pread64/preadv/io_uring_enter on the backing file during the guest read, with the offset matching sector * 512.
  • A one-paragraph explanation of why a kick does not take a VM exit (the ioeventfd path).
  • All tracing code removed from your working tree afterward (it is never part of a PR).

Troubleshooting

No [trace] lines appear in the log

Either the logger is not configured (you must PUT /logger before InstanceStart, with a level at or below Warning), or your log::warn! is in a code path that does not run. Confirm the logger took effect by checking the log for Firecracker's own startup lines, then re-check that your trace is in the queue handler, not in activate (which runs once).

The guest hangs at boot after your edit

You likely put slow or blocking code in the queue handler, or broke the add_used/used-ring update so the guest never sees completions. The handler runs on the VMM thread and is on the critical path for every device. Remove logic from it, keep only the prints, and confirm add_used and the interrupt are still raised.

strace -p shows nothing on the backing file

You may be on the io_uring engine — trace io_uring_enter too. Or the reads are being served from the guest page cache — use iflag=direct / --direct=1. Or you are stracing the wrong thread; use -f to follow all threads of the process.

Kicks fire but data_len is always tiny / zero

You may be reading the header descriptor as the data descriptor. Re-read the chain: the first descriptor is the device-readable virtio_blk_req header, the middle descriptor(s) carry data (WRITE flag set for a read), and the last is the one-byte status. Walk the chain by NEXT, don't assume positions.

Expected Output

# In /tmp/fc-trace.log during a guest `dd if=/dev/vda ... iflag=direct`:
[Warning] [trace] block kick: queue event fired
[Warning] [trace] block request: type=IN sector=2048 data_len=4096
[Warning] [trace] block io done: status=OK len=4096
[Warning] [trace] block request: type=IN sector=2056 data_len=4096
[Warning] [trace] block io done: status=OK len=4096
...

# strace on the VMM process during the same read:
[pid NNNN] pread64(12, "...", 4096, 1048576) = 4096      # offset 1048576 == sector 2048 * 512

The exact numbers depend on your kernel, filesystem, and io_engine — what must be true is: kicks → requests with ascending sectors → host pread at sector*512 → status=OK.

Stretch Goals

  1. Trace a write. Remount the rootfs read-write (or attach a second scratch drive), dd into it, and watch type=OUT requests and host pwrite64. Note that the data descriptor for a write is device-readable (no WRITE flag) — the opposite of a read.
  2. Count the descriptor chain. Add a trace line that prints the number of descriptors in each chain and their flags. Confirm the three-descriptor header/data/status shape, and observe when the guest uses multiple data descriptors.
  3. Watch the interrupt side. Find where the device raises the IRQ (InterruptStatus, the irqfd / try_signal_used_queue-style call) and add a trace there. Correlate it to the guest driver reaping the used ring. See interrupts-and-irqchip.
  4. Compare engines. Boot once with the Sync io_engine and once with io_uring, run the same fio, and compare the host syscalls and throughput. Read the io-engines engineering chapter.
  5. Measure the no-exit kick. Temporarily disable/observe the ioeventfd path and reason about how many VM exits a naive design would take per I/O versus the ioeventfd design.

Validation / Self-check

Answer without notes; these gate completion.

  1. Which ring does the guest driver write to hand the device a new request, and which ring does the device write on completion? Who increments avail.idx and who increments used.idx?
  2. What are the three descriptors in a block-read chain, and which of them carry the WRITE flag? Why does the data descriptor carry WRITE on a read but not on a write?
  3. What exactly happens between the guest writing QueueNotify and the block device's queue handler running — and where does ioeventfd remove a VM exit?
  4. When is activate() called, and what does it register that makes subsequent kicks reach the device?
  5. Which host syscall served the guest read, and how did you map a guest sector to a host file offset?
  6. If you removed the add_used call from the handler, what would the guest observe, and why?
  7. Why must the queue handler stay fast and non-blocking, and which thread runs it?

Cross-references: virtqueues, virtio-transport-mmio, virtio-block, the-mmio-bus-and-device-manager, rust-vmm virtio-queue.

Next: Lab 7.2 — Virtqueues and the MMIO Transport.