Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Message-ID: <3a8ee584f9846fba94d98d0e6941fefdcbed5d71.camel@redhat.com>
Subject: Re: [PATCH] scsi: core: Log SCSI command age with errors
From:   Laurence Oberman <loberman@redhat.com>
To:     Martin Wilck <mwilck@suse.de>,
        "Milan P. Gandhi" <mgandhi@redhat.com>,
        linux-kernel@vger.kernel.org, linux-scsi@vger.kernel.org
Cc:     jejb@linux.ibm.com, martin.petersen@oracle.com
Date:   Fri, 27 Sep 2019 13:45:21 -0400
In-Reply-To: <471732f03049a1528df1d144013d723041f0a419.camel@suse.de>
References: <20190923060122.GA9603@machine1>
         <471732f03049a1528df1d144013d723041f0a419.camel@suse.de>
Content-Type: text/plain; charset="UTF-8"
Mime-Version: 1.0
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

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