Re: [RFC PATCH 08/10] scsi/trace: Use scsi_print_sense trace point instead of printk

[Hannes Reinecke]

On 08/08/2014 01:50 PM, Yoshihiro YUNOMAE wrote:
> Previous sense messages can be mixed into other sense messages,
> because continuous printk (KERN_CONT) was used. To avoid the problem,
> patch d87f3a6f51 introduced a local buffer in Hannes's baranch (*1).
> But using local buffers can induce stack overflow, so we want to solve the
> problem without local buffer if possible.
>
> trace_seq_printf can add log messages without local buffer, so we use it.
>
> (*1) http://git.kernel.org/cgit/linux/kernel/git/hare/scsi-devel.git/log/?h=logging
>
> - Result examples
>
> <Before> (printk)
> sd 2:0:0:0: [sda] Sense Key : Medium Error [current]
>
> <After> (ftrace)
> scsi_print_sense: host_no=2 channel=0 id=0 lun=0 [sda] Sense Key (Medium Error [current])
>
> Signed-off-by: Yoshihiro YUNOMAE <yoshihiro.yunomae.ez@xxxxxxxxxxx>
> Cc: Hannes Reinecke <hare@xxxxxxx>
> Cc: Doug Gilbert <dgilbert@xxxxxxxxxxxx>
> Cc: Martin K. Petersen <martin.petersen@xxxxxxxxxx>
> Cc: Christoph Hellwig <hch@xxxxxx>
> Cc: "James E.J. Bottomley" <JBottomley@xxxxxxxxxxxxx>
> Cc: Hidehiro Kawai <hidehiro.kawai.ez@xxxxxxxxxxx>
> Cc: Masami Hiramatsu <masami.hiramatsu.pt@xxxxxxxxxxx>
> ---
>   drivers/scsi/constants.c    |  145 ++-----------------------------------------
>   drivers/scsi/scsi_trace.c   |  140 ++++++++++++++++++++++++++++++++++++++++--
>   include/scsi/scsi_eh.h      |    7 ++
>   include/trace/events/scsi.h |   48 ++++++++++++++
>   4 files changed, 195 insertions(+), 145 deletions(-)
>
> diff --git a/drivers/scsi/constants.c b/drivers/scsi/constants.c
> index f7b7f32..85b75c8 100644
> --- a/drivers/scsi/constants.c
> +++ b/drivers/scsi/constants.c
> @@ -19,7 +19,7 @@
>   #include <scsi/scsi_eh.h>
>   #include <scsi/scsi_dbg.h>
>
> -
> +#include <trace/events/scsi.h>
>
>   /* Commands with service actions that change the command name */
>   #define SERVICE_ACTION_IN_12 0xab
> @@ -1267,58 +1267,8 @@ static const struct error_info2 additional2[] =
>   	{0x70, 0x00, 0xff, "Decompression exception short algorithm id of %x"},
>   	{0, 0, 0, NULL}
>   };
> -
> -/* description of the sense key values */
> -static const char * const snstext[] = {
> -	"No Sense",	    /* 0: There is no sense information */
> -	"Recovered Error",  /* 1: The last command completed successfully
> -				  but used error correction */
> -	"Not Ready",	    /* 2: The addressed target is not ready */
> -	"Medium Error",	    /* 3: Data error detected on the medium */
> -	"Hardware Error",   /* 4: Controller or device failure */
> -	"Illegal Request",  /* 5: Error in request */
> -	"Unit Attention",   /* 6: Removable medium was changed, or
> -				  the target has been reset, or ... */
> -	"Data Protect",	    /* 7: Access to the data is blocked */
> -	"Blank Check",	    /* 8: Reached unexpected written or unwritten
> -				  region of the medium */
> -	"Vendor Specific(9)",
> -	"Copy Aborted",	    /* A: COPY or COMPARE was aborted */
> -	"Aborted Command",  /* B: The target aborted the command */
> -	"Equal",	    /* C: A SEARCH DATA command found data equal,
> -				  reserved in SPC-4 rev 36 */
> -	"Volume Overflow",  /* D: Medium full with still data to be written */
> -	"Miscompare",	    /* E: Source data and data on the medium
> -				  do not agree */
> -	"Completed",	    /* F: command completed sense data reported,
> -				  may occur for successful command */
> -};
> -#else
> -static const char * const snstext[] = {
> -	"0x0", "0x1", "0x2", "0x3", "0x4", "0x5", "0x6", "0x7",
> -	"0x8", "0x9", "0xa", "0xb", "0xc", "0xd", "0xe", "0xf",
> -};
>   #endif
>
> -/* Get sense key string or NULL if not available */
> -const char *
> -scsi_sense_key_string(unsigned char key) {
> -	return snstext[key & 0xf];
> -}
> -EXPORT_SYMBOL(scsi_sense_key_string);
> -
> -const char *
> -scsi_sense_type_string(struct scsi_sense_hdr *sshdr)
> -{
> -	return scsi_sense_is_deferred(sshdr) ? "[deferred]" : "[current]";
> -}
> -
> -const char *
> -scsi_sense_format_string(struct scsi_sense_hdr *sshdr)
> -{
> -	return sshdr->response_code >= 0x72 ? "[descriptor]" : "";
> -}
> -
>   /*
>    * Get additional sense code string or NULL if not available.
>    * This string may contain a "%x" and should be printed with ascq as arg.
> @@ -1375,105 +1325,22 @@ void
>   scsi_print_sense_hdr(struct scsi_device *sdev, const char *name,
>   		     struct scsi_sense_hdr *sshdr)
>   {
> -	sdev_printk(KERN_INFO, sdev, "[%s] Sense Key : %s %s%s\n", name,
> -		    scsi_sense_key_string(sshdr->sense_key),
> -		    scsi_sense_type_string(sshdr),
> -		    scsi_sense_format_string(sshdr));
> +	trace_scsi_print_sense(sdev, name, sshdr, NULL, 0, 0);
>   	scsi_show_extd_sense(sdev, name, sshdr->asc, sshdr->ascq);
>   }
>   EXPORT_SYMBOL(scsi_print_sense_hdr);
>
> -static void
> -scsi_dump_sense_buffer(struct scsi_device *sdev, const char *prefix,
> -		       const unsigned char *sense_buffer, int sense_len)
> -{
> -	char linebuf[128];
> -	int i, linelen, remaining;
> -
> -	if (sense_len < 32)
> -		sense_len = 32;
> -
> -	remaining = sense_len;
> -	for (i = 0; i < sense_len; i += 16) {
> -		linelen = min(remaining, 16);
> -		remaining -= 16;
> -
> -		hex_dump_to_buffer(sense_buffer + i, linelen, 16, 1,
> -				   linebuf, sizeof(linebuf), false);
> -	}
> -	sdev_printk(KERN_INFO, sdev,
> -		    "[%s] Unrecognized sense data (in hex): %s",
> -		    prefix, linebuf);
> -}
> -
> -static void
> -scsi_decode_sense_extras(struct scsi_device *sdev, const char *name,
> -			 const unsigned char *sense_buffer, int sense_len)
> -{
> -	int res, sense_flags = 0, fixed_valid = 0;
> -	u64 info = 0;
> -	char buff[80];
> -	int blen;
> -
> -	if ((sense_buffer[0] & 0x80) < 0x72) {
> -		/* decode extras for "fixed" format */
> -		fixed_valid = sense_buffer[0] & 0x80;
> -		info = get_unaligned_be32(&sense_buffer[3]);
> -		sense_flags = sense_buffer[2];
> -	} else if (sense_buffer[7] > 0) {
> -		const u8 *ucp;
> -
> -		/* descriptor format with sense descriptors */
> -		ucp = scsi_sense_desc_find(sense_buffer, sense_len, 0);
> -		if (ucp) {
> -			fixed_valid = ucp[2] & 0x80;
> -			if (fixed_valid)
> -				info = get_unaligned_be64(&ucp[4]);
> -		}
> -		ucp = scsi_sense_desc_find(sense_buffer, sense_len, 4);
> -		if (ucp)
> -			sense_flags |= ucp[3] & 0xe0;
> -	}
> -
> -	if (!sense_flags && !fixed_valid)
> -		return;
> -
> -	res = 0;
> -	memset(buff, 0, sizeof(buff));
> -	blen = sizeof(buff) - 1;
> -	if (fixed_valid)
> -		res += snprintf(buff + res, blen - res,
> -				"Info fld=0x%llx, ", info);
> -	if (sense_flags)
> -		res += snprintf(buff + res, blen - res, "%s%s%s",
> -				sense_flags & SENSE_FMK ? "FMK, " : "",
> -				sense_flags & SENSE_EOM ? "EOM, " : "",
> -				sense_flags & SENSE_ILI ? "ILI, " : "");
> -	if (res) {
> -		res -= 2;
> -		buff[res] = '\0';
> -	}
> -
> -	sdev_printk(KERN_INFO, sdev, "[%s] %s\n", name, buff);
> -}
> -
>   /* Normalize and print sense buffer with name prefix */
>   void __scsi_print_sense(struct scsi_device *sdev, const char *name,
>   			const unsigned char *sense_buffer, int sense_len)
>   {
>   	struct scsi_sense_hdr sshdr;
> +	int raw;
>
> -	if (!scsi_normalize_sense(sense_buffer, sense_len, &sshdr)) {
> -		/* this may be SCSI-1 sense data */
> -		scsi_dump_sense_buffer(sdev, name, sense_buffer, sense_len);
> -		return;
> -	}
> +	raw = !scsi_normalize_sense(sense_buffer, sense_len, &sshdr);
>
> -	sdev_printk(KERN_INFO, sdev, "[%s] Sense Key : %s %s%s\n", name,
> -	       scsi_sense_key_string(sshdr.sense_key),
> -	       scsi_sense_type_string(&sshdr),
> -	       scsi_sense_format_string(&sshdr));
> -	scsi_decode_sense_extras(sdev, name, sense_buffer, sense_len);
> +	trace_scsi_print_sense(sdev, name, &sshdr, sense_buffer, sense_len,
> +			       raw);
>   	scsi_show_extd_sense(sdev, name, sshdr.asc, sshdr.ascq);
>   }
>   EXPORT_SYMBOL(__scsi_print_sense);
> diff --git a/drivers/scsi/scsi_trace.c b/drivers/scsi/scsi_trace.c
> index 6ffbc40..2ecb1dc 100644
> --- a/drivers/scsi/scsi_trace.c
> +++ b/drivers/scsi/scsi_trace.c
> @@ -17,15 +17,16 @@
>    */
>   #include <linux/kernel.h>
>   #include <linux/trace_seq.h>
> +#include <asm/unaligned.h>
>   #include <trace/events/scsi.h>
>
>   #include <scsi/scsi_dbg.h>
> +#include <scsi/scsi_eh.h>
>
>   #define SERVICE_ACTION16(cdb) (cdb[1] & 0x1f)
>   #define SERVICE_ACTION32(cdb) ((cdb[8] << 8) | cdb[9])
>
> -static const char *
> -scsi_trace_misc(struct trace_seq *, unsigned char *, int);
> +static const char *scsi_trace_misc(struct trace_seq *);
>
>   static const char *
>   scsi_trace_rw6(struct trace_seq *p, unsigned char *cdb, int len)
> @@ -242,12 +243,12 @@ scsi_trace_varlen(struct trace_seq *p, unsigned char *cdb, int len)
>   	case WRITE_SAME_32:
>   		return scsi_trace_rw32(p, cdb, len);
>   	default:
> -		return scsi_trace_misc(p, cdb, len);
> +		return scsi_trace_misc(p);
>   	}
>   }
>
>   static const char *
> -scsi_trace_misc(struct trace_seq *p, unsigned char *cdb, int len)
> +scsi_trace_misc(struct trace_seq *p)
>   {
>   	const char *ret = p->buffer + p->len;
>
> @@ -285,10 +286,139 @@ scsi_trace_parse_cdb(struct trace_seq *p, unsigned char *cdb, int len)
>   	case VARIABLE_LENGTH_CMD:
>   		return scsi_trace_varlen(p, cdb, len);
>   	default:
> -		return scsi_trace_misc(p, cdb, len);
> +		return scsi_trace_misc(p);
>   	}
>   }
>
> +#ifdef CONFIG_SCSI_CONSTANTS
> +/* description of the sense key values */
> +static const char * const snstext[] = {
> +	"No Sense",	    /* 0: There is no sense information */
> +	"Recovered Error",  /* 1: The last command completed successfully
> +				  but used error correction */
> +	"Not Ready",	    /* 2: The addressed target is not ready */
> +	"Medium Error",	    /* 3: Data error detected on the medium */
> +	"Hardware Error",   /* 4: Controller or device failure */
> +	"Illegal Request",  /* 5: Error in request */
> +	"Unit Attention",   /* 6: Removable medium was changed, or
> +				  the target has been reset, or ... */
> +	"Data Protect",	    /* 7: Access to the data is blocked */
> +	"Blank Check",	    /* 8: Reached unexpected written or unwritten
> +				  region of the medium */
> +	"Vendor Specific(9)",
> +	"Copy Aborted",	    /* A: COPY or COMPARE was aborted */
> +	"Aborted Command",  /* B: The target aborted the command */
> +	"Equal",	    /* C: A SEARCH DATA command found data equal,
> +				  reserved in SPC-4 rev 36 */
> +	"Volume Overflow",  /* D: Medium full with still data to be written */
> +	"Miscompare",	    /* E: Source data and data on the medium
> +				  do not agree */
> +	"Completed",	    /* F: command completed sense data reported,
> +				  may occur for successful command */
> +};
> +#else
> +static const char * const snstext[] = {
> +	"0x0", "0x1", "0x2", "0x3", "0x4", "0x5", "0x6", "0x7",
> +	"0x8", "0x9", "0xa", "0xb", "0xc", "0xd", "0xe", "0xf",
> +};
> +#endif
> +
> +/* Get sense key string or NULL if not available */
> +const char *
> +scsi_sense_key_string(unsigned char key) {
> +	return snstext[key & 0xf];
> +}
> +EXPORT_SYMBOL(scsi_sense_key_string);
> +
> +static const char *
> +scsi_sense_type_string(u8 res_code)
> +{
> +	return __scsi_sense_is_deferred(res_code) ? "[deferred]" : "[current]";
> +}
> +
> +static const char *
> +scsi_sense_format_string(u8 res_code)
> +{
> +	return res_code >= 0x72 ? "[descriptor]" : "";
> +}
> +
> +static const char *
> +scsi_dump_sense_buffer(struct trace_seq *p, const unsigned char *buf, int len)
> +{
> +	const char *ret = p->buffer + p->len;
> +	int i;
> +
> +	if (!buf || !len)
> +		return scsi_trace_misc(p);
> +
> +	if (len < 32)
> +		len = 32;
> +
> +	trace_seq_printf(p, "Unrecognized sense data (in hex)");
> +	for (i = 0; i < len; i += 16)
> +		trace_seq_printf(p, " %02x", buf[i]);
> +
> +	trace_seq_putc(p, 0);
> +	return ret;
> +}
> +
> +const char *
> +scsi_trace_decode_sense_extras(struct trace_seq *p, u8 sense_key, u8 res_code,
> +			       const unsigned char *buf, int len, int raw)
> +{
> +	const char *ret = p->buffer + p->len;
> +	int sense_flags = 0, fixed_valid = 0;
> +	u64 info = 0;
> +
> +	if (raw)
> +		/* this may be SCSI-1 sense data */
> +		return scsi_dump_sense_buffer(p, buf, len);
> +
> +	trace_seq_printf(p, "Sense Key (%s %s%s",
> +			 scsi_sense_key_string(sense_key),
> +			 scsi_sense_type_string(res_code),
> +			 scsi_sense_format_string(res_code));
> +
> +	if (!buf || !len)
> +		goto out;
> +
> +	if ((buf[0] & 0x80) < 0x72) {
> +		/* decode extras for "fixed" format */
> +		fixed_valid = buf[0] & 0x80;
> +		info = get_unaligned_be32(&buf[3]);
> +		sense_flags = buf[2];
> +	} else if (buf[7] > 0) {
> +		const u8 *ucp;
> +
> +		/* descriptor format with sense descriptors */
> +		ucp = scsi_sense_desc_find(buf, len, 0);
> +		if (ucp) {
> +			fixed_valid = ucp[2] & 0x80;
> +			if (fixed_valid)
> +				info = get_unaligned_be64(&ucp[4]);
> +		}
> +		ucp = scsi_sense_desc_find(buf, len, 4);
> +		if (ucp)
> +			sense_flags |= ucp[3] & 0xe0;
> +	}
> +
> +	if (!sense_flags && !fixed_valid)
> +		goto out;
> +
> +	if (fixed_valid)
> +		trace_seq_printf(p, " Info fld=0x%llx", info);
> +	if (sense_flags)
> +		trace_seq_printf(p, " %s%s%s",
> +				sense_flags & SENSE_FMK ? "FMK" : "",
> +				sense_flags & SENSE_EOM ? "EOM" : "",
> +				sense_flags & SENSE_ILI ? "ILI" : "");
> +
> +out:
> +	trace_seq_printf(p, ")");
> +	trace_seq_putc(p, 0);
> +	return ret;
> +}
> +
>   void scsi_show_result(struct scsi_device *sdev, const char *name, int result)
>   {
>   	trace_scsi_show_result(sdev, name, result);
> diff --git a/include/scsi/scsi_eh.h b/include/scsi/scsi_eh.h
> index 06a8790..0e6d28c 100644
> --- a/include/scsi/scsi_eh.h
> +++ b/include/scsi/scsi_eh.h
> @@ -47,9 +47,14 @@ extern int scsi_normalize_sense(const u8 *sense_buffer, int sb_len,
>   extern int scsi_command_normalize_sense(struct scsi_cmnd *cmd,
>   		struct scsi_sense_hdr *sshdr);
>
> +static inline int __scsi_sense_is_deferred(u8 response_code)
> +{
> +	return ((response_code >= 0x70) && (response_code & 1));
> +}
> +
>   static inline int scsi_sense_is_deferred(struct scsi_sense_hdr *sshdr)
>   {
> -	return ((sshdr->response_code >= 0x70) && (sshdr->response_code & 1));
> +	return __scsi_sense_is_deferred(sshdr->response_code);
>   }
>
>   extern const u8 * scsi_sense_desc_find(const u8 * sense_buffer, int sb_len,
> diff --git a/include/trace/events/scsi.h b/include/trace/events/scsi.h
> index 0675195..572aa65 100644
> --- a/include/trace/events/scsi.h
> +++ b/include/trace/events/scsi.h
> @@ -395,6 +395,54 @@ TRACE_EVENT(scsi_show_result,
>   		  show_hostbyte_name(host_byte(__entry->result)))
>   );
>
> +const char *scsi_trace_decode_sense_extras(struct trace_seq*, u8, u8,
> +					   const unsigned char*, int, int);
> +#define __decode_extras(sense_key, res_code, buf, len, raw) \
> +	scsi_trace_decode_sense_extras(p, sense_key, res_code, buf, len, raw)
> +
> +TRACE_EVENT(scsi_print_sense,
> +
> +	TP_PROTO(struct scsi_device *sdev, const char *devname,
> +		 struct scsi_sense_hdr *sshdr,
> +		 const unsigned char *sense_buffer, int sense_len, int raw),
> +
> +	TP_ARGS(sdev, devname, sshdr, sense_buffer, sense_len, raw),
> +
> +	TP_STRUCT__entry(
> +		__field( unsigned int,		host_no		)
> +		__field( unsigned int,		channel		)
> +		__field( unsigned int,		id		)
> +		__field( unsigned int,		lun		)
> +		__string(devname,		devname		)
> +		__field( u8,			sense_key	)
> +		__field( u8,			res_code	)
> +		__dynamic_array(unsigned char,	sense_buffer, sense_len)
> +		__field( u8,			asc		)
> +		__field( u8,			ascq		)
> +		__field( int,			sense_len	)
> +		__field( int,			raw		)
> +	),
> +
> +	TP_fast_assign(
> +		__entry->host_no	= sdev->host->host_no;
> +		__entry->channel	= sdev->channel;
> +		__entry->id		= sdev->id;
> +		__entry->lun		= sdev->lun;
> +		__assign_str(devname, devname);
> +		__entry->sense_key	= sshdr->sense_key;
> +		__entry->res_code	= sshdr->response_code;
> +		memcpy(__get_dynamic_array(sense_buffer), sense_buffer,
> +		       sense_len);
> +		__entry->sense_len	= sense_len;
> +		__entry->raw		= raw;
> +	),
> +
> +	TP_printk("host_no=%u channel=%u id=%u lun=%u [%s] %s",
> +		  __entry->host_no, __entry->channel, __entry->id, __entry->lun,
> +		  __get_str(devname), __decode_extras(__entry->sense_key,
> +		  __entry->res_code, __get_dynamic_array(sense_buffer),
> +		  __entry->sense_len,  __entry->raw))
> +);
>   #endif /*  _TRACE_SCSI_H */
>
>   /* This part must be outside protection */
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-scsi" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
Same here:
Please use the functions from constants.c and delete the 
functionality from scsi_trace.

And we should remove the code to interpret any sense code extras.
But other than that having trace points for sense code printing is a 
really good idea.
Care to send this as a separate patch?

Cheers,

Hannes
--
Dr. Hannes Reinecke		      zSeries & Storage
hare@xxxxxxx			      +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 NÃrnberg
GF: J. Hawn, J. Guild, F. ImendÃrffer, HRB 16746 (AG NÃrnberg)
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/