blkparse how to show IO Scheduler message

Question

blktrace version v2.0.0

note: in blkparse output, the m in the sixth column indicate the line is scheduler information.

1. On Ubuntu 16.04 ext4 I can see the IO Scheduler message, blktrace -d /dev/sda -o - | blkparse -i -

   8,0    3        1     0.000000000 24714  A  WS 76519424 + 2048 <- (8,1) 76517376
   8,0    3        2     0.000000861 24714  Q  WS 76519424 + 2048 [TaskSchedulerFo]
   8,0    3        3     0.000005084 24714  X  WS 76519424 / 76520768 [TaskSchedulerFo]
   8,0    3        4     0.000008962 24714  G  WS 76519424 + 1344 [TaskSchedulerFo]
   8,0    3        5     0.000009379 24714  P   N [TaskSchedulerFo]
   8,0    3        6     0.000012021 24714  G  WS 76520768 + 704 [TaskSchedulerFo]
   8,0    3        7     0.000012622 24714  I  WS 76519424 + 1344 [TaskSchedulerFo]
   8,0    3        0     0.000015209     0  m   N cfq24714SN /user.slice insert_request
   8,0    3        0     0.000016074     0  m   N cfq24714SN /user.slice add_to_rr
   8,0    3        0     0.000017548     0  m   N cfq24714SN /user.slice preempt
   8,0    3        0     0.000018184     0  m   N cfq25055SN /user.slice slice expired t=1
   8,0    3        0     0.000018982     0  m   N cfq25055SN /user.slice resid=-2643710186
   8,0    3        0     0.000020125     0  m   N /user.slice served: vt=247310740068 min_vt=247310580285
   8,0    3        0     0.000021297     0  m   N cfq25055SN /user.slice sl_used=33325195 disp=13 charge=13 iops=1 sect=1088
   8,0    3        0     0.000021822     0  m   N cfq25055SN /user.slice del_from_rr
   8,0    3        0     0.000023767     0  m   N cfq workload slice:100000000
   8,0    3        0     0.000024496     0  m   N cfq24714SN /user.slice set_active wl_class:0 wl_type:1
   8,0    3        0     0.000025395     0  m   N cfq24714SN /user.slice dispatch_insert
   8,0    3        0     0.000026232     0  m   N cfq24714SN /user.slice dispatched a request
   8,0    3        0     0.000026818     0  m   N cfq24714SN /user.slice activate rq, drv=1
   8,0    3        8     0.000027030 24714  D  WS 76519424 + 1344 [TaskSchedulerFo]
   8,0    3        9     0.000037848 24714  U   N [TaskSchedulerFo] 1
   8,0    3       10     0.000038118 24714  P   N [TaskSchedulerFo]
   8,0    3       11     0.000048153 24714  A  WS 76521472 + 264 <- (8,1) 76519424
   8,0    3       12     0.000048340 24714  Q  WS 76521472 + 264 [TaskSchedulerFo]
   8,0    3       13     0.000049444 24714  M  WS 76521472 + 264 [TaskSchedulerFo]
   8,0    3       14     0.000050486 24714  I  WS 76520768 + 968 [TaskSchedulerFo]
   8,0    3        0     0.000051332     0  m   N cfq24714SN /user.slice insert_request
   8,0    3       15     0.000051755 24714  U   N [TaskSchedulerFo] 1
   8,0    3        0     0.000052418     0  m   N cfq24714SN /user.slice dispatch_insert
   8,0    3        0     0.000053068     0  m   N cfq24714SN /user.slice dispatched a request
   8,0    3        0     0.000053604     0  m   N cfq24714SN /user.slice activate rq, drv=2
   8,0    3       16     0.000053721 24714  D  WS 76520768 + 968 [TaskSchedulerFo]
   8,0    2        1     0.001844211     0  C  WS 76519424 + 1344 [0]
   8,0    2        0     0.001849143     0  m   N cfq24714SN /user.slice complete rqnoi
   

2. on CentOS 7.4 xfs,I can not see the IO Scheduler message, blktrace -d /dev/sdb -o - | blkparse -i -

   8,16  25        1     0.000000000 11966  Q   R 73400472 + 128 [fio]
   8,16  25        2     0.000006237 11966  G   R 73400472 + 128 [fio]
   8,16  25        3     0.000007806 11966  P   N [fio]
   8,16  25        4     0.000010836 11966  I   R 73400472 + 128 [fio]
   8,16  25        5     0.000011878 11966  U   N [fio] 1
   8,16  25        6     0.000013900 11966  D   R 73400472 + 128 [fio]
   8,16  10        1     0.008284979     0  C   R 73400472 + 128 [0]
   8,16  10        2     0.008343574 11966  Q   R 73400600 + 128 [fio]
   8,16  10        3     0.008345976 11966  G   R 73400600 + 128 [fio]
   8,16  10        4     0.008346908 11966  P   N [fio]
   8,16  10        5     0.008348926 11966  I   R 73400600 + 128 [fio]
   8,16  10        6     0.008349651 11966  U   N [fio] 1
   8,16  10        7     0.008350694 11966  D   R 73400600 + 128 [fio]
   8,16   8        1     0.008771249     0  C   R 73400600 + 128 [0]
   

Answer 1

While there are program version differences between the setups (in CentOS 7 blktrace is version 1.0.5 and the kernel is based off 3.10 whereas in Ubuntu 16.04 blktrace is version 1.1.0 and the kernel may be between 4.4 - 4.10) the real point may be down to what was asked (but unfortunately went unanswered) in one of the comments:

what [I/O] scheduler was in use

If we look at one of your m lines:

8,0    3        0     0.000015209     0  m   N cfq24714SN /user.slice insert_request

we can see that it is a textual message (hence the m) and that it likely came from the CFQ I/O scheduler (hence the cfq prefix on the message itself). If the I/O scheduler being used for the /dev/sdb device on the CentOS 7 setup was not CFQ (e.g. because the noop I/O scheduler was being used) then we cannot expect similar messages to be present.

So bringing this back to the title of the question:

blkparse how to show IO Scheduler message

If an I/O scheduler wants to it can send free form blktrace text (e.g. see block/cfq-iosched.c which has calls to blk_add_trace_msg() in it) but not all I/O schedulers do (e.g. see block/noop-iosched.c which doesn't even include the linux/blktrace_api.h header). By default blkparse will show all messages present unless you use the -M option to suppress them.