Simple filesystem read/write tracing with /proc/sys/vm/block dump

From lxadm | Linux administration tips, tutorials, HOWTOs and articles
Jump to: navigation, search

Ever wondered what is hammering your disk so now and then, but couldn’t figure out with top / htop / iotop and similar? Annoying, but constant 100-200 kB/s writes? Or, simply blktrace was an overkill (or not supported by the kernel)?


To debug, try this one (setting block_dump to nonzero value enables block I/O debugging):

echo 1 > /proc/sys/vm/block_dump


Note that it will cause massive output in dmesg, so consider stopping syslog.

Example output suggests it was postgresql:

# dmesg
[3569957.224548] postmaster(3655): WRITE block 1509960 on vda2 (8 sectors)
[3569957.224552] postmaster(3655): WRITE block 1509968 on vda2 (8 sectors)
[3569957.300188] postmaster(3655): WRITE block 1509960 on vda2 (8 sectors)
[3569957.300198] postmaster(3655): WRITE block 1509968 on vda2 (8 sectors)
[3569957.404195] postmaster(3655): WRITE block 1509960 on vda2 (8 sectors)
[3569957.404203] postmaster(3655): WRITE block 1509968 on vda2 (8 sectors)
[3569957.420076] flush-252:64(4714): WRITE block 8 on vde1 (8 sectors)
[3569957.420084] flush-252:64(4714): WRITE block 5384 on vde1 (8 sectors)
[3569957.420087] flush-252:64(4714): WRITE block 5392 on vde1 (8 sectors)
[3569957.420090] flush-252:64(4714): WRITE block 12583024 on vde1 (8 sectors)
[3569957.455495] postmaster(3655): WRITE block 1509960 on vda2 (8 sectors)
[3569957.455503] postmaster(3655): WRITE block 1509968 on vda2 (8 sectors)
[3569957.501505] postmaster(3655): WRITE block 1509960 on vda2 (8 sectors)
[3569957.501514] postmaster(3655): WRITE block 1509968 on vda2 (8 sectors)
[3569957.555818] postmaster(3655): WRITE block 1509960 on vda2 (8 sectors)
[3569957.555824] postmaster(3655): WRITE block 1509968 on vda2 (8 sectors)
[3569957.664498] postmaster(3777): dirtied inode 162688 (pgstat.tmp) on vda2
[3569957.664561] postmaster(3777): WRITE block 1344144 on vda2 (8 sectors)
[3569957.664569] postmaster(3777): WRITE block 1344280 on vda2 (8 sectors)
[3569957.664572] postmaster(3777): WRITE block 1344288 on vda2 (8 sectors)
[3569957.664575] postmaster(3777): WRITE block 1344296 on vda2 (8 sectors)
[3569957.687476] postmaster(3655): WRITE block 1509960 on vda2 (8 sectors)
[3569957.687494] postmaster(3655): WRITE block 1509968 on vda2 (8 sectors)

Remember to stop this debugging output with (and possibly reenable syslog):

echo 0 > /proc/sys/vm/block_dump


Citing kernel's Documentation/laptops/laptop-mode.txt:

If you want to find out which process caused the disk to spin up, you can
gather information by setting the flag /proc/sys/vm/block_dump. When this flag
is set, Linux reports all disk read and write operations that take place, and
all block dirtyings done to files. This makes it possible to debug why a disk
needs to spin up, and to increase battery life even more. The output of
block_dump is written to the kernel output, and it can be retrieved using
"dmesg". When you use block_dump and your kernel logging level also includes
kernel debugging messages, you probably want to turn off klogd, otherwise
the output of block_dump will be logged, causing disk activity that is not
normally there.