blktrace

@amitmund September 11, 2026

Linux blktrace — Complete Learning Notes & Output Guide

blktrace is the low-level block layer I/O tracing facility built into the Linux kernel. It captures the complete lifecycle of every I/O request—from the moment a filesystem submits a buffer (bio), through I/O scheduler queues and merging, down to device driver dispatch and hardware completion.

1. What is blktrace?

blktrace stands for:

Block Layer Tracer

While iostat provides point-in-time rolling averages and biolatency provides logarithmic histograms, blktrace provides an event-by-event chronicle of the kernel block I/O pipeline.

Using the kernel relayfs / debugfs infrastructure, blktrace logs raw per-CPU binary trace streams that are subsequently parsed and formatted into human-readable text by blkparse or analyzed by btt (Block Trace Toolkit).

It answers the deepest storage diagnostic questions:

  • Where is time being spent: inside the application, waiting in OS kernel queues, or waiting for physical NAND/platter hardware response?
  • Are sequential requests being merged effectively into large transfers, or is I/O fragmenting into small requests?
  • How long do requests sit waiting for queue tags or scheduler dispatch slots?
  • What are the exact physical sector numbers being accessed across the partition?

2. Installation & Ecosystem Tools

blktrace is distributed as a standalone package containing multiple complementary utilities:

Tool Role
blktrace Kernel-space recorder that writes raw per-CPU binary trace streams to disk.
blkparse Formatter that reads raw binary traces and parses them into chronological event logs.
btrace A convenience wrapper script that runs blktrace and pipes live into blkparse.
btt Block Trace Toolkit: Post-processing analytical engine that computes exact pipeline latency stages (Q2G, G2I, I2D, D2C).
blkrawverify Validates consistency of raw trace files.

Debian / Ubuntu

sudo apt update
sudo apt install blktrace

RHEL / Rocky / AlmaLinux / CentOS

sudo dnf install blktrace

Arch Linux

sudo pacman -S blktrace

Verify:

blktrace -v

3. The Linux Block I/O Lifecycle (The Event Sequence)

Every I/O request traverses several well-defined phases inside the Linux kernel block layer. blktrace instruments each of these transitions with a unique action code:

       Application (write() / read())
                     |
                     v
             Filesystem (VFS)
                     |
                     v
+-------------------------------------------------------------+
|                     LINUX BLOCK LAYER                       |
|                                                             |
|   1. [A] Remap: Translates partition/LVM to physical disk. |
|   2. [Q] Queued: bio submitted to the block queue.         |
|   3. [G] Get Request: Allocates a struct request.           |
|   4. [M] Merged: Request merged with an existing queued I/O.|
|   5. [I] Inserted: Sent to I/O scheduler (mq-deadline/bfq).|
|   6. [D] Dispatched: Issued to the hardware device driver.  |
|                                                             |
+-------------------------------------------------------------+
                     |
                     v
+-------------------------------------------------------------+
|                    HARDWARE LAYER                           |
|                                                             |
|   7. [C] Completed: Storage controller returns ACK/data.    |
|                                                             |
+-------------------------------------------------------------+

4. Basic Syntax & Execution Modes

Because blktrace outputs binary files per CPU core, standard execution requires either piping to blkparse or using the btrace wrapper.

Method 1: Live Real-Time Tracing via btrace

sudo btrace /dev/sda


# 1. Record 10 seconds of raw trace data to files: <dev>.<cpu>
sudo blktrace -d /dev/sda -w 10

# 2. Parse the recorded binary dumps into a formatted report
blkparse -i sda -d sda.parse.out

5. Anatomy of the Standard blkparse Output Line

When parsed, every single block layer event is printed as a structured text line:

  8,0    2        1     0.000000000  4512  Q  WS 2457600 + 8 [python3]
  8,0    2        2     0.000001250  4512  G  WS 2457600 + 8 [python3]
  8,0    2        3     0.000002100  4512  I  WS 2457600 + 8 [python3]
  8,0    0        4     0.000005400     0  D  WS 2457600 + 8 [swapper/0]
  8,0    1        5     0.000128450     0  C  WS 2457600 + 8 [0]

6. Detailed Breakdown of Every Output Heading & Field

+---------+-----+-----+---------------+------+--------+------+---------------+-----------+
| Device  | CPU | Seq | Timestamp     | PID  | Action | RWBS | Sector + Size | Process   |
+---------+-----+-----+---------------+------+--------+------+---------------+-----------+
|   8,0   |  2  |  1  | 0.000000000   | 4512 |   Q    |  WS  | 2457600 + 8   | [python3] |
+---------+-----+-----+---------------+------+--------+------+---------------+-----------+

