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

Yoshihiro YUNOMAE
2014-08-08T11:50:25Z

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@hitachi.com>
Cc: Hannes Reinecke <hare@suse.de>
Cc: Doug Gilbert <dgilbert@interlog.com>
Cc: Martin K. Petersen <martin.petersen@oracle.com>
Cc: Christoph Hellwig <hch@lst.de>
Cc: "James E.J. Bottomley" <JBottomley@parallels.com>
Cc: Hidehiro Kawai <hidehiro.kawai.ez@hitachi.com>
Cc: Masami Hiramatsu <masami.hiramatsu.pt@hitachi.com>
---
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 */