[PATCH V2 0/2] block: improve print_req_error

[PATCH V2 0/2] block: improve print_req_error

[Chaitanya Kulkarni]

Hi,

This patch-series is based on the initial patch posted by 
Christoph Hellwig <hch@lst.de>. I've added one more patch to improve
print message.

While debugging the driver and block layer this print message is very
handy.

Please consider this for 5.3.

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

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

I've fixed all the review comments except the one for which we want to
use the newly added function in the include/trace/events/f2fs.h as f2fs
code is highly coupled with the tracing structures. I'll make a separate
patch for that change as needed.

Thanks,
-Chaitanya

Changes from V1:-
1. Get rid of the function switch case and use the passtern similar to
   block/blk-mq-debuffs.c(Bart).

Chaitanya Kulkarni (1):
  block: add more debug data to print_req_err

Christoph Hellwig (1):
  block: improve print_req_error

 block/blk-core.c | 45 ++++++++++++++++++++++++++++++++++++++-------
 1 file changed, 38 insertions(+), 7 deletions(-)

-- 
2.19.1

[PATCH 1/2] 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 ee1b35fe8572..d1a227cfb72e 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,
@@ -1360,7 +1362,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 V2 2/2] block: add more debug data to print_req_err

[Chaitanya Kulkarni]

This patch adds more debug data on the top of the existing
print_req_error() where we enhance the print message with the printing
request operations in string format and other request fields.

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

diff --git a/block/blk-core.c b/block/blk-core.c
index d1a227cfb72e..6a8a808309f0 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -144,6 +144,32 @@ static const struct {
 	[BLK_STS_IOERR]		= { -EIO,	"I/O" },
 };
 
+#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),
+};
+
+static inline const char *op_str(int op)
+{
+	const char *op_str = "REQ_OP_UNKNOWN";
+
+	if (op < ARRAY_SIZE(op_name) && op_name[op])
+		op_str = op_name[op];
+
+	return op_str;
+}
+
 blk_status_t errno_to_blk_status(int errno)
 {
 	int i;
@@ -176,11 +202,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);
+		blk_rq_pos(req), req_op(req), 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

Re: [PATCH V2 2/2] block: add more debug data to print_req_err

[Bart Van Assche]

On 6/13/19 7:16 AM, Chaitanya Kulkarni wrote:
> +#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),
> +};
> +
> +static inline const char *op_str(int op)
> +{
> +	const char *op_str = "REQ_OP_UNKNOWN";
> +
> +	if (op < ARRAY_SIZE(op_name) && op_name[op])
> +		op_str = op_name[op];
> +
> +	return op_str;
> +}

If this patch gets applied there will be three copies in the upstream 
code that convert a REQ_OP_* constant into a string: one in blk-core.c, 
one in blk-mq-debugfs.c and one in include/trace/events/f2fs.h. Is it 
possible to avoid that duplication and have only one function that does 
the number-to-string conversion?

Bart.

Re: [PATCH V2 2/2] block: add more debug data to print_req_err

[Chaitanya Kulkarni]

On 06/13/2019 08:17 AM, Bart Van Assche wrote:
> On 6/13/19 7:16 AM, Chaitanya Kulkarni wrote:
>> +#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),
>> +};
>> +
>> +static inline const char *op_str(int op)
>> +{
>> +	const char *op_str = "REQ_OP_UNKNOWN";
>> +
>> +	if (op < ARRAY_SIZE(op_name) && op_name[op])
>> +		op_str = op_name[op];
>> +
>> +	return op_str;
>> +}
>
> If this patch gets applied there will be three copies in the upstream
> code that convert a REQ_OP_* constant into a string: one in blk-core.c,
> one in blk-mq-debugfs.c and one in include/trace/events/f2fs.h. Is it
> possible to avoid that duplication and have only one function that does
> the number-to-string conversion?
>
Okay let me work on this refactoring and send out V3.
> Bart.
>

Re: [PATCH V2 2/2] block: add more debug data to print_req_err

[Martin K. Petersen]

Bart,

> If this patch gets applied there will be three copies in the upstream
> code that convert a REQ_OP_* constant into a string: one in
> blk-core.c, one in blk-mq-debugfs.c and one in
> include/trace/events/f2fs.h. Is it possible to avoid that duplication
> and have only one function that does the number-to-string conversion?

People often have a hard time correlating SCSI and block error messages
with tracing output. So in general I'd like to see us not just trying to
standardize the helper functions, but the actual output.

