[PATCH] scsi: core: Rate limit "rejecting I/O" messages

[PATCH] scsi: core: Rate limit "rejecting I/O" messages

[Daniel Wagner]

Prevent excessive logging by rate limiting the "rejecting I/O"
messages. For example in setups where remote syslog is used the link
is saturated by those messages when a storage controller/disk
misbehaves.

Cc: "James E.J. Bottomley" <jejb@linux.ibm.com>
Cc: "Martin K. Petersen" <martin.petersen@oracle.com>
Signed-off-by: Daniel Wagner <dwagner@suse.de>
---
 drivers/scsi/scsi_lib.c    |  4 ++--
 include/scsi/scsi_device.h | 10 ++++++++++
 2 files changed, 12 insertions(+), 2 deletions(-)

diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index 47835c4b4ee0..01c35c58c6f3 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -1217,7 +1217,7 @@ scsi_prep_state_check(struct scsi_device *sdev, struct request *req)
 		 */
 		if (!sdev->offline_already) {
 			sdev->offline_already = true;
-			sdev_printk(KERN_ERR, sdev,
+			sdev_printk_ratelimited(KERN_ERR, sdev,
 				    "rejecting I/O to offline device\n");
 		}
 		return BLK_STS_IOERR;
@@ -1226,7 +1226,7 @@ scsi_prep_state_check(struct scsi_device *sdev, struct request *req)
 		 * If the device is fully deleted, we refuse to
 		 * process any commands as well.
 		 */
-		sdev_printk(KERN_ERR, sdev,
+		sdev_printk_ratelimited(KERN_ERR, sdev,
 			    "rejecting I/O to dead device\n");
 		return BLK_STS_IOERR;
 	case SDEV_BLOCK:
diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
index c3cba2aaf934..8be40b0e1b8f 100644
--- a/include/scsi/scsi_device.h
+++ b/include/scsi/scsi_device.h
@@ -257,6 +257,16 @@ sdev_prefix_printk(const char *, const struct scsi_device *, const char *,
 #define sdev_printk(l, sdev, fmt, a...)				\
 	sdev_prefix_printk(l, sdev, NULL, fmt, ##a)
 
+#define sdev_printk_ratelimited(l, sdev, fmt, a...)			\
+({									\
+	static DEFINE_RATELIMIT_STATE(_rs,				\
+				      DEFAULT_RATELIMIT_INTERVAL,	\
+				      DEFAULT_RATELIMIT_BURST);		\
+									\
+	if (__ratelimit(&_rs))						\
+		sdev_prefix_printk(l, sdev, NULL, fmt, ##a);		\
+})
+
 __printf(3, 4) void
 scmd_printk(const char *, const struct scsi_cmnd *, const char *, ...);
 
-- 
2.16.4

Re: [PATCH] scsi: core: Rate limit "rejecting I/O" messages

[James Bottomley]

On Wed, 2020-04-08 at 19:10 +0200, Daniel Wagner wrote: 
> +#define sdev_printk_ratelimited(l, sdev, fmt, a...)			
> \
> +({									
> \
> +	static DEFINE_RATELIMIT_STATE(_rs,				
> \
> +				      DEFAULT_RATELIMIT_INTERVAL,	
> \
> +				      DEFAULT_RATELIMIT_BURST);	
> 	\
> +									
> \
> +	if (__ratelimit(&_rs))					
> 	\
> +		sdev_prefix_printk(l, sdev, NULL, fmt, ##a);	

If we do go with a ratelimit architecture for sdev_printk, I would
think the limit has to be per sdev, because we wouldn't want a burst of
messages on one sdev to suppress messages on another.

For this particular issue, I suppose one target can have many sdevs, so
you'd prefer to rate limit by target?

James

Re: [PATCH] scsi: core: Rate limit "rejecting I/O" messages

[Ewan D. Milne]

On Wed, 2020-04-08 at 19:10 +0200, Daniel Wagner wrote:
> Prevent excessive logging by rate limiting the "rejecting I/O"
> messages. For example in setups where remote syslog is used the link
> is saturated by those messages when a storage controller/disk
> misbehaves.
> 
> Cc: "James E.J. Bottomley" <jejb@linux.ibm.com>
> Cc: "Martin K. Petersen" <martin.petersen@oracle.com>
> Signed-off-by: Daniel Wagner <dwagner@suse.de>
> ---
>  drivers/scsi/scsi_lib.c    |  4 ++--
>  include/scsi/scsi_device.h | 10 ++++++++++
>  2 files changed, 12 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
> index 47835c4b4ee0..01c35c58c6f3 100644
> --- a/drivers/scsi/scsi_lib.c
> +++ b/drivers/scsi/scsi_lib.c
> @@ -1217,7 +1217,7 @@ scsi_prep_state_check(struct scsi_device *sdev,
> struct request *req)
>  		 */
>  		if (!sdev->offline_already) {
>  			sdev->offline_already = true;
> -			sdev_printk(KERN_ERR, sdev,
> +			sdev_printk_ratelimited(KERN_ERR, sdev,
>  				    "rejecting I/O to offline
> device\n");

I would really prefer we not do it this way if at all possible.
It loses information we may need to debug SAN outage problems.

The reason I didn't use ratelimit is that the ratelimit structure is
per-instance of the ratelimit call here, not per-device.  So this
doesn't work right -- it will drop messages for other devices.

>  		}
>  		return BLK_STS_IOERR;
> @@ -1226,7 +1226,7 @@ scsi_prep_state_check(struct scsi_device *sdev,
> struct request *req)
>  		 * If the device is fully deleted, we refuse to
>  		 * process any commands as well.
>  		 */
> -		sdev_printk(KERN_ERR, sdev,
> +		sdev_printk_ratelimited(KERN_ERR, sdev,
>  			    "rejecting I/O to dead device\n");

I practice I hardly see this message, do you actually have a case
where this happens?  If so perhaps add another flag similar to
offline_already?

The offline message happens a *lot*, we get a ton of them for each
active device when the queues are unblocked when a target goes away.

-Ewan

>  		return BLK_STS_IOERR;
>  	case SDEV_BLOCK:
> diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
> index c3cba2aaf934..8be40b0e1b8f 100644
> --- a/include/scsi/scsi_device.h
> +++ b/include/scsi/scsi_device.h
> @@ -257,6 +257,16 @@ sdev_prefix_printk(const char *, const struct
> scsi_device *, const char *,
>  #define sdev_printk(l, sdev, fmt, a...)				
> \
>  	sdev_prefix_printk(l, sdev, NULL, fmt, ##a)
>  
> +#define sdev_printk_ratelimited(l, sdev, fmt, a...)			
> \
> +({									
> \
> +	static DEFINE_RATELIMIT_STATE(_rs,				
> \
> +				      DEFAULT_RATELIMIT_INTERVAL,	\
> +				      DEFAULT_RATELIMIT_BURST);		
> \
> +									
> \
> +	if (__ratelimit(&_rs))						
> \
> +		sdev_prefix_printk(l, sdev, NULL, fmt, ##a);		
> \
> +})
> +
>  __printf(3, 4) void
>  scmd_printk(const char *, const struct scsi_cmnd *, const char *,
> ...);
>  

Re: [PATCH] scsi: core: Rate limit "rejecting I/O" messages

[Joe Perches]

On Wed, 2020-04-08 at 15:16 -0400, Ewan D. Milne wrote:
> On Wed, 2020-04-08 at 19:10 +0200, Daniel Wagner wrote:
> > Prevent excessive logging by rate limiting the "rejecting I/O"
> > messages. For example in setups where remote syslog is used the link
> > is saturated by those messages when a storage controller/disk
> > misbehaves.
> > 
> > Cc: "James E.J. Bottomley" <jejb@linux.ibm.com>
> > Cc: "Martin K. Petersen" <martin.petersen@oracle.com>
> > Signed-off-by: Daniel Wagner <dwagner@suse.de>
> > ---
> >  drivers/scsi/scsi_lib.c    |  4 ++--
> >  include/scsi/scsi_device.h | 10 ++++++++++
> >  2 files changed, 12 insertions(+), 2 deletions(-)
> > 
> > diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
> > index 47835c4b4ee0..01c35c58c6f3 100644
> > --- a/drivers/scsi/scsi_lib.c
> > +++ b/drivers/scsi/scsi_lib.c
> > @@ -1217,7 +1217,7 @@ scsi_prep_state_check(struct scsi_device *sdev,
> > struct request *req)
> >  		 */
> >  		if (!sdev->offline_already) {
> >  			sdev->offline_already = true;
> > -			sdev_printk(KERN_ERR, sdev,
> > +			sdev_printk_ratelimited(KERN_ERR, sdev,
> >  				    "rejecting I/O to offline
> > device\n");
> 
> I would really prefer we not do it this way if at all possible.
> It loses information we may need to debug SAN outage problems.
> 
> The reason I didn't use ratelimit is that the ratelimit structure is
> per-instance of the ratelimit call here, not per-device.  So this
> doesn't work right -- it will drop messages for other devices.

Could add a ratelimit_state to struct scsi_device.

Something like:
---
 drivers/scsi/scsi_scan.c   | 2 ++
 include/scsi/scsi_device.h | 2 ++
 2 files changed, 4 insertions(+)

diff --git a/drivers/scsi/scsi_scan.c b/drivers/scsi/scsi_scan.c
index f2437a..938c83f 100644
--- a/drivers/scsi/scsi_scan.c
+++ b/drivers/scsi/scsi_scan.c
@@ -279,6 +279,8 @@ static struct scsi_device *scsi_alloc_sdev(struct scsi_target *starget,
 	scsi_change_queue_depth(sdev, sdev->host->cmd_per_lun ?
 					sdev->host->cmd_per_lun : 1);
 
+	ratelimit_state_init(&sdev->rs, DEFAULT_RATELIMIT_INTERVAL,
+			     DEFAULT_RATELIMIT_BURST);
 	scsi_sysfs_device_initialize(sdev);
 
 	if (shost->hostt->slave_alloc) {
diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
index c3cba2..2600de7 100644
--- a/include/scsi/scsi_device.h
+++ b/include/scsi/scsi_device.h
@@ -8,6 +8,7 @@
 #include <linux/blkdev.h>
 #include <scsi/scsi.h>
 #include <linux/atomic.h>
+#include <linux/ratelimit.h>
 
 struct device;
 struct request_queue;
@@ -233,6 +234,7 @@ struct scsi_device {
 	struct mutex		state_mutex;
 	enum scsi_device_state sdev_state;
 	struct task_struct	*quiesced_by;
+	struct ratelimit_state	rs;
 	unsigned long		sdev_data[];
 } __attribute__((aligned(sizeof(unsigned long))));
 

Re: [PATCH] scsi: core: Rate limit "rejecting I/O" messages

[Daniel Wagner]

Hi Ewan,

On Wed, Apr 08, 2020 at 03:16:27PM -0400, Ewan D. Milne wrote:
> On Wed, 2020-04-08 at 19:10 +0200, Daniel Wagner wrote:
> > --- a/drivers/scsi/scsi_lib.c
> > +++ b/drivers/scsi/scsi_lib.c
> > @@ -1217,7 +1217,7 @@ scsi_prep_state_check(struct scsi_device *sdev,
> > struct request *req)
> >  		 */
> >  		if (!sdev->offline_already) {
> >  			sdev->offline_already = true;
> > -			sdev_printk(KERN_ERR, sdev,
> > +			sdev_printk_ratelimited(KERN_ERR, sdev,
> >  				    "rejecting I/O to offline
> > device\n");
> 
> I would really prefer we not do it this way if at all possible.
> It loses information we may need to debug SAN outage problems.

Understood.

> The reason I didn't use ratelimit is that the ratelimit structure is
> per-instance of the ratelimit call here, not per-device.  So this
> doesn't work right -- it will drop messages for other devices.

I didn't really think this through. Sorry.

> > -		sdev_printk(KERN_ERR, sdev,
> > +		sdev_printk_ratelimited(KERN_ERR, sdev,
> >  			    "rejecting I/O to dead device\n");
> 
> I practice I hardly see this message, do you actually have a case
> where this happens?  If so perhaps add another flag similar to
> offline_already?
> 
> The offline message happens a *lot*, we get a ton of them for each
> active device when the queues are unblocked when a target goes away.

I've missed commit b0962c53bde9 ("scsi: core: avoid repetitive logging
of device offline messages") which should address the report I got in
our enterprise kernel. I was over eager to rate limit the 'dead
device' as well. It seem no need for this patch. Let me backport the
commit and see what our customer has to say.

Thanks for the help!
Daniel

Re: [PATCH] scsi: core: Rate limit "rejecting I/O" messages

[Ewan D. Milne]

On Wed, 2020-04-08 at 12:49 -0700, Joe Perches wrote:
> 
> Could add a ratelimit_state to struct scsi_device.
> 
> Something like:
> ---
>  drivers/scsi/scsi_scan.c   | 2 ++
>  include/scsi/scsi_device.h | 2 ++
>  2 files changed, 4 insertions(+)
> 
> diff --git a/drivers/scsi/scsi_scan.c b/drivers/scsi/scsi_scan.c
> index f2437a..938c83f 100644
> --- a/drivers/scsi/scsi_scan.c
> +++ b/drivers/scsi/scsi_scan.c
> @@ -279,6 +279,8 @@ static struct scsi_device *scsi_alloc_sdev(struct
> scsi_target *starget,
>  	scsi_change_queue_depth(sdev, sdev->host->cmd_per_lun ?
>  					sdev->host->cmd_per_lun : 1);
>  
> +	ratelimit_state_init(&sdev->rs, DEFAULT_RATELIMIT_INTERVAL,
> +			     DEFAULT_RATELIMIT_BURST);
>  	scsi_sysfs_device_initialize(sdev);
>  
>  	if (shost->hostt->slave_alloc) {
> diff --git a/include/scsi/scsi_device.h b/include/scsi/scsi_device.h
> index c3cba2..2600de7 100644
> --- a/include/scsi/scsi_device.h
> +++ b/include/scsi/scsi_device.h
> @@ -8,6 +8,7 @@
>  #include <linux/blkdev.h>
>  #include <scsi/scsi.h>
>  #include <linux/atomic.h>
> +#include <linux/ratelimit.h>
>  
>  struct device;
>  struct request_queue;
> @@ -233,6 +234,7 @@ struct scsi_device {
>  	struct mutex		state_mutex;
>  	enum scsi_device_state sdev_state;
>  	struct task_struct	*quiesced_by;
> +	struct ratelimit_state	rs;
>  	unsigned long		sdev_data[];
>  } __attribute__((aligned(sizeof(unsigned long))));
>  

We could but in our experience this may not work well enough.  We do
wants to see the message when the device goes offline, so we can look
at logs from SAN failures to see when that happened, but logging more
than one message per device is worthless.  And there can be *LOTS*
of LUNs behind targets that go away.  Hundreds.  Thousands, even.

I keep getting crash dumps with nothing useful in the dmesg buffer.
And we see a lot of serial console lockups.

-Ewan