[PATCH 0/2] block: improve print_req_error()

[PATCH 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
further print message.

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

Please consider this for 5.3.

-Chaitanya

Following is the sample error message with forced REQ_OP_WRITE failure
from null_blk:-

blk_update_request: I/O error, dev nullb0, sector 0 op 0x1:(write) flags 0x8800 phys_seg 1 prio class 0


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

Christoph Hellwig (1):
  block: improve print_req_error

 block/blk-core.c | 67 +++++++++++++++++++++++++++++++++++++++++++-----
 1 file changed, 60 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>
---
 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 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 | 57 +++++++++++++++++++++++++++++++++++++++++++++---
 1 file changed, 54 insertions(+), 3 deletions(-)

diff --git a/block/blk-core.c b/block/blk-core.c
index d1a227cfb72e..659e5ea6f6c9 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -167,6 +167,54 @@ int blk_status_to_errno(blk_status_t status)
 }
 EXPORT_SYMBOL_GPL(blk_status_to_errno);
 
+static inline const char *req_op_str(struct request *req)
+{
+       char *ret;
+
+       switch (req_op(req)) {
+       case REQ_OP_READ:
+               ret = "read";
+               break;
+       case REQ_OP_WRITE:
+               ret = "write";
+               break;
+       case REQ_OP_FLUSH:
+               ret = "flush";
+               break;
+       case REQ_OP_DISCARD:
+               ret = "discard";
+               break;
+       case REQ_OP_SECURE_ERASE:
+               ret = "secure_erase";
+               break;
+       case REQ_OP_ZONE_RESET:
+               ret = "zone_reset";
+               break;
+       case REQ_OP_WRITE_SAME:
+               ret = "write_same";
+               break;
+       case REQ_OP_WRITE_ZEROES:
+               ret = "write_zeroes";
+               break;
+       case REQ_OP_SCSI_IN:
+               ret = "scsi_in";
+               break;
+       case REQ_OP_SCSI_OUT:
+               ret = "scsi_out";
+               break;
+       case REQ_OP_DRV_IN:
+               ret = "drv_in";
+               break;
+       case REQ_OP_DRV_OUT:
+               ret = "drv_out";
+               break;
+       default:
+               ret = "unknown";
+       }
+
+       return ret;
+}
+
 static void print_req_error(struct request *req, blk_status_t status,
 		const char *caller)
 {
@@ -176,11 +224,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), req_op_str(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 2/2] block: add more debug data to print_req_err

[Bart Van Assche]

On 6/11/19 1:02 PM, Chaitanya Kulkarni wrote:
> +static inline const char *req_op_str(struct request *req)
> +{
> +       char *ret;
> +
> +       switch (req_op(req)) {
> +       case REQ_OP_READ:
> +               ret = "read";
> +               break;
> +       case REQ_OP_WRITE:
> +               ret = "write";
> +               break;
> +       case REQ_OP_FLUSH:
> +               ret = "flush";
> +               break;
> +       case REQ_OP_DISCARD:
> +               ret = "discard";
> +               break;
> +       case REQ_OP_SECURE_ERASE:
> +               ret = "secure_erase";
> +               break;
> +       case REQ_OP_ZONE_RESET:
> +               ret = "zone_reset";
> +               break;
> +       case REQ_OP_WRITE_SAME:
> +               ret = "write_same";
> +               break;
> +       case REQ_OP_WRITE_ZEROES:
> +               ret = "write_zeroes";
> +               break;
> +       case REQ_OP_SCSI_IN:
> +               ret = "scsi_in";
> +               break;
> +       case REQ_OP_SCSI_OUT:
> +               ret = "scsi_out";
> +               break;
> +       case REQ_OP_DRV_IN:
> +               ret = "drv_in";
> +               break;
> +       case REQ_OP_DRV_OUT:
> +               ret = "drv_out";
> +               break;
> +       default:
> +               ret = "unknown";
> +       }
> +
> +       return ret;
> +}
Please use an array instead of a switch/case statement to do this 
conversion. See also blk-mq-debugfs.c for examples.

Please also make show_bio_op(op) in include/trace/events/f2fs.h call the 
above function.

Thanks,

Bart.

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

[Chaitanya Kulkarni]

Thanks for for the review, I'll send out the V2.

On 6/12/19 8:22 AM, Bart Van Assche wrote:
> On 6/11/19 1:02 PM, Chaitanya Kulkarni wrote:
>> +static inline const char *req_op_str(struct request *req)
>> +{
>> +       char *ret;
>> +
>> +       switch (req_op(req)) {
>> +       case REQ_OP_READ:
>> +               ret = "read";
>> +               break;
>> +       case REQ_OP_WRITE:
>> +               ret = "write";
>> +               break;
>> +       case REQ_OP_FLUSH:
>> +               ret = "flush";
>> +               break;
>> +       case REQ_OP_DISCARD:
>> +               ret = "discard";
>> +               break;
>> +       case REQ_OP_SECURE_ERASE:
>> +               ret = "secure_erase";
>> +               break;
>> +       case REQ_OP_ZONE_RESET:
>> +               ret = "zone_reset";
>> +               break;
>> +       case REQ_OP_WRITE_SAME:
>> +               ret = "write_same";
>> +               break;
>> +       case REQ_OP_WRITE_ZEROES:
>> +               ret = "write_zeroes";
>> +               break;
>> +       case REQ_OP_SCSI_IN:
>> +               ret = "scsi_in";
>> +               break;
>> +       case REQ_OP_SCSI_OUT:
>> +               ret = "scsi_out";
>> +               break;
>> +       case REQ_OP_DRV_IN:
>> +               ret = "drv_in";
>> +               break;
>> +       case REQ_OP_DRV_OUT:
>> +               ret = "drv_out";
>> +               break;
>> +       default:
>> +               ret = "unknown";
>> +       }
>> +
>> +       return ret;
>> +}
> Please use an array instead of a switch/case statement to do this 
> conversion. See also blk-mq-debugfs.c for examples.
>
> Please also make show_bio_op(op) in include/trace/events/f2fs.h call the 
> above function.
>
> Thanks,
>
> Bart.
>

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)

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/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)