mbox series

[V5,0/5] block: improve print_req_error

Message ID 20190620175919.3273-1-chaitanya.kulkarni@wdc.com (mailing list archive)
Headers show
Series block: improve print_req_error | expand

Message

Chaitanya Kulkarni June 20, 2019, 5:59 p.m. UTC 
Hi,

This patch-series is based on the initial patch posted by
Christoph Hellwig <hch@lst.de>. While debugging the driver and block
layer this print message is very meaningful. Also, we centralize the
REQ_OP_XXX to the string conversion in the blk-core.c so that other
dependent subsystems can use this helper without having to duplicate
the code e.g. f2fs, blk-mq-debugfs.c.

Please consider this for 5.3.

In case someone is interested please find the test log for print_err_req
with null_blk, f2fs tracing and blk-mq-debugfs->blk_mq_debugfs_rq_show()
at the end of this patch.

Regards,
Chaitanya

Changes from V4:-

1. Add Reviewed-by.
2. Pull latest changes from for-next branch, build patches on the
   top of:-

commit 7262f3b8fe4b3c289fdc7ae345d33a0683e89e2c (origin/for-next)
Merge: e433e4d7957a 991d68ba7015
Author: Jens Axboe <axboe@kernel.dk>
Date:   Thu Jun 20 03:33:48 2019 -0600

    Merge branch 'for-5.3/block' into for-next
    
    * for-5.3/block: (29 commits)

Chaitanya Kulkarni (4):
  block: add centralize REQ_OP_XXX to string helper
  block: use blk_op_str() in blk-mq-debugfs.c
  block: update print_req_error()
  f2fs: use block layer helper for show_bio_op macro

Christoph Hellwig (1):
  block: improve print_req_error

 block/blk-core.c            | 55 ++++++++++++++++++++++++++++++++-----
 block/blk-mq-debugfs.c      | 24 +++-------------
 include/linux/blkdev.h      |  3 ++
 include/trace/events/f2fs.h | 11 +-------
 4 files changed, 56 insertions(+), 37 deletions(-)

A. Following is the sample error message with forced REQ_OP_WRITE,
   REQ_OP_WRITE_ZEROES and REQ_OP_DISCARD failure from modified
   null_blk for testing :-
------------------------------------------------------------------

[  489.013530] blk_update_request: I/O error, dev nullb0, sector 0 op 0x1:(WRITE) flags 0x8800 phys_seg 1 prio class 0
[  510.569833] blk_update_request: I/O error, dev nullb0, sector 0 op 0x9:(WRITE_ZEROES) flags 0x400800 phys_seg 0 prio class 0
[  557.009194] blk_update_request: I/O error, dev nullb0, sector 0 op 0x3:(DISCARD) flags 0x800 phys_seg 1 prio class 0

B. F2FS Tracing with this patch-series :-
-----------------------------------------
# 1. Format and mount device with f2fs :-
linux-block (for-next) # mkfs.f2fs -f  /dev/nvme0n1

	F2FS-tools: mkfs.f2fs Ver: 1.12.0 (2018-11-12)
        <snip>
	Info: format successful
linux-block (for-next) # mount /dev/nvme0n1 /mnt/nvme0n1

