Lab 12: Trace a Write

Background

write(fd, buf, 4096) returns in about a microsecond. The data reaches the device milliseconds later, or seconds later, or never if the machine loses power first.

This lab follows one write through every layer — syscall, VFS, page cache, filesystem, block layer, driver — and then follows the second half of the journey, which happens after the syscall has already returned. Then you add fsync() and watch what changes.

Why This Lab Matters

The gap between "the write returned" and "the data is safe" is where most data-loss bugs live.
Every layer has tracepoints, and connecting them is the skill: one write() becomes bios becomes requests becomes a device command, and the ratios tell you what the system is doing.
"The disk is slow" is almost never the diagnosis. This is how you find the real one.

Prerequisites

The VFS, The Block Layer, and Durability and Filesystems read.
A guest with a virtio-blk disk (not just an initramfs) — you need a real block device.
bpftrace, perf, and ideally fio in the guest.

Add a disk to your QEMU line if you have not:

qemu-img create -f qcow2 ~/kernel/lab-disk.qcow2 4G
# ...add to run-qemu.sh:
#   -drive file=$HOME/kernel/lab-disk.qcow2,if=virtio,cache=none
# ...then in the guest:
mkfs.ext4 /dev/vda && mkdir -p /mnt/d && mount /dev/vda /mnt/d

Predict First

write() of 4 KB to a file. How many bios reach the block layer before the syscall returns?
The same, followed by fsync(). How many now, and of what kinds?
50,000 sequential 4 KB buffered writes. How many bios? How many requests issued to the device?
The same, with O_DIRECT. Same two numbers.
How long after write() returns does the data reach the device, with no fsync?
Appending to a file versus overwriting in place: which produces more I/O, and why?

The Target

   write(fd, buf, 4096)
     └── ksys_write → vfs_write → f_op->write_iter
           └── generic_perform_write / iomap_file_buffered_write
                 ├── find or allocate the folio in the page cache
                 ├── copy_from_user into it
                 ├── mark it DIRTY
                 └── RETURN.  ← the syscall is over. Nothing has been written.

   ...later, asynchronously...

   writeback (per-bdi kworker)
     └── a_ops->writepages → the filesystem
           ├── map file offset → device blocks (extent lookup)
           ├── possibly allocate blocks, and JOURNAL that
           └── submit_bio()
                 └── blk_mq_submit_bio → merge, or allocate a request
                       └── mq_ops->queue_rq → the driver → the device
                             └── ...interrupt... → bio->bi_end_io
                                   └── folio is CLEAN

Step-by-Step Tasks

Step 1: Watch the syscall stop early

cd /mnt/d

sudo bpftrace -e '
  tracepoint:syscalls:sys_enter_write /comm == "dd"/    { @writes = count(); }
  tracepoint:block:block_bio_queue    /comm == "dd"/    { @bios_in_dd = count(); }
  tracepoint:block:block_bio_queue                       { @bios_total = count(); }' &

dd if=/dev/zero of=/mnt/d/f bs=4k count=1000 2>/dev/null
sleep 1
kill %1

PREDICT FIRST: @writes will be 1000. What will @bios_in_dd be — 1000, some smaller number, or zero? And how does @bios_total compare?

The answer is the whole point of the lab: the writing process issues almost no I/O. The bios come later, from a kworker, which is why @bios_in_dd and @bios_total differ.

# Who actually submits them:
sudo bpftrace -e 'tracepoint:block:block_bio_queue { @[comm] = count(); }' &
dd if=/dev/zero of=/mnt/d/f2 bs=4k count=5000 2>/dev/null; sync; kill %1

Step 2: Follow the layers, in one trace

sudo bpftrace -e '
  tracepoint:syscalls:sys_enter_write  /comm == "dd"/ { @1_syscall = count(); }
  kprobe:generic_perform_write                        { @2_pagecache = count(); }
  kprobe:submit_bio                                   { @3_submit_bio = count(); }
  tracepoint:block:block_bio_queue                    { @4_bio_queue = count(); }
  tracepoint:block:block_bio_backmerge                { @5_merged = count(); }
  tracepoint:block:block_rq_issue                     { @6_rq_issue[args.rwbs] = count(); }
  tracepoint:block:block_rq_complete                  { @7_rq_complete = count(); }' &

