2020-04-08 20:30:50

by Ewan Milne

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

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" <[email protected]>
> Cc: "Martin K. Petersen" <[email protected]>
> Signed-off-by: Daniel Wagner <[email protected]>
> ---
> 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 *,
> ...);
>


2020-04-08 20:42:10

by Joe Perches

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

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" <[email protected]>
> > Cc: "Martin K. Petersen" <[email protected]>
> > Signed-off-by: Daniel Wagner <[email protected]>
> > ---
> > 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))));



2020-04-09 07:39:03

by Daniel Wagner

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

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

2020-04-09 17:17:10

by Ewan Milne

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

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