Re: [PATCH 4/4] scsi: Trace SCSI sense data

[Steven Rostedt <rostedt@goodmis.org>]

On Tue, 25 Apr 2023 16:34:46 -0700
Bart Van Assche <bvanassche@acm.org> 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);
> +		  })

The above will absolutely break user space parsing.

The TP_printk() isn't supposed to be too complex, as user space uses it to
figure out how to parse the data.

If you are doing the above, I'm guessing that most of the time the
sense_data doesn't use the 96 bytes (defined by SCSI_SENSE_BUFFERSIZE).

Perhaps instead, you should make result a dynamic array, and save writing
a large amount of zeros into the precious ring buffer?

static int sense_data_size(unsigned char *array)
{
	int len = SCSI_SENSE_BUFFERSIZE;

	for (len && array[len - 1] == 0)
		len--;

	return len;
}

		__dynamic_array(unsigned char, sense_data, result_size(cmd->sense_data)

	[..]


		memcpy(__get_dynamic_array(sense_data), cmd->sense_data, result_size(cmd->sense_data));

// Yes, I need a way to pass the "result_size" from the initialization to
// the allocation.


	[..]


		__print_hex(__get_dynamic_array(sense_data),
			    __get_dynamic_array_len(sense_data))

Or something like that.

-- Steve


> +		  : "")
>  );
>  
>  DEFINE_EVENT(scsi_cmd_done_timeout_template, scsi_dispatch_cmd_done,