How to Use blktrace in Linux to Trace Block I/O Latency, Queue Depths, and Device Merges

Storage performance troubleshooting on enterprise Linux hosts often stalls when relying solely on macroscopic statistics from iostat or vmstat. While an average wait time (await) or disk utilisation figure (%util) indicates that a block device is congested, it cannot explain why. Latency may stem from application thread serialization, I/O scheduler queueing bottlenecks, device driver lock contention, or slow physical NAND flash garbage collection.

The Linux blktrace framework provides microsecond-resolution tracing of request lifecycles through the kernel block I/O layer. Coupled with blkparse and the Block Trace Toolkit (btt), systems engineers can deconstruct every I/O transaction into distinct timing phases, pinpointing storage scheduler inefficiencies and hardware submission stalls.

Architectural Overview: The Block I/O Request Lifecycle

Before a byte is read from or written to an NVMe SSD, SATA drive, or SAN LUN, an I/O operation traverses several discrete stages within the Linux kernel:

Stage / Action Code	Lifecycle Event Name	Kernel Event Description
A	Remap	Logical Volume Manager (LVM) or MD-RAID re-maps I/O from a virtual device to a physical sector.
Q	Queued	The I/O request arrives at the block layer from filesystem or user-space page cache flushers.
M	Back / Front Merge	The I/O operation is coalesced with a contiguous adjacent request already in the queue.
G	Get Request	The kernel allocates a formal struct request descriptor for the transaction.
I	Inserted	The request enters the I/O elevator/scheduler queue (e.g. mq-deadline, none, or kyber).
D	Dispatched	The scheduler submits the request to the low-level hardware device driver / controller queue.
C	Complete	The physical storage controller signals completion via interrupt; execution ends.

The total round-trip latency experienced by an application is Q2C (Queued to Complete). Tracing the intervals between these individual milestones exposes whether delays occur inside the operating system scheduler or inside the physical device controller.

Installing blktrace and Mounting debugfs

blktrace relies on the Linux kernel tracepoint infrastructure and relayfs to stream raw event buffers to disk with near-zero instrumentation overhead.

Step 1: Install the blktrace Suite

# Install blktrace and btt on Debian / Ubuntu
sudo apt update && sudo apt install -y blktrace

# Install on RHEL / Rocky Linux
sudo dnf install -y blktrace

Step 2: Verify debugfs Mount

Ensure that debugfs is mounted, as blktrace establishes trace endpoints under /sys/kernel/debug/block/:

# Verify debugfs is active
mount | grep debugfs

# If not mounted, mount it manually
sudo mount -t debugfs debugfs /sys/kernel/debug

Capturing Block I/O Traces with blktrace

To avoid trace logging from polluting the very storage device you are analysing, always write trace output files to a separate filesystem, a RAM disk (tmpfs), or an external mount.

Step 1: Prepare a RAM Disk Output Directory

# Create temporary scratch directory in memory
sudo mkdir -p /tmp/trace_data
sudo mount -t tmpfs -o size=1G tmpfs /tmp/trace_data
cd /tmp/trace_data

Step 2: Execute blktrace Against the Target Block Device

Capture 15 seconds of live I/O traffic on target block device /dev/nvme0n1:

# Capture trace on NVMe device for 15 seconds (-w 15)
# -d specifies the target block device
sudo blktrace -d /dev/nvme0n1 -w 15 -o nvme_trace

This generates per-CPU raw binary trace files (e.g. nvme_trace.blktrace.0, nvme_trace.blktrace.1).

Parsing Raw Event Streams with blkparse

The blkparse utility reassembles per-CPU binary buffers into a human-readable chronological event stream.

Step 1: Parse Binary Logs to Human-Readable Format

# Merge and parse trace files
blkparse -i nvme_trace -d nvme_trace.parsed | head -n 30

Step 2: Interpret Event Output Columns

A typical line emitted by blkparse looks like this:

