Add block_bio_* tracing

[shastah]

Disclaimer: I don't necessarily need it merged as-is, but it may be helpful for others who stumble upon a similar problem.

I scratched my head today trying to explain the IO on a disk, as it wasn't showing up in iosnoop output in a manner that would allow me to pinpoint what exactly is that IO.

So I hacked in tracing block_bio_queue and block_bio_complete, et voila

COMM         PID    TYPE DEV      BLOCK        BYTES     LATms
ext4lazyinit 13030  W    253,18   5553305856   1048576     3.31
ext4lazyinit 13030  WS   253,18   5553307904   1048576     5.70
ext4lazyinit 13030  WS   253,23   1778432256   1048576     5.70
ext4lazyinit 13030  W    253,18   5553309952   1048576     6.61

This patch adds -B option that traces block_bio_queue and block_bio_complete instead of block_rq_*, and is mutually exclusive with -Q.

[brendangregg]

How is block_bio_queue different to block_rq_insert (ie, -Q)? I can see that they are called from different places, and have the plug/unplug stuff between them, but I'm wondering how we can neatly explain this and how it was affecting your workload? I'm happy with the change, just need to understand it first.

[shastah]

As far as I can tell, tracing block_rq_insert will not show mkfs.ext4 writes - it only shows the underlying disks (dev major 8):

# ./iosnoop -i '*W*' -Q 
(...)
md2_raid5    307    WS   8,0      105908240    4096       0.23
md2_raid5    307    WS   8,16     105908240    4096       0.28
md2_raid5    307    WS   8,32     105908240    4096       0.27
md2_raid5    307    WS   8,48     105908240    4096       0.26
md2_raid5    307    WS   8,0      105908232    512        0.25
md2_raid5    307    WS   8,16     105908232    512        0.29
md2_raid5    307    WS   8,32     105908232    512        0.28
md2_raid5    307    WS   8,48     105908232    512        0.28
(...)

While with -B, I can see write requests to other layers of my stack, namely 253: (dm/lvm) and 9: (md)

# ./iosnoop -i '*W*' -B
(...)
mkfs.ext4    19006  WS   253,7    17105049432  4096   13885.14
mkfs.ext4    19006  WS   253,10   3221900120   4096   13885.14
dmcrypt_writ 1669   WS   9,2      17105052512  4096      64.57
(...)

This is while doing mkfs.ext4 /dev/mapper/vgS-test. The setup is: four disks in a md_raid5 array, LUKS-encrypted volume on top of that, and LVM PV on top of it:

$ lsblk
(...)
sdd                    8:48   0  3.7T  0 disk  
(...)
|-sdd3                 8:51   0  3.6T  0 part  
| `-md2                9:2    0 10.8T  0 raid5 
|   `-pvcrypt        253:7    0 10.8T  0 crypt 
|     `-vgS-test     253:10   0    3T  0 lvm   
(...)
$