[PATCH V3 0/6] block: improve print_req_error

[PATCH V3 0/6] block: improve print_req_error

[Chaitanya Kulkarni]

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 since V2:-

1. Add a centralized definition of the REQ_OP_XXX string array in the
   blk-core so that it will be available to other dependent subsystems
   as well.
2. Adjust the code and use blk_op_str() in the blk-mq-debugfs.c
3. Adjust the code and use blk_op_str() in the f2fs tracing.

Chaitanya Kulkarni (5):
  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 REQ_OP_XXX
  f2fs: get rid of duplicate code for in tracing

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 | 20 +++-----------
 4 files changed, 59 insertions(+), 43 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}


-- 
2.19.1

[PATCH V3 1/6] block: improve print_req_error

[Chaitanya Kulkarni]

From: Christoph Hellwig <hch@lst.de>

Print the calling function instead of print_req_error as a prefix, and
print the operation and op_flags separately instead of the whole field.

Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
Signed-off-by: Christoph Hellwig <hch@lst.de>
---
 block/blk-core.c | 16 +++++++++-------
 1 file changed, 9 insertions(+), 7 deletions(-)

diff --git a/block/blk-core.c b/block/blk-core.c
index 8340f69670d8..6753231b529b 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -167,18 +167,20 @@ int blk_status_to_errno(blk_status_t status)
 }
 EXPORT_SYMBOL_GPL(blk_status_to_errno);
 