dd if=/dev/zero of=/mnt/d/f3 bs=4k count=50000 2>/dev/null
sync
kill %1

PREDICT FIRST, filling this in before running:

Counter	Prediction	Actual
`sys_enter_write`	50000
`generic_perform_write` (or the iomap equivalent)
`submit_bio`
`block_bio_queue`
`block_bio_backmerge`
`block_rq_issue`

The bio_queue ÷ rq_issue ratio is the merging, and it is usually the largest single factor in sequential write performance.

Note: If generic_perform_write does not fire, your filesystem uses iomap instead. Find the right symbol:
sudo bpftrace -l 'kprobe:*buffered_write*'
sudo bpftrace -l 'kprobe:iomap_*'
rg -n "write_iter" fs/ext4/file.c fs/xfs/xfs_file.c | head

Step 3: Measure the delay

sudo bpftrace -e '
  tracepoint:syscalls:sys_exit_write /comm == "dd"/ { @last_write = nsecs; }
  tracepoint:block:block_rq_issue /@last_write/ {
      @delay_ms = hist((nsecs - @last_write) / 1000000);
  }' &
dd if=/dev/zero of=/mnt/d/f4 bs=4k count=1000 2>/dev/null
sleep 40                       # do NOT sync: wait for dirty_expire
kill %1
grep -E '^Dirty' /proc/meminfo

PREDICT FIRST: with no sync and no memory pressure, how long before the data reaches the device? Check vm.dirty_expire_centisecs first and predict from it.

Step 4: Add `fsync` and watch it change

sudo bpftrace -e '
  tracepoint:block:block_rq_issue { @[args.rwbs] = count(); }' &

echo "--- no fsync"
dd if=/dev/zero of=/mnt/d/g1 bs=4k count=1000 2>/dev/null
sleep 2
echo "--- with fsync per write (O_DSYNC)"
dd if=/dev/zero of=/mnt/d/g2 bs=4k count=1000 oflag=dsync 2>/dev/null
kill %1

PREDICT FIRST: the rwbs strings you will see. Specifically: will F (flush) appear? FUA? How many of each per fsync?

Then the cost:

for f in "" "conv=fsync" "oflag=dsync" "oflag=direct"; do
  echo "== dd $f"
  dd if=/dev/zero of=/mnt/d/h bs=4k count=2000 $f 2>&1 | tail -1
done

PREDICT FIRST: rank the four by throughput, and predict the ratio between the fastest and slowest.

Step 5: The journal

ls /sys/kernel/tracing/events/jbd2/ 2>/dev/null
sudo bpftrace -e '
  tracepoint:jbd2:jbd2_start_commit { @commits = count(); }
  tracepoint:block:block_rq_issue /args.rwbs =~ /F/ { @flushes = count(); }
  tracepoint:block:block_rq_issue { @all_requests = count(); }' &

# Metadata-heavy: many small files, which means many journal transactions.
for i in $(seq 500); do echo x > /mnt/d/many-$i; done; sync
kill %1
rm -f /mnt/d/many-*

PREDICT FIRST: 500 file creations. How many journal commits? How many flushes? Why is the commit count much lower than 500?

Step 6: `O_DIRECT`, for contrast

sudo bpftrace -e '
  tracepoint:syscalls:sys_enter_write /comm == "dd"/ { @writes = count(); }
  tracepoint:block:block_bio_queue    /comm == "dd"/ { @bios_in_dd = count(); }
  tracepoint:block:block_rq_issue                    { @requests = count(); }' &
dd if=/dev/zero of=/mnt/d/direct bs=4k count=5000 oflag=direct 2>/dev/null
kill %1

PREDICT FIRST: with O_DIRECT, is @bios_in_dd now equal to @writes? What does that tell you about which context submits the I/O, and why direct I/O at 4 KB is slow?

Step 7: Latency, end to end

sudo bpftrace -e '
tracepoint:block:block_rq_issue {
	@start[args.dev, args.sector] = nsecs;
	@bytes = hist(args.nr_sector * 512);
}
tracepoint:block:block_rq_complete /@start[args.dev, args.sector]/ {
	@latency_us[args.rwbs] = hist((nsecs - @start[args.dev, args.sector]) / 1000);
	delete(@start[args.dev, args.sector]);
}' &
fio --name=mix --rw=randrw --bs=4k --size=256M --filename=/mnt/d/io \
    --direct=1 --iodepth=8 --runtime=20 --time_based 2>/dev/null | grep -E 'IOPS|clat'
