lkml.org 
[lkml]   [2019]   [Sep]   [27]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
SubjectRe: [PATCH] scsi: core: Log SCSI command age with errors
From
Date
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@redhat.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

\
 
 \ /
  Last update: 2019-09-27 19:45    [W:0.067 / U:0.564 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site