[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <3a8ee584f9846fba94d98d0e6941fefdcbed5d71.camel@redhat.com>
Date: Fri, 27 Sep 2019 13:45:21 -0400
From: Laurence Oberman <loberman@...hat.com>
To: Martin Wilck <mwilck@...e.de>,
"Milan P. Gandhi" <mgandhi@...hat.com>,
linux-kernel@...r.kernel.org, linux-scsi@...r.kernel.org
Cc: jejb@...ux.ibm.com, martin.petersen@...cle.com
Subject: Re: [PATCH] scsi: core: Log SCSI command age with errors
On Fri, 2019-09-27 at 17:26 +0200, Martin Wilck wrote:
> On Mon, 2019-09-23 at 11:31 +0530, Milan P. Gandhi wrote:
> > Couple of users had requested to print the SCSI command age along
> > with command failure errors. This is a small change, but allows
> > users to get more important information about the command that was
> > failed, it would help the users in debugging the command failures:
> >
> > Signed-off-by: Milan P. Gandhi <mgandhi@...hat.com>
> > ---
> > diff --git a/drivers/scsi/scsi_logging.c
> > b/drivers/scsi/scsi_logging.c
> > index ecc5918e372a..ca2182bc53c6 100644
> > --- a/drivers/scsi/scsi_logging.c
> > +++ b/drivers/scsi/scsi_logging.c
> > @@ -437,6 +437,7 @@ void scsi_print_result(const struct scsi_cmnd
> > *cmd, const char *msg,
> > const char *mlret_string = scsi_mlreturn_string(disposition);
> > const char *hb_string = scsi_hostbyte_string(cmd->result);
> > const char *db_string = scsi_driverbyte_string(cmd->result);
> > + unsigned long cmd_age = (jiffies - cmd->jiffies_at_alloc) / HZ;
>
> This comes down to pretty coarse time resolution, does it not? More
> often than not, the time difference shown will be 0. I'd recommend at
> least millisecond resolution.
>
> >
> > logbuf = scsi_log_reserve_buffer(&logbuf_len);
> > if (!logbuf)
> > @@ -478,10 +479,15 @@ void scsi_print_result(const struct scsi_cmnd
> > *cmd, const char *msg,
> >
> > if (db_string)
> > off += scnprintf(logbuf + off, logbuf_len - off,
> > - "driverbyte=%s", db_string);
> > + "driverbyte=%s ", db_string);
> > else
> > off += scnprintf(logbuf + off, logbuf_len - off,
> > - "driverbyte=0x%02x", driver_byte(cmd-
> > > result));
> >
> > + "driverbyte=0x%02x ",
> > + driver_byte(cmd->result));
> > +
> > + off += scnprintf(logbuf + off, logbuf_len - off,
> > + "cmd-age=%lus", cmd_age);
>
> This is certainly helpful in some situations. Yet I am unsure if it
> should *always* be printed. I wouldn't say it's as important as the
> other stuff scsi_print_result() provides. After all, by activating
> MLQUEUE+MLCOMPLETE, the time on-wire can be extracted with better
> accuracy from currently available logs.
>
> So perhaps make this depend on a module parameter?
>
> Also, we should carefully ponder if we want to put this on the same
> line as the driver byte, as users may have created scripts for
> parsing
> this output.
>
> Regards,
> Martin
>
>
Hi Martin
Agreed about log extraction, but turning that on with a busy workload
in a production environment is not practical. We cant do it with
systems with 1000's of luns and 1000's of IOPS/sec.
Also second resolution is good enough for the debug we want to see.
Regards
Laurence
Powered by blists - more mailing lists