[4/4] scsi: Trace SCSI sense data

If a command fails, SCSI sense data is essential to determine why it
failed. Hence make the SCSI sense data available in the ftrace output.

Cc: Christoph Hellwig <hch@lst.de>
Cc: Ming Lei <ming.lei@redhat.com>
Cc: Hannes Reinecke <hare@suse.de>
Cc: John Garry <john.g.garry@oracle.com>
Cc: Mike Christie <michael.christie@oracle.com>
Signed-off-by: Bart Van Assche <bvanassche@acm.org>
---
 include/trace/events/scsi.h | 17 +++++++++++++++--
 1 file changed, 15 insertions(+), 2 deletions(-)

On Tue, Apr 25, 2023 at 04:34:46PM -0700, Bart Van Assche wrote:
> If a command fails, SCSI sense data is essential to determine why it
> failed. Hence make the SCSI sense data available in the ftrace output.
> 
> Cc: Christoph Hellwig <hch@lst.de>
> Cc: Ming Lei <ming.lei@redhat.com>
> Cc: Hannes Reinecke <hare@suse.de>
> Cc: John Garry <john.g.garry@oracle.com>
> Cc: Mike Christie <michael.christie@oracle.com>
> Signed-off-by: Bart Van Assche <bvanassche@acm.org>
> ---
>  include/trace/events/scsi.h | 17 +++++++++++++++--
>  1 file changed, 15 insertions(+), 2 deletions(-)
> 
> diff --git a/include/trace/events/scsi.h b/include/trace/events/scsi.h
> index a2c7befd451a..bb5f31504fbb 100644
> --- a/include/trace/events/scsi.h
> +++ b/include/trace/events/scsi.h
> @@ -269,6 +269,7 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
>  		__field( unsigned int,	prot_sglen )
>  		__field( unsigned char,	prot_op )
>  		__dynamic_array(unsigned char,	cmnd, cmd->cmd_len)
> +		__array(unsigned char,  sense_data, SCSI_SENSE_BUFFERSIZE)
>  	),
>  
>  	TP_fast_assign(
> @@ -285,11 +286,13 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
>  		__entry->prot_sglen	= scsi_prot_sg_count(cmd);
>  		__entry->prot_op	= scsi_get_prot_op(cmd);
>  		memcpy(__get_dynamic_array(cmnd), cmd->cmnd, cmd->cmd_len);
> +		memcpy(__entry->sense_data, cmd->sense_buffer,
> +		       SCSI_SENSE_BUFFERSIZE);
>  	),
>  
>  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u prot_sgl=%u " \
>  		  "prot_op=%s driver_tag=%d scheduler_tag=%d cmnd=(%s %s raw=%s) " \
> -		  "result=(driver=%s host=%s message=%s status=%s)",
> +		  "result=(driver=%s host=%s message=%s status=%s%s%s)",
>  		  __entry->host_no, __entry->channel, __entry->id,
>  		  __entry->lun, __entry->data_sglen, __entry->prot_sglen,
>  		  show_prot_op_name(__entry->prot_op), __entry->driver_tag,
> @@ -299,7 +302,17 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
>  		  "DRIVER_OK",
>  		  show_hostbyte_name(((__entry->result) >> 16) & 0xff),
>  		  "COMMAND_COMPLETE",
> -		  show_statusbyte_name(__entry->result & 0xff))
> +		  show_statusbyte_name(__entry->result & 0xff),
> +		  __entry->result & 0xff ? " sense_data=" : "",
> +		  __entry->result & 0xff ?
> +		  ({
> +			  unsigned int len = SCSI_SENSE_BUFFERSIZE;
> +
> +			  while (len && __entry->sense_data[len - 1] == 0)
> +				  len--;
> +			  __print_hex(__entry->sense_data, len);

Hello Bart,

Do we really need to dump the whole sense buffer?

Shouldn't simply printing the SK, ASC, ASCQ be sufficient?

Yes, it is a bit annoying that there are two different formats.
But you could do the reverse of:
https://github.com/torvalds/linux/blob/v6.3/drivers/scsi/scsi_common.c#L241

Or, if the tracepoint is after scsi_normalize_sense() has been called,
you could simply use sshdr->sense_key, sshdr->asc and sshdr->ascq.


Kind regards,
Niklas

On 4/28/23 01:09, Niklas Cassel wrote:
> Do we really need to dump the whole sense buffer?
> 
> Shouldn't simply printing the SK, ASC, ASCQ be sufficient?
Hi Niklas,

How about replacing patch 4/4 of this series with the patch below?

Thanks,

Bart.



diff --git a/include/trace/events/scsi.h b/include/trace/events/scsi.h
index 370ade0d4093..d4a27cd4040b 100644
--- a/include/trace/events/scsi.h
+++ b/include/trace/events/scsi.h
@@ -258,9 +258,14 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
  		__field( unsigned int,	prot_sglen )
  		__field( unsigned char,	prot_op )
  		__dynamic_array(unsigned char,	cmnd, cmd->cmd_len)
+		__field( u8, sense_key )
+		__field( u8, asc )
+		__field( u8, ascq )
  	),

  	TP_fast_assign(
+		struct scsi_sense_hdr sshdr;
+
  		__entry->host_no	= cmd->device->host->host_no;
  		__entry->channel	= cmd->device->channel;
  		__entry->id		= cmd->device->id;
@@ -272,11 +277,21 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
  		__entry->prot_sglen	= scsi_prot_sg_count(cmd);
  		__entry->prot_op	= scsi_get_prot_op(cmd);
  		memcpy(__get_dynamic_array(cmnd), cmd->cmnd, cmd->cmd_len);
+		if (cmd->result & 0xff &&
+		    scsi_command_normalize_sense(cmd, &sshdr)) {
+			__entry->sense_key = sshdr.sense_key;
+			__entry->asc = sshdr.asc;
+			__entry->ascq = sshdr.ascq;
+		} else {
+			__entry->sense_key = 0;
+			__entry->asc = 0;
+			__entry->ascq = 0;
+		}
  	),

  	TP_printk("host_no=%u channel=%u id=%u lun=%u data_sgl=%u " \
  		  "prot_sgl=%u prot_op=%s cmnd=(%s %s raw=%s) result=(driver=" \
-		  "%s host=%s message=%s status=%s)",
+		  "%s host=%s message=%s status=%s sense_key=%u asc=%#x ascq=%#x)",
  		  __entry->host_no, __entry->channel, __entry->id,
  		  __entry->lun, __entry->data_sglen, __entry->prot_sglen,
  		  show_prot_op_name(__entry->prot_op),
@@ -286,7 +301,8 @@ DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
  		  "DRIVER_OK",
  		  show_hostbyte_name(((__entry->result) >> 16) & 0xff),
  		  "COMMAND_COMPLETE",
-		  show_statusbyte_name(__entry->result & 0xff))
+		  show_statusbyte_name(__entry->result & 0xff),
+		  __entry->sense_key, __entry->asc, __entry->ascq)
  );

  DEFINE_EVENT(scsi_cmd_done_timeout_template, scsi_dispatch_cmd_done,