# 2.  Enable f2fs traces which are associated with the bio:-
linux-block (for-next) # cat /sys/kernel/debug/tracing/events/f2fs/f2fs_prepare_read_bio/enable
1
linux-block (for-next) # cat /sys/kernel/debug/tracing/events/f2fs/f2fs_prepare_write_bio/enable
1
linux-block (for-next) # cat /sys/kernel/debug/tracing/events/f2fs/f2fs_submit_page_bio/enable
1
linux-block (for-next) # cat /sys/kernel/debug/tracing/events/f2fs/f2fs_submit_read_bio/enable
1
linux-block (for-next) # cat /sys/kernel/debug/tracing/events/f2fs/f2fs_submit_write_bio/enable
1
# 3.  Issue I/O using dd(1) :-
linux-block (for-next) # dd of=/mnt/nvme0n1/data if=/dev/zero bs=4k count=100
100+0 records in
100+0 records out
409600 bytes (410 kB) copied, 0.00315802 s, 130 MB/s
linux-block (for-next) #
linux-block (for-next) #
# 4, Collect the trace
linux-block (for-next) # cat /sys/kernel/debug/tracing/trace_pipe
# 5. Following is the trimmed trace where we get rid of first few columns :-
f2fs_trace_pid: 103:  0 1af2 dd
f2fs_trace_ios: 103:  0    0 ----------------  3     0  2000         1600    1
f2fs_trace_pid: 103:  0  1e8 kworker/u24:5
f2fs_prepare_write_bio: dev = (259,0)/(259,0), rw = WRITE(S), DATA, sector = 53256, size = 4096
f2fs_submit_write_bio: dev = (259,0)/(259,0), rw = WRITE(S), DATA, sector = 53256, size = 4096
f2fs_trace_ios: 103:  0 1ace ----------------  1     1   800         1a01    1
f2fs_trace_ios: 103:  0  1e8 ----------------  2     1   800         1401    1
f2fs_prepare_write_bio: dev = (259,0)/(259,0), rw = WRITE(S), NODE, sector = 40968, size = 4096
f2fs_submit_write_bio: dev = (259,0)/(259,0), rw = WRITE(S), NODE, sector = 40968, size = 4096
f2fs_prepare_write_bio: dev = (259,0)/(259,0), rw = WRITE(S), NODE, sector = 45056, size = 4096
f2fs_submit_write_bio: dev = (259,0)/(259,0), rw = WRITE(S), NODE, sector = 45056, size = 4096
f2fs_trace_ios: 103:  0 1ace ----------------  2     1   800         1600    1
f2fs_prepare_write_bio: dev = (259,0)/(259,0), rw = WRITE(S|M|P), META, sector = 8192, size = 8192
f2fs_submit_write_bio: dev = (259,0)/(259,0), rw = WRITE(S|M|P), META, sector = 8192, size = 8192
f2fs_prepare_write_bio: dev = (259,0)/(259,0), rw = WRITE(S|M|P|PF|FUA), META_FLUSH, sector = 8208, size = 4096
f2fs_submit_write_bio: dev = (259,0)/(259,0), rw = WRITE(S|M|P|PF|FUA), META_FLUSH, sector = 8208, size = 4096
f2fs_trace_ios: 103:  0  1e8 ----------------  3     1  3800          400    3
f2fs_prepare_write_bio: dev = (259,0)/(259,0), rw = WRITE(), DATA, sector = 53264, size = 40960
f2fs_submit_write_bio: dev = (259,0)/(259,0), rw = WRITE(), DATA, sector = 53264, size = 40960
f2fs_trace_pid: 103:  0 1b16 dd
f2fs_trace_ios: 103:  0 1af2 ----------------  0     1 100000         1a02    a
f2fs_prepare_write_bio: dev = (259,0)/(259,0), rw = WRITE(), DATA, sector = 1064960, size = 409600
f2fs_submit_write_bio: dev = (259,0)/(259,0), rw = WRITE(), DATA, sector = 1064960, size = 409600

C. blk-mq-debugfs.c tests for __blk_mq_debugfs_rq_show() :-
-----------------------------------------------------------

# 1. Issue write-zeroes, disacrd and write operation on the null_blk
     with modified null_blk 

@@ -1180,6 +1207,20 @@ static blk_status_t null_handle_cmd(struct nullb_cmd *cmd)
                }
        }
+       /* just discard for write zeroes for now */
+       switch (req_op(cmd->rq)) {
+       case REQ_OP_DISCARD:
+               /* fall through */
+       case REQ_OP_WRITE_ZEROES:
+               mdelay(10000);
+               break;
+       case REQ_OP_WRITE:
+               mdelay(10000);
+       }
+
linux-block (for-next) # blkdiscard -z  -o 0 -l 40960 /dev/nullb0 
linux-block (for-next) # blkdiscard -o 0 -l 40960 /dev/nullb0 
linux-block (for-next) # dd if=/dev/zero of=/dev/nullb0 bs=4k count=1 oflag=direct

#2. Read the hctx busy file every second, each type of request should
    be block for 10 seconds and must appear in the hctx->busy file in
    the debugfs. This will lead to from block/blk-mq-debugfs.c : 
	{"busy", 0400, hctx_busy_show}
		hctx_show_busy_rq()
			__blk_mq_debugfs_rq_show()
				blk_op_str()

linux-block (for-next) # while [ 1 ]; do cat /sys/kernel/debug/block/nullb0/hctx0/busy ; sleep 1; done