kill %1

PREDICT FIRST: will reads and writes have the same latency distribution? On a virtio disk backed by a host file, which will be faster and why?

Implementation Requirements / Deliverables

A block device mounted in the guest, with a real filesystem.
The step-2 counter table, predicted then measured, with the merge ratio computed.
A demonstration that the writing process submits almost no I/O, and identification of which thread does.
The write-to-device delay measured with no sync, and explained from dirty_expire_centisecs.
The rwbs flags for fsync/O_DSYNC identified, including F and FUA if present.
The four-way throughput comparison, with predictions.
Journal commits counted for a metadata-heavy workload, and the ratio to file creations explained.
O_DIRECT contrasted with buffered, with the submitting context identified in each.
A block-I/O latency histogram, split by read/write.
One paragraph: given "the database is slow", what do you measure here first, in what order, and what does each result rule in or out?

Expected Output

$ sudo bpftrace ... ; dd if=/dev/zero of=/mnt/d/f bs=4k count=1000
@writes: 1000
@bios_in_dd: 0            ← the syscall submitted NOTHING
@bios_total: 34           ← a kworker did, later, after merging

$ sudo bpftrace -e 'tracepoint:block:block_bio_queue { @[comm] = count(); }'
@[kworker/u8:3]: 412      ← writeback
@[jbd2/vda-8]: 26         ← the journal thread
@[dd]: 0

The full pipeline for 50,000 sequential 4 KB writes:

@1_syscall:      50000
@2_pagecache:    50000
@3_submit_bio:     412     ← 121 writes coalesced per bio
@4_bio_queue:      412
@5_merged:         386     ← nearly all of them merged again
@6_rq_issue[W]:     26     ← TWENTY-SIX device requests for 50,000 writes
@7_rq_complete:     26

And with fsync:

@[FWFS]:  1000       ← flush + write + FUA + sync, one per fsync
@[W]:      812
@[F]:     1000       ← a cache flush per fsync. THIS is why fsync is slow.

Debugging Steps

No block I/O at all

You are writing to tmpfs or the initramfs, which has no backing device. df /mnt/d and check it is your virtio disk.

`generic_perform_write` never fires

Your filesystem uses iomap. Find the right symbol with bpftrace -l 'kprobe:*write*' and rg -n write_iter fs/<yourfs>/file.c.

`args.rwbs` is empty or missing

Field names differ between kernel versions:

sudo cat /sys/kernel/tracing/events/block/block_rq_issue/format
sudo bpftrace -lv 'tracepoint:block:block_rq_issue'

The numbers are wildly different from the expected output

Expected — they depend on the filesystem, the device, the block size, and the queue settings. What matters is the ratios: syscalls ≫ bios ≫ requests, and that they collapse in that direction.

`jbd2` tracepoints do not exist

You are not on ext4, or the journal is external. mount | grep /mnt/d, and for XFS use the xfs_log tracepoints instead.

Everything is instant and no I/O appears

Your qcow2 is being cached by the host. Use cache=none on the QEMU -drive line, or accept that you are measuring the host's page cache.

The latency histogram has two widely separated modes

That is real, and it is the answer to something: on a virtio disk it is usually host cache hits versus host disk access.

Experiment

CLAIM. "The disk is slow" is almost never the diagnosis, and the same workload can be dominated by four completely different bottlenecks depending on how it writes.

METHOD. Run the same 200 MB of data four ways, and for each collect: wall-clock time, device requests issued, flush count, and whether balance_dirty_pages was hit.

probe() {
  sudo bpftrace -e '
    tracepoint:block:block_rq_issue { @requests = count(); }
    tracepoint:block:block_rq_issue /args.rwbs =~ /F/ { @flushes = count(); }
    kprobe:balance_dirty_pages { @throttled = count(); }' &
  BP=$!; sleep 1; eval "$1"; sync; sleep 1; kill $BP
}

probe 'dd if=/dev/zero of=/mnt/d/x bs=4k   count=50000 2>&1 | tail -1'
probe 'dd if=/dev/zero of=/mnt/d/x bs=1M   count=200   2>&1 | tail -1'
probe 'dd if=/dev/zero of=/mnt/d/x bs=4k   count=50000 oflag=dsync 2>&1 | tail -1'
probe 'dd if=/dev/zero of=/mnt/d/x bs=4k   count=50000 oflag=direct 2>&1 | tail -1'