259,0    3     1024     0.000124852  2489  Q   W 1048576 + 8 [mysqld]
259,0    3     1025     0.000125102  2489  G   W 1048576 + 8 [mysqld]
259,0    3     1026     0.000125540  2489  I   W 1048576 + 8 [mysqld]
259,0    3     1027     0.000126120     0  D   W 1048576 + 8 [swapper/3]
259,0    0     1028     0.000185900     0  C   W 1048576 [0]

• 259,0: Major and minor device numbers.
• 3: CPU core ID executing the tracepoint.
• 1024: Monotonic sequence number.
• 0.000124852: Timestamp relative to trace inception.
• 2489: Process ID (PID).
• Q / G / I / D / C: Lifecycle action code.
• W: Read/Write indicator (W for write, R for read, D for discard).
• 1048576 + 8: Starting block sector number and sector count (8 sectors = 4 KB).
• [mysqld]: Originating process command name.

Calculating Latency Breakdowns with the Block Trace Toolkit (btt)

Reading raw transaction lines manually is impractical across millions of operations. The btt command automates statistical analysis, aggregating intervals into definitive latency matrices:

# Process parsed trace file through btt
btt -i nvme_trace.parsed -o btt_report

Analyse the Timing Breakdown Table

Inspect the output in btt_report.avg:

Timing Phase	Component Interval	Interpretation & Diagnostic Indicator
Q2G	Queued to Get Request	Time spent waiting to allocate a request structure. High values indicate kernel request pool exhaustion (nr_requests).
G2I	Get Request to Insert	Time spent evaluating merging and elevator algorithms. Usually sub-microsecond.
I2D	Insert to Dispatch	Scheduler Queueing Latency: Time request sat waiting in the elevator queue before submission to device driver.
D2C	Dispatch to Complete	Hardware Service Time: Time physical hardware spent processing and completing the I/O transaction.
Q2C	Queued to Complete	Total End-to-End Latency: Sum of OS queueing delay and hardware service time.

If I2D accounts for 80% of total latency, the I/O scheduler is creating bottlenecks. If D2C accounts for 95% of latency, the storage media itself is saturated, throttling, or experiencing hardware write amplification.

Real-Time Interactive Profiling with btrace

For quick ad-hoc investigations, the wrapper script btrace combines blktrace and blkparse into a single real-time console stream:

# Stream live block I/O operations directly to terminal
sudo btrace /dev/nvme0n1

Troubleshooting Block I/O Bottlenecks and Trace Faults

Consult this diagnostic matrix to resolve tracing errors and performance findings:

Symptom	Probable Root Cause	Remediation Procedure
blktrace fails with “No such file or directory: /sys/kernel/debug/block”.	The kernel does not have CONFIG_BLK_DEV_IO_TRACE compiled, or debugfs is unmounted.	Mount debugfs via sudo mount -t debugfs debugfs /sys/kernel/debug. Verify kernel configuration with grep BLK_DEV_IO_TRACE /boot/config-$(uname -r).
High Q2G latency reported in btt output.	Kernel request descriptor exhaustion under heavy burst traffic.	Increase device queue size: echo 512 | sudo tee /sys/block/nvme0n1/queue/nr_requests.
High I2D latency while D2C remains low.	Sub-optimal I/O scheduler algorithm for fast NVMe storage.	Switch scheduler from mq-deadline or bfq to none for ultra-low latency NVMe drives: echo none | sudo tee /sys/block/nvme0n1/queue/scheduler.
Trace output reports “Dropped events”.	Disk write bandwidth on trace output directory could not keep pace with raw event volume.	Increase internal buffer sizing using -b 1024 -n 8 in blktrace command, and ensure output directory points to a tmpfs in-memory filesystem.

By leveraging blktrace and btt, Linux administrators transition from vague guesswork to empirical, phase-by-phase diagnostics, ensuring pinpoint remediation of enterprise storage latency.