Hi,

This is a little something I have played with. It allows you to see
exactly what is going on in the block layer for a given queue. Currently
it can logs request queueing and building, dispatches, requeues, and
completions. I've uploaded a little silly app to do dumps here:

http://www.kernel.org/pub/linux/kernel/people/axboe/tools/blktrace.c

Sample output looks like this:

wiggum:~ # ./blktrace /dev/sda
relay name: /relay/sda0
           0  3765 Q R 192-200
           5  3765 G R
          13  3765 M R [200-208]
          15  3765 M R [208-216]
          17  3765 M R [216-224]
          18  3765 M R [224-232]
          19  3765 M R [232-240]
          20  3765 M R [240-248]
          21  3765 M R [248-256]
         154  3765 M R [256-264]
         156  3765 M R [264-272]
         157  3765 M R [272-280]
         159  3765 M R [280-288]
         160  3765 M R [288-296]
         161  3765 M R [296-304]
         162  3765 M R [304-312]
         163  3765 M R [312-320]
         164  3765 M R [320-328]
         170  3765 M R [328-336]
         171  3765 M R [336-344]
         172  3765 M R [344-352]
         173  3765 M R [352-360]
         174  3765 M R [360-368]
         175  3765 M R [368-376]
         177  3765 M R [376-384]
         178  3765 M R [384-392]
         179  3765 Q R 392-400
         180  3765 G R
         181  3765 M R [400-408]
         182  3765 M R [408-416]
         183  3765 M R [416-424]
         184  3765 M R [424-432]
         185  3765 M R [432-440]
         186  3765 M R [440-448]
         187  3765 M R [448-456]
         189  3765 M R [456-464]
         190  3765 M R [464-472]
         191  3765 M R [472-480]
         193  3765 M R [480-488]
         194  3765 M R [488-496]
         196  3765 M R [496-504]
         197  3765 M R [504-512]
         228  3765 D R 192-392
         245  3765 D R 392-512
       14049     0 C R 192-392 [0]
       14067     0 D R 392-512
       14807     0 C R 392-512 [0]
Reads:  Queued:           2,      160KiB
        Completed:        2,      160KiB
        Merges:          38
Writes: Queued:           0,        0KiB
        Completed:        0,        0KiB
        Merges:           0
Events: 47
Missed events: 0

This is a log of a dd if=/dev/sda of=/dev/null bs=64k count=2 and it
shows queueing (Q) and allocation (G) of two requests, along with the
merges (M) that happens there. Finally you see dispatch (D) and
completion (C) of them as well. When sigint is received, blktrace dumps
stats of the current run.

It will work for scsi commands as well, so you can see what is going on
when cdrecord is talking to the device (the cdb is dumped, not the
data). The final integer printed in [] after a completion is the error,
0 for correct completion.

You can register interest in various events, see blktrace.c (grep for
buts and BLKSTARTTRACE).

Patch is against 2.6.13-rc6-mm2. I'm attaching a relayfs update from Tom
Zanussi as well, which is required to handle sub-buffer wrapping
correctly. You need to apply both patches to play with this - and make
sure to enable CONFIG_BLK_DEV_IO_TRACE in your .config, of course. And
blktrace.c relies on relayfs being mounted on /relay, add something ala

none                 /relay               relayfs    defaults 0 0

to your /etc/fstab to accomplish that (or do it manually, only
mentioning it for completeness).

-- 
Jens Axboe