0000000095104d0a {.op=WRITE_ZEROES, .cmd_flags=SYNC|NOUNMAP, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=48, .internal_tag=96}
0000000095104d0a {.op=WRITE_ZEROES, .cmd_flags=SYNC|NOUNMAP, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=48, .internal_tag=96}
0000000095104d0a {.op=WRITE_ZEROES, .cmd_flags=SYNC|NOUNMAP, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=48, .internal_tag=96}
0000000095104d0a {.op=WRITE_ZEROES, .cmd_flags=SYNC|NOUNMAP, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=48, .internal_tag=96}
0000000095104d0a {.op=WRITE_ZEROES, .cmd_flags=SYNC|NOUNMAP, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=48, .internal_tag=96}
0000000095104d0a {.op=WRITE_ZEROES, .cmd_flags=SYNC|NOUNMAP, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=48, .internal_tag=96}
0000000095104d0a {.op=WRITE_ZEROES, .cmd_flags=SYNC|NOUNMAP, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=48, .internal_tag=96}
0000000095104d0a {.op=WRITE_ZEROES, .cmd_flags=SYNC|NOUNMAP, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=48, .internal_tag=96}
0000000095104d0a {.op=WRITE_ZEROES, .cmd_flags=SYNC|NOUNMAP, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=48, .internal_tag=96}
0000000095104d0a {.op=WRITE_ZEROES, .cmd_flags=SYNC|NOUNMAP, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=48, .internal_tag=96}
0000000051de04b0 {.op=DISCARD, .cmd_flags=SYNC, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=47}
0000000051de04b0 {.op=DISCARD, .cmd_flags=SYNC, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=47}
0000000051de04b0 {.op=DISCARD, .cmd_flags=SYNC, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=47}
0000000051de04b0 {.op=DISCARD, .cmd_flags=SYNC, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=47}
0000000051de04b0 {.op=DISCARD, .cmd_flags=SYNC, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=47}
0000000051de04b0 {.op=DISCARD, .cmd_flags=SYNC, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=47}
0000000051de04b0 {.op=DISCARD, .cmd_flags=SYNC, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=47}
0000000051de04b0 {.op=DISCARD, .cmd_flags=SYNC, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=47}
0000000051de04b0 {.op=DISCARD, .cmd_flags=SYNC, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=47}
0000000051de04b0 {.op=DISCARD, .cmd_flags=SYNC, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=47}
0000000037e18909 {.op=WRITE, .cmd_flags=SYNC|IDLE, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=97}
0000000037e18909 {.op=WRITE, .cmd_flags=SYNC|IDLE, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=97}
0000000037e18909 {.op=WRITE, .cmd_flags=SYNC|IDLE, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=97}
0000000037e18909 {.op=WRITE, .cmd_flags=SYNC|IDLE, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=97}
0000000037e18909 {.op=WRITE, .cmd_flags=SYNC|IDLE, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=97}
0000000037e18909 {.op=WRITE, .cmd_flags=SYNC|IDLE, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=97}
0000000037e18909 {.op=WRITE, .cmd_flags=SYNC|IDLE, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=97}
0000000037e18909 {.op=WRITE, .cmd_flags=SYNC|IDLE, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=97}
0000000037e18909 {.op=WRITE, .cmd_flags=SYNC|IDLE, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=97}
0000000037e18909 {.op=WRITE, .cmd_flags=SYNC|IDLE, .rq_flags=STARTED|ELVPRIV|IO_STAT|STATS, .state=in_flight, .tag=49, .internal_tag=97}

Comments

Jens Axboe June 20, 2019, 7:04 p.m. UTC | #1 
On 6/20/19 11:59 AM, Chaitanya Kulkarni wrote:
> Hi,
> 
> This patch-series is based on the initial patch posted by
> Christoph Hellwig <hch@lst.de>. While debugging the driver and block
> layer this print message is very meaningful. Also, we centralize the
> REQ_OP_XXX to the string conversion in the blk-core.c so that other
> dependent subsystems can use this helper without having to duplicate
> the code e.g. f2fs, blk-mq-debugfs.c.
> 
> Please consider this for 5.3.
> 
> In case someone is interested please find the test log for print_err_req
> with null_blk, f2fs tracing and blk-mq-debugfs->blk_mq_debugfs_rq_show()
> at the end of this patch.

Applied, thanks.