I.e. I think it would be great to print exactly the same string for both
error log messages and tracepoints. Since Chaitanya is doing a lot of
work in this area anyway, that may be worth looking into?

-- 
Martin K. Petersen	Oracle Linux Engineering

Re: [PATCH V2 2/2] block: add more debug data to print_req_err

[Bart Van Assche]

On 6/13/19 9:53 AM, Martin K. Petersen wrote:
> 
> Bart,
> 
>> If this patch gets applied there will be three copies in the upstream
>> code that convert a REQ_OP_* constant into a string: one in
>> blk-core.c, one in blk-mq-debugfs.c and one in
>> include/trace/events/f2fs.h. Is it possible to avoid that duplication
>> and have only one function that does the number-to-string conversion?
> 
> People often have a hard time correlating SCSI and block error messages
> with tracing output. So in general I'd like to see us not just trying to
> standardize the helper functions, but the actual output.
> 
> I.e. I think it would be great to print exactly the same string for both
> error log messages and tracepoints. Since Chaitanya is doing a lot of
> work in this area anyway, that may be worth looking into?

Hi Martin,

I'm in favor of improving consistency. But are you sure that we can 
modify the tracing output format without breaking any applications?

Bart.

Re: [PATCH V2 2/2] block: add more debug data to print_req_err

[Martin K. Petersen]

Bart,

> I'm in favor of improving consistency. But are you sure that we can
> modify the tracing output format without breaking any applications?

Chaitanya is already working on enhancing tracing. I seem to recall
blktrace being fairly flexible with what it digests.

On top of that, we also have the option of changing the error path
output as opposed to changing the tracing ditto should that be an issue.

My main point is that there is probably going to be close to a 1:1
mapping between what you would want to see in an error message and what
you would want to see in tracing. So it would be good to use the same
plumbing for both.

-- 
Martin K. Petersen	Oracle Linux Engineering

Re: [PATCH 1/2] block: improve print_req_error

[Hannes Reinecke]

On 6/17/19 6:49 PM, Chaitanya Kulkarni wrote:
> On 06/17/2019 01:43 AM, Hannes Reinecke wrote:
>> On 6/11/19 10:02 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>
>>> ---
>>>   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 ee1b35fe8572..d1a227cfb72e 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,
>>> @@ -1360,7 +1362,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);
>>>
>>>
>> I did ask this already, but didn't get an answer:
>> Why do we have the __func__ argument?
>> Can it print anything else than 'blk_update_request' ?
>> If so, can't it be dropped?
> Thanks for looking into this. The caller argument I think is useful for 
> future use if this function gets called from different places.
> 
> Are you okay with that ?
> 
Yes, I am.

Reviewed-by: Hannes Reinecke <hare@suse.com>

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		   Teamlead Storage & Networking
hare@suse.de			               +49 911 74053 688
SUSE LINUX GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: Felix Imendörffer, Mary Higgins, Sri Rasiah
HRB 21284 (AG Nürnberg)

Re: [PATCH 1/2] block: improve print_req_error

[Chaitanya Kulkarni]

On 06/17/2019 01:43 AM, Hannes Reinecke wrote:
> On 6/11/19 10:02 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>
>> ---
>>   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 ee1b35fe8572..d1a227cfb72e 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,
>> @@ -1360,7 +1362,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);
>>
>>
> I did ask this already, but didn't get an answer:
> Why do we have the __func__ argument?
> Can it print anything else than 'blk_update_request' ?
> If so, can't it be dropped?
Thanks for looking into this. The caller argument I think is useful for 
future use if this function gets called from different places.

Are you okay with that ?

>
> Cheers,
>
> Hannes
>

Re: [PATCH 1/2] block: improve print_req_error

[Hannes Reinecke]

On 6/11/19 10:02 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>
> ---
>  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 ee1b35fe8572..d1a227cfb72e 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,
> @@ -1360,7 +1362,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);
>  
> 
I did ask this already, but didn't get an answer:
Why do we have the __func__ argument?
Can it print anything else than 'blk_update_request' ?
If so, can't it be dropped?

Cheers,

Hannes
-- 
Dr. Hannes Reinecke		   Teamlead Storage & Networking
hare@suse.de			               +49 911 74053 688
SUSE LINUX GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: Felix Imendörffer, Mary Higgins, Sri Rasiah
HRB 21284 (AG Nürnberg)

[PATCH 1/2] 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>
---
 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 ee1b35fe8572..d1a227cfb72e 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,
@@ -1360,7 +1362,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