PREDICTION. Fill in the 4 × 4 table before running.

RESULT. Then name the dominant cost in each row. The four answers should be different, and they are, in order: merging works, merging plus fewer syscalls, a device flush per write, and no merging and full device latency per I/O.

Write one sentence per row of the form: "If a user reports X, this row is what is happening, and the measurement that identifies it is Y."

Test

cat > ~/kernel-labs/scripts/io-profile.sh <<'EOF'
#!/usr/bin/env bash
# The I/O profile of a command: syscalls vs bios vs requests, flushes,
# throttling, and latency. Run in the guest, as root.
set -euo pipefail
[ $# -ge 1 ] || { echo "usage: io-profile.sh <command> [args...]"; exit 2; }

bpftrace -e '
tracepoint:syscalls:sys_enter_write   { @1_write_syscalls = count(); }
kprobe:submit_bio                     { @2_submit_bio = count(); }
tracepoint:block:block_bio_backmerge  { @3_merges = count(); }
tracepoint:block:block_rq_issue       { @4_requests = count();
                                        @s[args.dev, args.sector] = nsecs; }
tracepoint:block:block_rq_issue /args.rwbs =~ /F/ { @5_FLUSHES = count(); }
kprobe:balance_dirty_pages            { @6_THROTTLED = count(); }
tracepoint:block:block_rq_complete /@s[args.dev, args.sector]/ {
	@latency_us = hist((nsecs - @s[args.dev, args.sector]) / 1000);
	delete(@s[args.dev, args.sector]);
}
END { clear(@s); }' -c "$*"
EOF
chmod +x ~/kernel-labs/scripts/io-profile.sh
sudo ~/kernel-labs/scripts/io-profile.sh dd if=/dev/zero of=/mnt/d/t bs=4k count=20000

Verify it discriminates: run it on the buffered and the oflag=dsync versions. If @5_FLUSHES is not dramatically different, the script is not measuring what it claims.

Challenge Extensions

Prove the directory-fsync problem. Write the atomic-replace pattern with and without the final fsync(dirfd), and use bpftrace to show that the version without it issues fewer flushes — then reason about exactly what a crash between them would leave behind.
Measure write amplification per filesystem. mkfs the same loop device as ext4, xfs, and btrfs, run the identical workload, and compare sectors written from /proc/diskstats against the payload. The differences are the filesystems' designs, made visible.
Find the readahead boundary. Read a large file with increasing stride and find the point where readahead gives up and every access becomes a major fault. Compare with /sys/block/*/queue/read_ahead_kb and with madvise(MADV_RANDOM).
Break merging on purpose. Write the same 200 MB in a random order rather than sequentially and measure the request count. That ratio is why sequential I/O is fast, quantified.
Write a blk-mq driver. Complete modules/04-ramdisk-block/ from the companion workspace: a RAM-backed block device with a real request handler. Then run this lab's measurements against your device and explain the differences from virtio.
Simulate power loss. Kill QEMU with SIGKILL mid-write (not a clean shutdown), reboot, and check what survived. Do it with data=ordered and data=writeback and compare. This is the only honest way to test crash consistency, and it is why "I killed the process" tests nothing.

Validation / Self-check

How many bios does a buffered write() submit before returning? Who submits them, and when?
Give the syscall → bio → request ratios you measured, and say what each collapse represents.
What determines the delay between write() returning and the device seeing the data?
Which rwbs flags appear for an fsync, and what does each ask the device to do?
Why is O_DIRECT at 4 KB slow? Name both reasons.
Why are there far fewer journal commits than file creations?
Rank buffered, conv=fsync, oflag=dsync, and oflag=direct by throughput, and explain the ordering.
Which thread submits writeback I/O, and which submits journal I/O? How did you find out?
Your latency histogram is bimodal. Give two plausible explanations and how you would distinguish them.
"The database is slow." Give your first three measurements, in order, and what each rules out.
Why does killing a process not test crash consistency? What does?
From the experiment: give the four dominant costs, one per row, in one sentence each.

Next: Networking — the other high-throughput path, and the one with the most tracepoints.

Open-Source Engineer & Contributor