6.1 Device (8,0)

  • Format: Major,Minor device numbers.
  • Meaning: Identifies the Linux block device handle. 8,0 corresponds to /dev/sda, 8,16 to /dev/sdb, 259,0 to /dev/nvme0n1.

6.2 CPU (2)

  • Meaning: The logical CPU core on which the kernel event was processed.

6.3 Seq (Sequence Number, 1)

  • Meaning: Monotonically increasing sequence integer per trace session. Used to detect dropped events or out-of-order execution across multiple cores.

6.4 Timestamp (0.000000000)

  • Format: Seconds.Nanoseconds elapsed since trace initialization.
  • Troubleshooting Significance: High-resolution timing used to calculate microsecond and nanosecond intervals between consecutive pipeline stages.

6.5 PID (4512)

  • Meaning: The Process ID that initiated the operation. If an action is processed in an interrupt handler or kernel worker context upon completion, this may display 0 (idle task / kernel context).

6.6 Action (Event Stage Code, Q)

  • Meaning: The specific block lifecycle state being transitioned through. (Full list decoded in Section 7).

6.7 RWBS (I/O Type & Flags, WS)

  • Meaning: Direction and attributes of the request (e.g., Write, Synchronous). (Full list decoded in Section 8).

6.8 Sector + Size (2457600 + 8)

  • Format: Starting_Sector + Number_of_Sectors
  • Sector Size: Standard Linux block layer calculations assume 512 bytes per sector.
  • Byte Calculation:

$$\text{Bytes} = 8 \text{ sectors} \times 512\text{ bytes} = 4096\text{ bytes (4 KB)}$$

  • Troubleshooting Significance: Consecutive sector numbers reveal sequential streaming. Disjointed, widely varying sector numbers indicate random I/O seeking.

6.9 Process ([python3])

  • Meaning: The executable command name of the thread owning the operation. In completion events (C), this often displays [0] or the return status code.

7. Deep-Dive: Action / Event Codes

The single-character Action code indicates the exact block-layer transition point:

Code Name Technical Meaning
A Remap The I/O was remapped to a different device or partition (e.g., translating a logical volume or MD-RAID block to a physical disk sector).
Q Queued A bio request from the filesystem or memory manager has entered the block device queue.
G Get Request A new struct request structure was allocated from the block layer request pool.
M Merged The request was contiguous with a previously queued request and merged into a single larger request.
F Front Merge Merged to the beginning of an existing request in the queue.
B Bounce Memory buffer resides in high memory and required bouncing through a low-memory DMA buffer.
I Inserted The request was submitted to the I/O scheduler (e.g., mq-deadline, bfq).
D Dispatched The request left the scheduler queue and was sent down to the physical device driver/controller.
C Completed The storage device signaled completion via hardware interrupt; the driver finalized the request.
P Plug The queue was plugged (temporarily paused) to allow subsequent requests to accumulate and merge.
U Unplug The queue was unplugged; queued requests are released for dispatch.
S Sleep The process was put to sleep waiting for an available request descriptor due to queue exhaustion.

8. Deep-Dive: RWBS Flags

The RWBS field denotes the read/write direction and operational modifiers:

Flag Character Name Technical Meaning
R Read Data is being fetched from disk into memory.
W Write Data is being transferred from memory to non-volatile storage.
D Discard / TRIM Deallocates flash blocks on SSDs/NVMe drives.
S Synchronous The application thread is blocking until the I/O completes.
A Read Ahead Speculative read issued by the OS kernel ahead of current pointer.
M Metadata Filesystem superblock, inode, or directory tree metadata operation.
F FUA Force Unit Access: Writes must bypass device volatile write caches and commit directly to flash/magnetic media.
B Barrier / Flush Flush command issued to ensure previously written data is safely committed before continuing.
N None No direction specified (often used for queue management commands).

Common Combinations

  • WS: Synchronous Write (e.g., database WAL commits, fsync).
  • RA: Read-Ahead read.
  • WM: Metadata Write (allocating inodes or updating filesystem tables).
  • WSF: Synchronous Write with Force Unit Access (high-durability transactional write).

9. Post-Processing with btt (Block Trace Toolkit)

btt analyzes the raw trace data produced by blktrace and breaks down where latency occurred across the kernel lifecycle:

# Run btt against parsed trace data
btt -i sda.parse.out

Raw btt Output Example

==================== All Devices ====================

            ALL               MIN           AVG           MAX           N
--------------- ------------- ------------- ------------- -----------
Q2G             0.000000850   0.000001240   0.000045100       10420
G2I             0.000000420   0.000000910   0.000012400       10420
I2D             0.000001100   0.004501200   0.085420100       10420
D2C             0.000120400   0.000850120   0.012450800       10420
Q2C             0.000125400   0.005353470   0.097883300       10420