-static void print_req_error(struct request *req, blk_status_t status)
+static void print_req_error(struct request *req, blk_status_t status,
+		const char *caller)
 {
 	int idx = (__force int)status;
 
 	if (WARN_ON_ONCE(idx >= ARRAY_SIZE(blk_errors)))
 		return;
 
-	printk_ratelimited(KERN_ERR "%s: %s error, dev %s, sector %llu flags %x\n",
-				__func__, blk_errors[idx].name,
-				req->rq_disk ?  req->rq_disk->disk_name : "?",
-				(unsigned long long)blk_rq_pos(req),
-				req->cmd_flags);
+	printk_ratelimited(KERN_ERR
+		"%s: %s error, dev %s, sector %llu op 0x%x flags 0x%x\n",
+		caller, blk_errors[idx].name,
+		req->rq_disk ?  req->rq_disk->disk_name : "?",
+		blk_rq_pos(req), req_op(req),
+		req->cmd_flags & ~REQ_OP_MASK);
 }
 
 static void req_bio_endio(struct request *rq, struct bio *bio,
@@ -1373,7 +1375,7 @@ bool blk_update_request(struct request *req, blk_status_t error,
 
 	if (unlikely(error && !blk_rq_is_passthrough(req) &&
 		     !(req->rq_flags & RQF_QUIET)))
-		print_req_error(req, error);
+		print_req_error(req, error, __func__);
 
 	blk_account_io_completion(req, nr_bytes);
 
-- 
2.19.1

[PATCH V3 2/6] block: add centralize REQ_OP_XXX to string helper

[Chaitanya Kulkarni]

In order to centralize the REQ_OP_XXX to string conversion which can be
used in the block layer and different places in the kernel like f2fs,
this patch adds a new helper function along with an array similar to the
one present in the blk-mq-debugfs.c.

We keep this helper functionality centralize under blk-core.c instead of
blk-mq-debugfs.c since blk-core.c is configured using CONFIG_BLOCK and
it will not be dependent on blk-mq-debugfs.c which is configured using
CONFIG_BLK_DEBUG_FS which can be disabled when block layer debugging
is not needed by the user.

Next patch adjusts the code in the blk-mq-debugfs.c with newly
introduced helper.

Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
---
 block/blk-core.c       | 36 ++++++++++++++++++++++++++++++++++++
 include/linux/blkdev.h |  3 +++
 2 files changed, 39 insertions(+)

diff --git a/block/blk-core.c b/block/blk-core.c
index 6753231b529b..c92b5a16a27a 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -120,6 +120,42 @@ void blk_rq_init(struct request_queue *q, struct request *rq)
 }
 EXPORT_SYMBOL(blk_rq_init);
 
+#define REQ_OP_NAME(name) [REQ_OP_##name] = #name
+static const char *const blk_op_name[] = {
+	REQ_OP_NAME(READ),
+	REQ_OP_NAME(WRITE),
+	REQ_OP_NAME(FLUSH),
+	REQ_OP_NAME(DISCARD),
+	REQ_OP_NAME(SECURE_ERASE),
+	REQ_OP_NAME(ZONE_RESET),
+	REQ_OP_NAME(WRITE_SAME),
+	REQ_OP_NAME(WRITE_ZEROES),
+	REQ_OP_NAME(SCSI_IN),
+	REQ_OP_NAME(SCSI_OUT),
+	REQ_OP_NAME(DRV_IN),
+	REQ_OP_NAME(DRV_OUT),
+};
+#undef REQ_OP_NAME
+
+/**
+ * blk_op_str - Return string XXX in the REQ_OP_XXX.
+ * @op: REQ_OP_XXX.
+ *
+ * Description: Centralize block layer function to convert REQ_OP_XXX into
+ * string format. Useful in the debugging and tracing bio or request. For
+ * invalid REQ_OP_XXX it returns string "UNKNOWN".
+ */
+inline const char *blk_op_str(int op)
+{
+	const char *op_str = "UNKNOWN";
+
+	if (op < ARRAY_SIZE(blk_op_name) && blk_op_name[op])
+		op_str = blk_op_name[op];
+
+	return op_str;
+}
+EXPORT_SYMBOL_GPL(blk_op_str);
+
 static const struct {
 	int		errno;
 	const char	*name;
diff --git a/include/linux/blkdev.h b/include/linux/blkdev.h
index 592669bcc536..077a77a4a91c 100644
--- a/include/linux/blkdev.h
+++ b/include/linux/blkdev.h
@@ -867,6 +867,9 @@ extern void blk_execute_rq(struct request_queue *, struct gendisk *,
 extern void blk_execute_rq_nowait(struct request_queue *, struct gendisk *,
 				  struct request *, int, rq_end_io_fn *);
 
+/* Helper to convert REQ_OP_XXX to its string format XXX */
+extern const char *blk_op_str(int op);
+
 int blk_status_to_errno(blk_status_t status);
 blk_status_t errno_to_blk_status(int errno);
 
-- 
2.19.1

[PATCH V3 3/6] block: use blk_op_str() in blk-mq-debugfs.c

[Chaitanya Kulkarni]

Now that we've a helper function blk_op_str() to convert the
REQ_OP_XXX to string XXX, adjust the code to use that. Get rid of
the duplicate array op_name which is now present in the blk-core.c
which we renamed it to "blk_op_name" and open coding in the
blk-mq-debugfs.c.

Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
---
 block/blk-mq-debugfs.c | 24 ++++--------------------
 1 file changed, 4 insertions(+), 20 deletions(-)

diff --git a/block/blk-mq-debugfs.c b/block/blk-mq-debugfs.c
index f0550be60824..68b602d4d1b8 100644
--- a/block/blk-mq-debugfs.c
+++ b/block/blk-mq-debugfs.c
@@ -261,23 +261,6 @@ static int hctx_flags_show(void *data, struct seq_file *m)
 	return 0;
 }
 
-#define REQ_OP_NAME(name) [REQ_OP_##name] = #name
-static const char *const op_name[] = {
-	REQ_OP_NAME(READ),
-	REQ_OP_NAME(WRITE),
-	REQ_OP_NAME(FLUSH),
-	REQ_OP_NAME(DISCARD),
-	REQ_OP_NAME(SECURE_ERASE),
-	REQ_OP_NAME(ZONE_RESET),
-	REQ_OP_NAME(WRITE_SAME),
-	REQ_OP_NAME(WRITE_ZEROES),
-	REQ_OP_NAME(SCSI_IN),
-	REQ_OP_NAME(SCSI_OUT),
-	REQ_OP_NAME(DRV_IN),
-	REQ_OP_NAME(DRV_OUT),
-};
-#undef REQ_OP_NAME
-
 #define CMD_FLAG_NAME(name) [__REQ_##name] = #name
 static const char *const cmd_flag_name[] = {
 	CMD_FLAG_NAME(FAILFAST_DEV),
@@ -342,12 +325,13 @@ int __blk_mq_debugfs_rq_show(struct seq_file *m, struct request *rq)
 {
 	const struct blk_mq_ops *const mq_ops = rq->q->mq_ops;
 	const unsigned int op = rq->cmd_flags & REQ_OP_MASK;
+	const char *op_str = blk_op_str(op);
 
 	seq_printf(m, "%p {.op=", rq);
-	if (op < ARRAY_SIZE(op_name) && op_name[op])
-		seq_printf(m, "%s", op_name[op]);
-	else
+	if (strcmp(op_str, "UNKNOWN") == 0)
 		seq_printf(m, "%d", op);
+	else
+		seq_printf(m, "%s", op_str);
 	seq_puts(m, ", .cmd_flags=");
 	blk_flags_show(m, rq->cmd_flags & ~REQ_OP_MASK, cmd_flag_name,
 		       ARRAY_SIZE(cmd_flag_name));
-- 
2.19.1

[PATCH V3 4/6] block: update print_req_error()

[Chaitanya Kulkarni]

Improve the print_req_error with additional request fields which are
helpful for debugging. Use newly introduced blk_op_str() to print the
REQ_OP_XXX in the string format.

Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
---
 block/blk-core.c | 11 +++++++----
 1 file changed, 7 insertions(+), 4 deletions(-)

diff --git a/block/blk-core.c b/block/blk-core.c
index c92b5a16a27a..88a716c3dc56 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -212,11 +212,14 @@ static void print_req_error(struct request *req, blk_status_t status,
 		return;
 
 	printk_ratelimited(KERN_ERR
-		"%s: %s error, dev %s, sector %llu op 0x%x flags 0x%x\n",
+		"%s: %s error, dev %s, sector %llu op 0x%x:(%s) flags 0x%x "
+		"phys_seg %u prio class %u\n",
 		caller, blk_errors[idx].name,
-		req->rq_disk ?  req->rq_disk->disk_name : "?",
-		blk_rq_pos(req), req_op(req),
-		req->cmd_flags & ~REQ_OP_MASK);
+		req->rq_disk ? req->rq_disk->disk_name : "?",
+		blk_rq_pos(req), req_op(req), blk_op_str(req_op(req)),
+		req->cmd_flags & ~REQ_OP_MASK,
+		req->nr_phys_segments,
+		IOPRIO_PRIO_CLASS(req->ioprio));
 }
 
 static void req_bio_endio(struct request *rq, struct bio *bio,
-- 
2.19.1

[PATCH V3 5/6] f2fs: use block layer helper for REQ_OP_XXX

[Chaitanya Kulkarni]

Adjust the f2fs tracing code to use newly introduced block layer
function blk_op_str() which converts the REQ_OP_XXX into the string
XXX.

Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
---
 include/trace/events/f2fs.h | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/include/trace/events/f2fs.h b/include/trace/events/f2fs.h
index 53b96f12300c..ec4dba5a4c30 100644
--- a/include/trace/events/f2fs.h
+++ b/include/trace/events/f2fs.h
@@ -1045,7 +1045,8 @@ DECLARE_EVENT_CLASS(f2fs__submit_page_bio,
 		(unsigned long)__entry->index,
 		(unsigned long long)__entry->old_blkaddr,
 		(unsigned long long)__entry->new_blkaddr,
-		show_bio_type(__entry->op, __entry->op_flags),
+		blk_op_str(__entry->op),
+		show_bio_op_flags(__entry->op_flags),
 		show_block_temp(__entry->temp),
 		show_block_type(__entry->type))
 );
@@ -1097,7 +1098,8 @@ DECLARE_EVENT_CLASS(f2fs__bio,
 	TP_printk("dev = (%d,%d)/(%d,%d), rw = %s(%s), %s, sector = %lld, size = %u",
 		show_dev(__entry->target),
 		show_dev(__entry->dev),
-		show_bio_type(__entry->op, __entry->op_flags),
+		blk_op_str(__entry->op),
+		show_bio_op_flags(__entry->op_flags),
 		show_block_type(__entry->type),
 		(unsigned long long)__entry->sector,
 		__entry->size)
-- 
2.19.1

[PATCH V3 6/6] f2fs: get rid of duplicate code for in tracing

[Chaitanya Kulkarni]

Now that we have used the blk_op_str(), get rid of show_bio_type() and
show_bio_op() to eliminate the duplicate code.

Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
---
 include/trace/events/f2fs.h | 14 --------------
 1 file changed, 14 deletions(-)

diff --git a/include/trace/events/f2fs.h b/include/trace/events/f2fs.h
index ec4dba5a4c30..a8e4fe053e7c 100644
--- a/include/trace/events/f2fs.h
+++ b/include/trace/events/f2fs.h
@@ -73,20 +73,6 @@ TRACE_DEFINE_ENUM(CP_TRIMMED);
 			REQ_PREFLUSH | REQ_FUA)
 #define F2FS_BIO_FLAG_MASK(t)	(t & F2FS_OP_FLAGS)
 
-#define show_bio_type(op,op_flags)	show_bio_op(op),		\
-						show_bio_op_flags(op_flags)
-
-#define show_bio_op(op)							\
-	__print_symbolic(op,						\
-		{ REQ_OP_READ,			"READ" },		\
-		{ REQ_OP_WRITE,			"WRITE" },		\
-		{ REQ_OP_FLUSH,			"FLUSH" },		\
-		{ REQ_OP_DISCARD,		"DISCARD" },		\
-		{ REQ_OP_SECURE_ERASE,		"SECURE_ERASE" },	\
-		{ REQ_OP_ZONE_RESET,		"ZONE_RESET" },		\
-		{ REQ_OP_WRITE_SAME,		"WRITE_SAME" },		\
-		{ REQ_OP_WRITE_ZEROES,		"WRITE_ZEROES" })
-
 #define show_bio_op_flags(flags)					\
 	__print_flags(F2FS_BIO_FLAG_MASK(flags), "|",			\
 		{ REQ_RAHEAD,		"R" },				\
-- 
2.19.1

Re: [PATCH V3 6/6] f2fs: get rid of duplicate code for in tracing

[Chao Yu]

Hi Chaitanya,

On 2019/6/18 13:42, Chaitanya Kulkarni wrote:
> Now that we have used the blk_op_str(), get rid of show_bio_type() and
> show_bio_op() to eliminate the duplicate code.

I think we can merge 5/6 and 6/6 into one patch.

> 
> Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
> ---
>  include/trace/events/f2fs.h | 14 --------------
>  1 file changed, 14 deletions(-)
> 
> diff --git a/include/trace/events/f2fs.h b/include/trace/events/f2fs.h
> index ec4dba5a4c30..a8e4fe053e7c 100644
> --- a/include/trace/events/f2fs.h
> +++ b/include/trace/events/f2fs.h
> @@ -73,20 +73,6 @@ TRACE_DEFINE_ENUM(CP_TRIMMED);
>  			REQ_PREFLUSH | REQ_FUA)
>  #define F2FS_BIO_FLAG_MASK(t)	(t & F2FS_OP_FLAGS)
>  
> -#define show_bio_type(op,op_flags)	show_bio_op(op),		\

Could you just replace show_bio_op() with blk_op_str()? it's minor though.

Thanks,

> -						show_bio_op_flags(op_flags)
> -
> -#define show_bio_op(op)							\
> -	__print_symbolic(op,						\
> -		{ REQ_OP_READ,			"READ" },		\
> -		{ REQ_OP_WRITE,			"WRITE" },		\
> -		{ REQ_OP_FLUSH,			"FLUSH" },		\
> -		{ REQ_OP_DISCARD,		"DISCARD" },		\
> -		{ REQ_OP_SECURE_ERASE,		"SECURE_ERASE" },	\
> -		{ REQ_OP_ZONE_RESET,		"ZONE_RESET" },		\
> -		{ REQ_OP_WRITE_SAME,		"WRITE_SAME" },		\
> -		{ REQ_OP_WRITE_ZEROES,		"WRITE_ZEROES" })
> -
>  #define show_bio_op_flags(flags)					\
>  	__print_flags(F2FS_BIO_FLAG_MASK(flags), "|",			\
>  		{ REQ_RAHEAD,		"R" },				\
> 

Re: [PATCH V3 1/6] block: improve print_req_error

[Bart Van Assche]

On 6/17/19 10:42 PM, Chaitanya Kulkarni wrote:
> From: Christoph Hellwig <hch@lst.de>
> 
> Print the calling function instead of print_req_error as a prefix, and
> print the operation and op_flags separately instead of the whole field.
> 
> Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
> Signed-off-by: Christoph Hellwig <hch@lst.de>

Is Christoph the original author of this patch? In that case I think 
Christoph's signed-off-by should occur first and yours second. See also 
Documentation/process/submitting-patches.rst.

Bart.

Re: [PATCH V3 2/6] block: add centralize REQ_OP_XXX to string helper

[Bart Van Assche]

On 6/17/19 10:42 PM, Chaitanya Kulkarni wrote:
> +inline const char *blk_op_str(int op)
> +{
> +	const char *op_str = "UNKNOWN";
> +
> +	if (op < ARRAY_SIZE(blk_op_name) && blk_op_name[op])
> +		op_str = blk_op_name[op];
> +
> +	return op_str;
> +}

This won't work correctly if op < 0. If you have another look at the 
block layer debugfs code you will see that 'op' is has an unsigned type 
in that code. Please either change the type of 'op' from 'int' to 
'unsigned int' or change 'op < ARRAY_SIZE(blk_op_name)' into 
'(unsigned)op < ARRAY_SIZE(blk_op_name)'.

Thanks,

Bart.

Re: [PATCH V3 3/6] block: use blk_op_str() in blk-mq-debugfs.c

[Bart Van Assche]

On 6/17/19 10:42 PM, Chaitanya Kulkarni wrote:
> +	if (strcmp(op_str, "UNKNOWN") == 0)
>   		seq_printf(m, "%d", op);
> +	else
> +		seq_printf(m, "%s", op_str);

My opinion about using strcmp() to check whether or not 
req_opf-to-string conversion succeeded is that this is ugly ...

Bart.

Re: [PATCH V3 6/6] f2fs: get rid of duplicate code for in tracing

[Bart Van Assche]

On 6/18/19 12:19 AM, Chao Yu wrote:
> Hi Chaitanya,
> 
> On 2019/6/18 13:42, Chaitanya Kulkarni wrote:
>> Now that we have used the blk_op_str(), get rid of show_bio_type() and
>> show_bio_op() to eliminate the duplicate code.
> 
> I think we can merge 5/6 and 6/6 into one patch.

Yes please.

Bart.

Re: [PATCH V3 1/6] block: improve print_req_error

[Chaitanya Kulkarni]

On 6/18/19 8:21 AM, Bart Van Assche wrote:
> On 6/17/19 10:42 PM, Chaitanya Kulkarni wrote:
>> From: Christoph Hellwig <hch@lst.de>
>>
>> Print the calling function instead of print_req_error as a prefix, and
>> print the operation and op_flags separately instead of the whole field.
>>
>> Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
>> Signed-off-by: Christoph Hellwig <hch@lst.de>
> 
> Is Christoph the original author of this patch? In that case I think
> Christoph's signed-off-by should occur first and yours second. See also
> Documentation/process/submitting-patches.rst.
> 
> Bart.
> 

Okay I'll do so.

Re: [PATCH V3 2/6] block: add centralize REQ_OP_XXX to string helper

[Chaitanya Kulkarni]

On 6/18/19 8:26 AM, Bart Van Assche wrote:
> On 6/17/19 10:42 PM, Chaitanya Kulkarni wrote:
>> +inline const char *blk_op_str(int op)
>> +{
>> +	const char *op_str = "UNKNOWN";
>> +
>> +	if (op < ARRAY_SIZE(blk_op_name) && blk_op_name[op])
>> +		op_str = blk_op_name[op];
>> +
>> +	return op_str;
>> +}
> 
> This won't work correctly if op < 0. If you have another look at the
> block layer debugfs code you will see that 'op' is has an unsigned type
> in that code. Please either change the type of 'op' from 'int' to
> 'unsigned int' or change 'op < ARRAY_SIZE(blk_op_name)' into
> '(unsigned)op < ARRAY_SIZE(blk_op_name)'.
> 
Will change the op to unsigned in next version.
> Thanks,
> 
> Bart.
> 

Re: [PATCH V3 3/6] block: use blk_op_str() in blk-mq-debugfs.c

[Chaitanya Kulkarni]

On 6/18/19 8:28 AM, Bart Van Assche wrote:
> On 6/17/19 10:42 PM, Chaitanya Kulkarni wrote:
>> +	if (strcmp(op_str, "UNKNOWN") == 0)
>>    		seq_printf(m, "%d", op);
>> +	else
>> +		seq_printf(m, "%s", op_str);
> 
> My opinion about using strcmp() to check whether or not
> req_opf-to-string conversion succeeded is that this is ugly ...
> 
I didn't like that either, but I also don't want callers to repeat the 
string "UNKNOWN" or any other error string and return NULL from the
blk_top_str().

Do you have any suggestion or preference ?

> Bart.
> 

Re: [PATCH V3 6/6] f2fs: get rid of duplicate code for in tracing

[Chaitanya Kulkarni]

Thanks for the comments Chao.

On 6/18/19 12:19 AM, Chao Yu wrote:
> Hi Chaitanya,
> 
> On 2019/6/18 13:42, Chaitanya Kulkarni wrote:
>> Now that we have used the blk_op_str(), get rid of show_bio_type() and
>> show_bio_op() to eliminate the duplicate code.
> 
> I think we can merge 5/6 and 6/6 into one patch.
> 
>>
Will do it in a next version.
>> Signed-off-by: Chaitanya Kulkarni <chaitanya.kulkarni@wdc.com>
>> ---
>>   include/trace/events/f2fs.h | 14 --------------
>>   1 file changed, 14 deletions(-)
>>
>> diff --git a/include/trace/events/f2fs.h b/include/trace/events/f2fs.h
>> index ec4dba5a4c30..a8e4fe053e7c 100644
>> --- a/include/trace/events/f2fs.h
>> +++ b/include/trace/events/f2fs.h
>> @@ -73,20 +73,6 @@ TRACE_DEFINE_ENUM(CP_TRIMMED);
>>   			REQ_PREFLUSH | REQ_FUA)
>>   #define F2FS_BIO_FLAG_MASK(t)	(t & F2FS_OP_FLAGS)
>>   
>> -#define show_bio_type(op,op_flags)	show_bio_op(op),		\
> 
> Could you just replace show_bio_op() with blk_op_str()? it's minor though.
> 
Okay, that also can be done. Will replace it in a next version.

> Thanks,
> 
>> -						show_bio_op_flags(op_flags)
>> -
>> -#define show_bio_op(op)							\
>> -	__print_symbolic(op,						\
>> -		{ REQ_OP_READ,			"READ" },		\
>> -		{ REQ_OP_WRITE,			"WRITE" },		\
>> -		{ REQ_OP_FLUSH,			"FLUSH" },		\
>> -		{ REQ_OP_DISCARD,		"DISCARD" },		\
>> -		{ REQ_OP_SECURE_ERASE,		"SECURE_ERASE" },	\
>> -		{ REQ_OP_ZONE_RESET,		"ZONE_RESET" },		\
>> -		{ REQ_OP_WRITE_SAME,		"WRITE_SAME" },		\
>> -		{ REQ_OP_WRITE_ZEROES,		"WRITE_ZEROES" })
>> -
>>   #define show_bio_op_flags(flags)					\
>>   	__print_flags(F2FS_BIO_FLAG_MASK(flags), "|",			\
>>   		{ REQ_RAHEAD,		"R" },				\
>>
> 

Re: [PATCH V3 2/6] block: add centralize REQ_OP_XXX to string helper

[Chaitanya Kulkarni]

On 06/18/2019 08:26 AM, Bart Van Assche wrote:
> On 6/17/19 10:42 PM, Chaitanya Kulkarni wrote:
>> +inline const char *blk_op_str(int op)
>> +{
>> +	const char *op_str = "UNKNOWN";
>> +
>> +	if (op < ARRAY_SIZE(blk_op_name) && blk_op_name[op])
>> +		op_str = blk_op_name[op];
>> +
>> +	return op_str;
>> +}
>
> This won't work correctly if op < 0. If you have another look at the
> block layer debugfs code you will see that 'op' is has an unsigned type
> in that code. Please either change the type of 'op' from 'int' to
> 'unsigned int' or change 'op < ARRAY_SIZE(blk_op_name)' into
> '(unsigned)op < ARRAY_SIZE(blk_op_name)'.
>

Sorry I'm little confused here, even though op is defined as a unsigned 
int we print it as a "%d". So I think we need to keep that as it is or
I'll be happy to send a corrective patch to print it is using %u, your 
input will be very useful here.

Regarding the correctness, I think if one of the operand is unsigned 
then signed values are converted to unsigned valued implicitly.

However the exceptions is if the type of the operand with signed integer 
type can represent all of the values of the type of the operand with 
unsigned integer type, then the operand with unsigned integer type is 
converted to the type of the operand with signed integer type.

I'm wondering how would above scenario occur when comparing int and 
size_t. (unless on a platform int can fit all the values into size_t).
Since above comparison of the ARRAY_SIZE involves sizeof (size_t) type 
is a base unsigned integer value, even if op < 0 it will get converted 
into the unsigned and it will still work.

Please correct me if I'm wrong.

In order to validate my claim I ran a test with simple test module
here are the result:-

void test(void)
{
         pr_info("%s\n", blk_op_str(REQ_OP_READ));
         pr_info("%s\n", blk_op_str(REQ_OP_WRITE));
         pr_info("%s\n", blk_op_str(REQ_OP_FLUSH));
         pr_info("%s\n", blk_op_str(REQ_OP_DISCARD));
         pr_info("%s\n", blk_op_str(REQ_OP_SECURE_ERASE));
         pr_info("%s\n", blk_op_str(REQ_OP_ZONE_RESET));
         pr_info("%s\n", blk_op_str(REQ_OP_WRITE_SAME));
         pr_info("%s\n", blk_op_str(REQ_OP_WRITE_ZEROES));
         pr_info("%s\n", blk_op_str(REQ_OP_SCSI_IN));
         pr_info("%s\n", blk_op_str(REQ_OP_SCSI_OUT));
         pr_info("%s\n", blk_op_str(REQ_OP_DRV_IN));
         pr_info("%s\n", blk_op_str(REQ_OP_DRV_OUT));
         pr_info("LAST %s\n", blk_op_str(REQ_OP_LAST));
         pr_info("LAST + 1 %s\n", blk_op_str(REQ_OP_LAST + 1)); 

         pr_info("-1 %s\n", blk_op_str(-1));
         pr_info("-2 %s\n", blk_op_str(-2));
         pr_info("-3 %s\n", blk_op_str(-3));
         pr_info("-4 %s\n", blk_op_str(-4));
}

[  819.336023] READ
[  819.336030] WRITE
[  819.336034] FLUSH
[  819.336037] DISCARD
[  819.336041] SECURE_ERASE
[  819.336044] ZONE_RESET
[  819.336048] WRITE_SAME
[  819.336051] WRITE_ZEROES
[  819.336054] SCSI_IN
[  819.336058] SCSI_OUT
[  819.336061] DRV_IN
[  819.336064] DRV_OUT
[  819.336068] LAST UNKNOWN
[  819.336071] LAST + 1 UNKNOWN
[  819.336075] -1 UNKNOWN
[  819.336078] -2 UNKNOWN
[  819.336081] -3 UNKNOWN
[  819.336084] -4 UNKNOWN

I'll make this change op int->unsigned as it is present in the debugfs 
code so that it will be consistent, thanks again for looking into this.

> Thanks,
>
> Bart.
>

Re: [PATCH V3 2/6] block: add centralize REQ_OP_XXX to string helper

[Bart Van Assche]

On 6/18/19 3:00 PM, Chaitanya Kulkarni wrote:
> Regarding the correctness, I think if one of the operand is unsigned
> then signed values are converted to unsigned valued implicitly.
> 
> However the exceptions is if the type of the operand with signed integer
> type can represent all of the values of the type of the operand with
> unsigned integer type, then the operand with unsigned integer type is
> converted to the type of the operand with signed integer type.
> 
> I'm wondering how would above scenario occur when comparing int and
> size_t. (unless on a platform int can fit all the values into size_t).
> Since above comparison of the ARRAY_SIZE involves sizeof (size_t) type
> is a base unsigned integer value, even if op < 0 it will get converted
> into the unsigned and it will still work.
> 
> Please correct me if I'm wrong.

Since a long comment was needed to explain this, that means that the 
mental effort for anyone who wants to verify the blk_op_str() code is 
large. Please make sure that kernel code is easy to read and to verify.

Thanks,

Bart.