Re: [PATCH] scsi: core: Log SCSI command age with errors

[Laurence Oberman <loberman@redhat.com>]

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