The 5 Critical Latency Stages

       Q (Queued)
           |
           |---> Q2G: Time to allocate a request structure
           v
       G (Get Request)
           |
           |---> G2I: Time to prepare and insert into scheduler
           v
       I (Inserted)
           |
           |---> I2D: Time spent sitting in scheduler / OS queue (Queue Delay)
           v
       D (Dispatched)
           |
           |---> D2C: Physical Hardware Service Time (Drive Controller Latency)
           v
       C (Completed)

   ========================================================================
   Total End-to-End Latency = Q2C (Queue to Completion)
   ========================================================================
Latency Metric Description Diagnostic Significance
Q2G Queue to Get Request Delays here indicate request pool exhaustion (nr_requests ceiling reached).
G2I Get Request to Insert Usually negligible; delays indicate memory allocator locks.
I2D Insert to Dispatch OS Queuing Delay. Long I2D times mean requests are stalled waiting for hardware queue tags or block scheduler slots.
D2C Dispatch to Complete Hardware Service Time. Long D2C times indicate slow physical NAND/disk media, SAN network delays, or bad sectors.
Q2C Total Latency Overall duration from initial kernel submission to final completion.

10. blktrace vs. iostat vs. biosnoop vs. biolatency

Feature blktrace + btt iostat -x biosnoop (eBPF) biolatency (eBPF)
Primary Scope Full kernel queue pipeline High-level device averages Driver dispatch & completion Logarithmic latency histograms
OS Queue Time (I2D) Yes (exact nanoseconds) Estimated via aqu-sz Yes (via -Q) Yes (via -Q)
Hardware Latency (D2C) Yes (exact nanoseconds) Estimated via await Yes Yes
Request Merging Visibility Full (M, F events) Output averages (rrqm/s) No No
Sector / LBA Tracking Yes (exact sector numbers) No Yes No
Overhead Moderate to High Zero (Reads /proc) Moderate Negligible
Storage Consumption Writes large binary traces None Terminal output only None (in-kernel maps)

11. Real-World Troubleshooting Scenarios

Scenario A: Diagnosing Host Queue Congestion vs. Hardware Storage Failure

A server experiences 100ms I/O latency spikes. You need to know whether the physical drive is dying or if the Linux kernel scheduler is backlogged.

Run blktrace and parse with btt:

sudo btrace /dev/sda -w 10 -o trace_run
btt -i trace_run.parse.out
  • Case 1: I2D = 95ms, D2C = 5ms: The physical disk responded in only 5ms. The 95ms stall occurred in I2D, proving the bottleneck is host OS queue congestion (e.g., queue depth too shallow, wrong I/O scheduler, or block layer lock contention).
  • Case 2: I2D = 1ms, D2C = 99ms: The OS handed the request to the hardware immediately, but the drive took 99ms to return. The bottleneck is physical storage hardware (bad sectors, flash controller thermal throttling, or cloud EBS bandwidth exhaustion).

Scenario B: Verifying Sequential I/O Merging Efficiency

A data ingestion service writes 4KB records continuously. You want to verify whether the Linux block layer is merging them into efficient 128KB transfers before hitting disk:

sudo btrace /dev/sda | grep -E "( M | D )"
  • Healthy Merging: You see numerous M (Merge) events followed by a single D (Dispatch) with a large sector size (+ 256).
  • Unmerged / Fragmented I/O: Every Q event is followed immediately by a D event with + 8 (4KB) and zero M events, proving that writes are unbuffered and bypassing scheduler merging.

12. Important Interview Questions & Answers

Q: What is the operational distinction between the I2D and D2C latency stages in btt?

Answer: I2D (Insert to Dispatch) measures the time a request spent waiting inside the Linux kernel block layer and I/O scheduler queues before being handed off to the device driver. D2C (Dispatch to Completion) measures the time from when the device driver sent the request to the storage controller until the storage hardware completed the transfer and triggered an interrupt. High I2D points to OS scheduler misconfigurations or queue depth exhaustion, while high D2C points to physical disk saturation or hardware bottlenecks.

Q: What does an A (Remap) event in blkparse indicate?

Answer: An A event indicates that an I/O request targeting a logical partition (e.g., /dev/sda1), device-mapper target (LVM, LUKS encryption), or MD-RAID array was remapped by the kernel block layer to its underlying physical disk and physical starting sector address.

Q: Why is blktrace typically run for short windows (10–30 seconds) rather than left running continuously?

Answer: blktrace records high-volume binary trace records for every block layer event across all CPU cores into /sys/kernel/debug/tracing via relayfs. On a storage subsystem processing 50,000 to 100,000 IOPS, blktrace can generate gigabytes of trace data per minute, consuming significant disk space and introducing I/O interference if the trace data is written to the same storage controller being monitored.

0 Likes
2 Views
0 Comments

Filters

No filters available for this view.

Reset All