2010-02-01 04:56:20

by Kei Tokunaga

[permalink] [raw]
Subject: [PATCH 0/2 v2] scsi: ftrace based scsi tracing feature

Hi,

This is v2 patch series of SCSI trace.

Changelog from v1:

- fixed variable length command handling (DIF_TYPE2 case only)
- moved scsi trace functions from kernel/trace/scsitrace.c to
drivers/scsi/scsi_trace.c

Here are the links to the discussions on v1:

[PATCH 0/2] scsi: ftrace based scsi tracing feature
http://marc.info/?l=linux-scsi&m=126396981308416&w=2
[PATCH 1/2] scsi: add __print_hex() to ftrace
http://marc.info/?l=linux-scsi&m=126396984308451&w=2
[PATCH 2/2] scsi: add scsi trace core function and put trace points
http://marc.info/?l=linux-scsi&m=126396987608486&w=2

This patchset applies to 2.6.33-rc6.

Thanks,
Kei


2010-02-01 05:05:42

by Kei Tokunaga

[permalink] [raw]
Subject: [PATCH 1/2 v2] scsi: add __print_hex() to ftrace

From: Li Zefan <[email protected]>

This is the same patch from v1.

__print_hex() prints values in an array in hex (w/o '0x') (space separated)
EX) 92 33 32 f3 ee 4d

Signed-off-by: Li Zefan <[email protected]>
Signed-off-by: Tomohiro Kusumi <[email protected]>
Signed-off-by: Kei Tokunaga <[email protected]>


---

linux-2.6.33-rc6-trace-kei/include/linux/ftrace_event.h | 3 +++
linux-2.6.33-rc6-trace-kei/include/trace/ftrace.h | 3 +++
linux-2.6.33-rc6-trace-kei/kernel/trace/trace_output.c | 15 +++++++++++++++
3 files changed, 21 insertions(+)

diff -puN include/linux/ftrace_event.h~ftrace_print_hex include/linux/ftrace_event.h
--- linux-2.6.33-rc6-trace/include/linux/ftrace_event.h~ftrace_print_hex 2010-02-01 11:56:32.000000000 +0900
+++ linux-2.6.33-rc6-trace-kei/include/linux/ftrace_event.h 2010-02-01 11:56:32.000000000 +0900
@@ -24,6 +24,9 @@ const char *ftrace_print_flags_seq(struc
const char *ftrace_print_symbols_seq(struct trace_seq *p, unsigned long val,
const struct trace_print_flags *symbol_array);

+const char *ftrace_print_hex_seq(struct trace_seq *p,
+ const unsigned char *buf, int len);
+
/*
* The trace entry - the most basic unit of tracing. This is what
* is printed in the end as a single line in the trace output, such as:
diff -puN include/trace/ftrace.h~ftrace_print_hex include/trace/ftrace.h
--- linux-2.6.33-rc6-trace/include/trace/ftrace.h~ftrace_print_hex 2010-02-01 11:56:32.000000000 +0900
+++ linux-2.6.33-rc6-trace-kei/include/trace/ftrace.h 2010-02-01 11:56:32.000000000 +0900
@@ -321,6 +321,9 @@ ftrace_format_##name(struct ftrace_event
ftrace_print_symbols_seq(p, value, symbols); \
})

+#undef __print_hex
+#define __print_hex(buf, buf_len) ftrace_print_hex_seq(p, buf, buf_len)
+
#undef DECLARE_EVENT_CLASS
#define DECLARE_EVENT_CLASS(call, proto, args, tstruct, assign, print) \
static enum print_line_t \
diff -puN kernel/trace/trace_output.c~ftrace_print_hex kernel/trace/trace_output.c
--- linux-2.6.33-rc6-trace/kernel/trace/trace_output.c~ftrace_print_hex 2010-02-01 11:56:32.000000000 +0900
+++ linux-2.6.33-rc6-trace-kei/kernel/trace/trace_output.c 2010-02-01 11:56:32.000000000 +0900
@@ -355,6 +355,21 @@ ftrace_print_symbols_seq(struct trace_se
}
EXPORT_SYMBOL(ftrace_print_symbols_seq);

+const char *
+ftrace_print_hex_seq(struct trace_seq *p, const unsigned char *buf, int buf_len)
+{
+ int i;
+ const char *ret = p->buffer + p->len;
+
+ for (i = 0; i < buf_len; i++)
+ trace_seq_printf(p, "%s%2.2x", i == 0 ? "" : " ", buf[i]);
+
+ trace_seq_putc(p, 0);
+
+ return ret;
+}
+EXPORT_SYMBOL(ftrace_print_hex_seq);
+
#ifdef CONFIG_KRETPROBES
static inline const char *kretprobed(const char *name)
{

_


2010-02-01 05:07:56

by Kei Tokunaga

[permalink] [raw]
Subject: [PATCH 2/2 v2] scsi: add scsi trace core function and put trace points

This is v2 patchset.

Changelog from v1:

- fixed variable length command handling (DIF_TYPE2 case only)
- moved scsi trace functions from kernel/trace/scsitrace.c to
drivers/scsi/scsi_trace.c (new file)

Although Martin gave me a good sight that decoding some other fields
and some other commands might be nice, those are not added in this
version.

Trace points are the same from the last time as follows:

- when a command is about to be dispatched.
- when a command dispatched returns in error.
- when a command is done.
- when an error handler is about to waken up.
- when timeout of a command is detected.

Here is an outputs example:

# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
flush-8:0-3746 [001] 1374.517152: scsi_dispatch_cmd_start: host_no=0 channel=0 id=0 lun=0 cmnd=(WRITE_10 lba=32267539 txlen=8 raw=2a 00 01 ec 5d 13 00 00 08 00)
<idle>-0 [000] 1374.524964: scsi_dispatch_cmd_done: host_no=0 channel=0 id=0 lun=0 cmnd=(WRITE_10 lba=32267539 txlen=8 raw=2a 00 01 ec 5d 13 00 00 08 00) result=(driver=DRIVER_OK host=DID_OK message=COMMAND_COMPLETE status=SAM_STAT_GOOD)

Signed-off-by: Xiao Guangrong <[email protected]>
Signed-off-by: Tomohiro Kusumi <[email protected]>
Signed-off-by: Kei Tokunaga <[email protected]>


---

linux-2.6.33-rc6-trace-kei/drivers/scsi/Makefile | 1
linux-2.6.33-rc6-trace-kei/drivers/scsi/scsi.c | 6
linux-2.6.33-rc6-trace-kei/drivers/scsi/scsi_error.c | 4
linux-2.6.33-rc6-trace-kei/drivers/scsi/scsi_trace.c | 188 +++++++++
linux-2.6.33-rc6-trace-kei/include/trace/events/scsi.h | 328 +++++++++++++++++
linux-2.6.33-rc6-trace-kei/kernel/trace/trace_output.c | 1
6 files changed, 528 insertions(+)

diff -puN drivers/scsi/Makefile~scsi_trace drivers/scsi/Makefile
--- linux-2.6.33-rc6-trace/drivers/scsi/Makefile~scsi_trace 2010-02-01 11:56:35.000000000 +0900
+++ linux-2.6.33-rc6-trace-kei/drivers/scsi/Makefile 2010-02-01 11:56:35.000000000 +0900
@@ -162,6 +162,7 @@ scsi_mod-y += scsi_scan.o scsi_sysfs.o
scsi_mod-$(CONFIG_SCSI_NETLINK) += scsi_netlink.o
scsi_mod-$(CONFIG_SYSCTL) += scsi_sysctl.o
scsi_mod-$(CONFIG_SCSI_PROC_FS) += scsi_proc.o
+scsi_mod-y += scsi_trace.o

scsi_tgt-y += scsi_tgt_lib.o scsi_tgt_if.o

diff -puN drivers/scsi/scsi.c~scsi_trace drivers/scsi/scsi.c
--- linux-2.6.33-rc6-trace/drivers/scsi/scsi.c~scsi_trace 2010-02-01 11:56:35.000000000 +0900
+++ linux-2.6.33-rc6-trace-kei/drivers/scsi/scsi.c 2010-02-01 11:56:35.000000000 +0900
@@ -67,6 +67,9 @@
#include "scsi_priv.h"
#include "scsi_logging.h"

+#define CREATE_TRACE_POINTS
+#include <trace/events/scsi.h>
+
static void scsi_done(struct scsi_cmnd *cmd);

/*
@@ -747,10 +750,12 @@ int scsi_dispatch_cmd(struct scsi_cmnd *
cmd->result = (DID_NO_CONNECT << 16);
scsi_done(cmd);
} else {
+ trace_scsi_dispatch_cmd_start(cmd);
rtn = host->hostt->queuecommand(cmd, scsi_done);
}
spin_unlock_irqrestore(host->host_lock, flags);
if (rtn) {
+ trace_scsi_dispatch_cmd_error(cmd, rtn);
if (rtn != SCSI_MLQUEUE_DEVICE_BUSY &&
rtn != SCSI_MLQUEUE_TARGET_BUSY)
rtn = SCSI_MLQUEUE_HOST_BUSY;
@@ -781,6 +786,7 @@ int scsi_dispatch_cmd(struct scsi_cmnd *
*/
static void scsi_done(struct scsi_cmnd *cmd)
{
+ trace_scsi_dispatch_cmd_done(cmd);
blk_complete_request(cmd->request);
}

diff -puN drivers/scsi/scsi_error.c~scsi_trace drivers/scsi/scsi_error.c
--- linux-2.6.33-rc6-trace/drivers/scsi/scsi_error.c~scsi_trace 2010-02-01 11:56:35.000000000 +0900
+++ linux-2.6.33-rc6-trace-kei/drivers/scsi/scsi_error.c 2010-02-01 11:56:35.000000000 +0900
@@ -38,6 +38,8 @@
#include "scsi_logging.h"
#include "scsi_transport_api.h"

+#include <trace/events/scsi.h>
+
#define SENSE_TIMEOUT (10*HZ)

/*
@@ -51,6 +53,7 @@
void scsi_eh_wakeup(struct Scsi_Host *shost)
{
if (shost->host_busy == shost->host_failed) {
+ trace_scsi_eh_wakeup(shost);
wake_up_process(shost->ehandler);
SCSI_LOG_ERROR_RECOVERY(5,
printk("Waking error handler thread\n"));
@@ -126,6 +129,7 @@ enum blk_eh_timer_return scsi_times_out(
struct scsi_cmnd *scmd = req->special;
enum blk_eh_timer_return rtn = BLK_EH_NOT_HANDLED;

+ trace_scsi_dispatch_cmd_timeout(scmd);
scsi_log_completion(scmd, TIMEOUT_ERROR);

if (scmd->device->host->transportt->eh_timed_out)
diff -puN /dev/null drivers/scsi/scsi_trace.c
--- /dev/null 2010-01-29 22:19:42.380425002 +0900
+++ linux-2.6.33-rc6-trace-kei/drivers/scsi/scsi_trace.c 2010-02-01 11:56:35.000000000 +0900
@@ -0,0 +1,188 @@
+/*
+ * Copyright (C) 2010 FUJITSU LIMITED
+ * Copyright (C) 2010 Tomohiro Kusumi <[email protected]>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 2 as
+ * published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA
+ */
+#include <linux/kernel.h>
+#include <linux/trace_seq.h>
+#include <trace/events/scsi.h>
+
+#define SERVICE_ACTION(cdb) ((cdb[8] << 8) | cdb[9])
+
+static const char *
+scsi_trace_misc(struct trace_seq *, unsigned char *, int);
+
+static const char *
+scsi_trace_rw6(struct trace_seq *p, unsigned char *cdb, int len)
+{
+ const char *ret = p->buffer + p->len;
+ sector_t lba = 0, txlen = 0;
+
+ lba |= ((cdb[1] & 0x1F) << 16);
+ lba |= (cdb[2] << 8);
+ lba |= cdb[3];
+ txlen = cdb[4];
+
+ trace_seq_printf(p, "lba=%llu txlen=%llu",
+ (unsigned long long)lba, (unsigned long long)txlen);
+ trace_seq_putc(p, 0);
+
+ return ret;
+}
+
+static const char *
+scsi_trace_rw10(struct trace_seq *p, unsigned char *cdb, int len)
+{
+ const char *ret = p->buffer + p->len;
+ sector_t lba = 0, txlen = 0;
+
+ lba |= (cdb[2] << 24);
+ lba |= (cdb[3] << 16);
+ lba |= (cdb[4] << 8);
+ lba |= cdb[5];
+ txlen |= (cdb[7] << 8);
+ txlen |= cdb[8];
+
+ trace_seq_printf(p, "lba=%llu txlen=%llu",
+ (unsigned long long)lba, (unsigned long long)txlen);
+ trace_seq_putc(p, 0);
+
+ return ret;
+}
+
+static const char *
+scsi_trace_rw12(struct trace_seq *p, unsigned char *cdb, int len)
+{
+ const char *ret = p->buffer + p->len;
+ sector_t lba = 0, txlen = 0;
+
+ lba |= (cdb[2] << 24);
+ lba |= (cdb[3] << 16);
+ lba |= (cdb[4] << 8);
+ lba |= cdb[5];
+ txlen |= (cdb[6] << 24);
+ txlen |= (cdb[7] << 16);
+ txlen |= (cdb[8] << 8);
+ txlen |= cdb[9];
+
+ trace_seq_printf(p, "lba=%llu txlen=%llu",
+ (unsigned long long)lba, (unsigned long long)txlen);
+ trace_seq_putc(p, 0);
+
+ return ret;
+}
+
+static const char *
+scsi_trace_rw16(struct trace_seq *p, unsigned char *cdb, int len)
+{
+ const char *ret = p->buffer + p->len;
+ sector_t lba = 0, txlen = 0;
+
+ lba |= ((u64)cdb[2] << 56);
+ lba |= ((u64)cdb[3] << 48);
+ lba |= ((u64)cdb[4] << 40);
+ lba |= ((u64)cdb[5] << 32);
+ lba |= (cdb[6] << 24);
+ lba |= (cdb[7] << 16);
+ lba |= (cdb[8] << 8);
+ lba |= cdb[9];
+ txlen |= (cdb[10] << 24);
+ txlen |= (cdb[11] << 16);
+ txlen |= (cdb[12] << 8);
+ txlen |= cdb[13];
+
+ trace_seq_printf(p, "lba=%llu txlen=%llu",
+ (unsigned long long)lba, (unsigned long long)txlen);
+ trace_seq_putc(p, 0);
+
+ return ret;
+}
+
+static const char *
+scsi_trace_rw32(struct trace_seq *p, unsigned char *cdb, int len)
+{
+ const char *ret = p->buffer + p->len;
+ sector_t lba = 0, txlen = 0;
+
+ lba |= ((u64)cdb[12] << 56);
+ lba |= ((u64)cdb[13] << 48);
+ lba |= ((u64)cdb[14] << 40);
+ lba |= ((u64)cdb[15] << 32);
+ lba |= (cdb[16] << 24);
+ lba |= (cdb[17] << 16);
+ lba |= (cdb[18] << 8);
+ lba |= cdb[19];
+ txlen |= (cdb[28] << 24);
+ txlen |= (cdb[29] << 16);
+ txlen |= (cdb[30] << 8);
+ txlen |= cdb[31];
+
+ trace_seq_printf(p, "%s_32 lba=%llu txlen=%llu",
+ (SERVICE_ACTION(cdb) == READ_32 ? "READ" : "WRITE"),
+ (unsigned long long)lba, (unsigned long long)txlen);
+
+ trace_seq_putc(p, 0);
+
+ return ret;
+}
+
+static const char *
+scsi_trace_varlen(struct trace_seq *p, unsigned char *cdb, int len)
+{
+ switch (SERVICE_ACTION(cdb)) {
+ case READ_32:
+ case WRITE_32:
+ /* if protection is enabled */
+ if (((cdb[10] >> 5) & 0x7) == 1)
+ return scsi_trace_rw32(p, cdb, len);
+ /* fall through */
+ default:
+ return scsi_trace_misc(p, cdb, len);
+ }
+}
+
+static const char *
+scsi_trace_misc(struct trace_seq *p, unsigned char *cdb, int len)
+{
+ const char *ret = p->buffer + p->len;
+
+ trace_seq_printf(p, "-");
+ trace_seq_putc(p, 0);
+
+ return ret;
+}
+
+const char *
+scsi_trace_parse_cdb(struct trace_seq *p, unsigned char *cdb, int len)
+{
+ switch (cdb[0]) {
+ case READ_6:
+ case WRITE_6:
+ return scsi_trace_rw6(p, cdb, len);
+ case READ_10:
+ case WRITE_10:
+ return scsi_trace_rw10(p, cdb, len);
+ case READ_12:
+ case WRITE_12:
+ return scsi_trace_rw12(p, cdb, len);
+ case READ_16:
+ case WRITE_16:
+ return scsi_trace_rw16(p, cdb, len);
+ case VARIABLE_LENGTH_CMD:
+ return scsi_trace_varlen(p, cdb, len);
+ default:
+ return scsi_trace_misc(p, cdb, len);
+ }
+}
diff -puN /dev/null include/trace/events/scsi.h
--- /dev/null 2010-01-29 22:19:42.380425002 +0900
+++ linux-2.6.33-rc6-trace-kei/include/trace/events/scsi.h 2010-02-01 11:56:35.000000000 +0900
@@ -0,0 +1,328 @@
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM scsi
+
+#if !defined(_TRACE_SCSI_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_SCSI_H
+
+#include <scsi/scsi_cmnd.h>
+#include <scsi/scsi_host.h>
+#include <linux/tracepoint.h>
+#include <linux/trace_seq.h>
+
+#define scsi_opcode_name(opcode) { opcode, #opcode }
+#define show_opcode_name(val) \
+ __print_symbolic(val, \
+ scsi_opcode_name(TEST_UNIT_READY), \
+ scsi_opcode_name(REZERO_UNIT), \
+ scsi_opcode_name(REQUEST_SENSE), \
+ scsi_opcode_name(FORMAT_UNIT), \
+ scsi_opcode_name(READ_BLOCK_LIMITS), \
+ scsi_opcode_name(REASSIGN_BLOCKS), \
+ scsi_opcode_name(INITIALIZE_ELEMENT_STATUS), \
+ scsi_opcode_name(READ_6), \
+ scsi_opcode_name(WRITE_6), \
+ scsi_opcode_name(SEEK_6), \
+ scsi_opcode_name(READ_REVERSE), \
+ scsi_opcode_name(WRITE_FILEMARKS), \
+ scsi_opcode_name(SPACE), \
+ scsi_opcode_name(INQUIRY), \
+ scsi_opcode_name(RECOVER_BUFFERED_DATA), \
+ scsi_opcode_name(MODE_SELECT), \
+ scsi_opcode_name(RESERVE), \
+ scsi_opcode_name(RELEASE), \
+ scsi_opcode_name(COPY), \
+ scsi_opcode_name(ERASE), \
+ scsi_opcode_name(MODE_SENSE), \
+ scsi_opcode_name(START_STOP), \
+ scsi_opcode_name(RECEIVE_DIAGNOSTIC), \
+ scsi_opcode_name(SEND_DIAGNOSTIC), \
+ scsi_opcode_name(ALLOW_MEDIUM_REMOVAL), \
+ scsi_opcode_name(SET_WINDOW), \
+ scsi_opcode_name(READ_CAPACITY), \
+ scsi_opcode_name(READ_10), \
+ scsi_opcode_name(WRITE_10), \
+ scsi_opcode_name(SEEK_10), \
+ scsi_opcode_name(POSITION_TO_ELEMENT), \
+ scsi_opcode_name(WRITE_VERIFY), \
+ scsi_opcode_name(VERIFY), \
+ scsi_opcode_name(SEARCH_HIGH), \
+ scsi_opcode_name(SEARCH_EQUAL), \
+ scsi_opcode_name(SEARCH_LOW), \
+ scsi_opcode_name(SET_LIMITS), \
+ scsi_opcode_name(PRE_FETCH), \
+ scsi_opcode_name(READ_POSITION), \
+ scsi_opcode_name(SYNCHRONIZE_CACHE), \
+ scsi_opcode_name(LOCK_UNLOCK_CACHE), \
+ scsi_opcode_name(READ_DEFECT_DATA), \
+ scsi_opcode_name(MEDIUM_SCAN), \
+ scsi_opcode_name(COMPARE), \
+ scsi_opcode_name(COPY_VERIFY), \
+ scsi_opcode_name(WRITE_BUFFER), \
+ scsi_opcode_name(READ_BUFFER), \
+ scsi_opcode_name(UPDATE_BLOCK), \
+ scsi_opcode_name(READ_LONG), \
+ scsi_opcode_name(WRITE_LONG), \
+ scsi_opcode_name(CHANGE_DEFINITION), \
+ scsi_opcode_name(WRITE_SAME), \
+ scsi_opcode_name(UNMAP), \
+ scsi_opcode_name(READ_TOC), \
+ scsi_opcode_name(LOG_SELECT), \
+ scsi_opcode_name(LOG_SENSE), \
+ scsi_opcode_name(XDWRITEREAD_10), \
+ scsi_opcode_name(MODE_SELECT_10), \
+ scsi_opcode_name(RESERVE_10), \
+ scsi_opcode_name(RELEASE_10), \
+ scsi_opcode_name(MODE_SENSE_10), \
+ scsi_opcode_name(PERSISTENT_RESERVE_IN), \
+ scsi_opcode_name(PERSISTENT_RESERVE_OUT), \
+ scsi_opcode_name(VARIABLE_LENGTH_CMD), \
+ scsi_opcode_name(REPORT_LUNS), \
+ scsi_opcode_name(MAINTENANCE_IN), \
+ scsi_opcode_name(MAINTENANCE_OUT), \
+ scsi_opcode_name(MOVE_MEDIUM), \
+ scsi_opcode_name(EXCHANGE_MEDIUM), \
+ scsi_opcode_name(READ_12), \
+ scsi_opcode_name(WRITE_12), \
+ scsi_opcode_name(WRITE_VERIFY_12), \
+ scsi_opcode_name(SEARCH_HIGH_12), \
+ scsi_opcode_name(SEARCH_EQUAL_12), \
+ scsi_opcode_name(SEARCH_LOW_12), \
+ scsi_opcode_name(READ_ELEMENT_STATUS), \
+ scsi_opcode_name(SEND_VOLUME_TAG), \
+ scsi_opcode_name(WRITE_LONG_2), \
+ scsi_opcode_name(READ_16), \
+ scsi_opcode_name(WRITE_16), \
+ scsi_opcode_name(VERIFY_16), \
+ scsi_opcode_name(WRITE_SAME_16), \
+ scsi_opcode_name(SERVICE_ACTION_IN), \
+ scsi_opcode_name(SAI_READ_CAPACITY_16), \
+ scsi_opcode_name(SAI_GET_LBA_STATUS), \
+ scsi_opcode_name(MI_REPORT_TARGET_PGS), \
+ scsi_opcode_name(MO_SET_TARGET_PGS), \
+ scsi_opcode_name(READ_32), \
+ scsi_opcode_name(WRITE_32), \
+ scsi_opcode_name(WRITE_SAME_32), \
+ scsi_opcode_name(ATA_16), \
+ scsi_opcode_name(ATA_12))
+
+#define scsi_hostbyte_name(result) { result, #result }
+#define show_hostbyte_name(val) \
+ __print_symbolic(val, \
+ scsi_hostbyte_name(DID_OK), \
+ scsi_hostbyte_name(DID_NO_CONNECT), \
+ scsi_hostbyte_name(DID_BUS_BUSY), \
+ scsi_hostbyte_name(DID_TIME_OUT), \
+ scsi_hostbyte_name(DID_BAD_TARGET), \
+ scsi_hostbyte_name(DID_ABORT), \
+ scsi_hostbyte_name(DID_PARITY), \
+ scsi_hostbyte_name(DID_ERROR), \
+ scsi_hostbyte_name(DID_RESET), \
+ scsi_hostbyte_name(DID_BAD_INTR), \
+ scsi_hostbyte_name(DID_PASSTHROUGH), \
+ scsi_hostbyte_name(DID_SOFT_ERROR), \
+ scsi_hostbyte_name(DID_IMM_RETRY), \
+ scsi_hostbyte_name(DID_REQUEUE), \
+ scsi_hostbyte_name(DID_TRANSPORT_DISRUPTED), \
+ scsi_hostbyte_name(DID_TRANSPORT_FAILFAST))
+
+#define scsi_driverbyte_name(result) { result, #result }
+#define show_driverbyte_name(val) \
+ __print_symbolic(val, \
+ scsi_driverbyte_name(DRIVER_OK), \
+ scsi_driverbyte_name(DRIVER_BUSY), \
+ scsi_driverbyte_name(DRIVER_SOFT), \
+ scsi_driverbyte_name(DRIVER_MEDIA), \
+ scsi_driverbyte_name(DRIVER_ERROR), \
+ scsi_driverbyte_name(DRIVER_INVALID), \
+ scsi_driverbyte_name(DRIVER_TIMEOUT), \
+ scsi_driverbyte_name(DRIVER_HARD), \
+ scsi_driverbyte_name(DRIVER_SENSE))
+
+#define scsi_msgbyte_name(result) { result, #result }
+#define show_msgbyte_name(val) \
+ __print_symbolic(val, \
+ scsi_msgbyte_name(COMMAND_COMPLETE), \
+ scsi_msgbyte_name(EXTENDED_MESSAGE), \
+ scsi_msgbyte_name(SAVE_POINTERS), \
+ scsi_msgbyte_name(RESTORE_POINTERS), \
+ scsi_msgbyte_name(DISCONNECT), \
+ scsi_msgbyte_name(INITIATOR_ERROR), \
+ scsi_msgbyte_name(ABORT_TASK_SET), \
+ scsi_msgbyte_name(MESSAGE_REJECT), \
+ scsi_msgbyte_name(NOP), \
+ scsi_msgbyte_name(MSG_PARITY_ERROR), \
+ scsi_msgbyte_name(LINKED_CMD_COMPLETE), \
+ scsi_msgbyte_name(LINKED_FLG_CMD_COMPLETE), \
+ scsi_msgbyte_name(TARGET_RESET), \
+ scsi_msgbyte_name(ABORT_TASK), \
+ scsi_msgbyte_name(CLEAR_TASK_SET), \
+ scsi_msgbyte_name(INITIATE_RECOVERY), \
+ scsi_msgbyte_name(RELEASE_RECOVERY), \
+ scsi_msgbyte_name(CLEAR_ACA), \
+ scsi_msgbyte_name(LOGICAL_UNIT_RESET), \
+ scsi_msgbyte_name(SIMPLE_QUEUE_TAG), \
+ scsi_msgbyte_name(HEAD_OF_QUEUE_TAG), \
+ scsi_msgbyte_name(ORDERED_QUEUE_TAG), \
+ scsi_msgbyte_name(IGNORE_WIDE_RESIDUE), \
+ scsi_msgbyte_name(ACA), \
+ scsi_msgbyte_name(QAS_REQUEST), \
+ scsi_msgbyte_name(BUS_DEVICE_RESET), \
+ scsi_msgbyte_name(ABORT))
+
+#define scsi_statusbyte_name(result) { result, #result }
+#define show_statusbyte_name(val) \
+ __print_symbolic(val, \
+ scsi_statusbyte_name(SAM_STAT_GOOD), \
+ scsi_statusbyte_name(SAM_STAT_CHECK_CONDITION), \
+ scsi_statusbyte_name(SAM_STAT_CONDITION_MET), \
+ scsi_statusbyte_name(SAM_STAT_BUSY), \
+ scsi_statusbyte_name(SAM_STAT_INTERMEDIATE), \
+ scsi_statusbyte_name(SAM_STAT_INTERMEDIATE_CONDITION_MET), \
+ scsi_statusbyte_name(SAM_STAT_RESERVATION_CONFLICT), \
+ scsi_statusbyte_name(SAM_STAT_COMMAND_TERMINATED), \
+ scsi_statusbyte_name(SAM_STAT_TASK_SET_FULL), \
+ scsi_statusbyte_name(SAM_STAT_ACA_ACTIVE), \
+ scsi_statusbyte_name(SAM_STAT_TASK_ABORTED))
+
+const char *scsi_trace_parse_cdb(struct trace_seq*, unsigned char*, int);
+#define __parse_cdb(cdb, len) scsi_trace_parse_cdb(p, cdb, len)
+
+TRACE_EVENT(scsi_dispatch_cmd_start,
+
+ TP_PROTO(struct scsi_cmnd *cmd),
+
+ TP_ARGS(cmd),
+
+ TP_STRUCT__entry(
+ __field( unsigned int, host_no )
+ __field( unsigned int, channel )
+ __field( unsigned int, id )
+ __field( unsigned int, lun )
+ __field( unsigned int, opcode )
+ __field( unsigned int, cmd_len )
+ __dynamic_array(unsigned char, cmnd, cmd->cmd_len)
+ ),
+
+ TP_fast_assign(
+ __entry->host_no = cmd->device->host->host_no;
+ __entry->channel = cmd->device->channel;
+ __entry->id = cmd->device->id;
+ __entry->lun = cmd->device->lun;
+ __entry->opcode = cmd->cmnd[0];
+ __entry->cmd_len = cmd->cmd_len;
+ memcpy(__get_dynamic_array(cmnd), cmd->cmnd, cmd->cmd_len);
+ ),
+
+ TP_printk("host_no=%u channel=%u id=%u lun=%u cmnd=(%s %s raw=%s)",
+ __entry->host_no, __entry->channel, __entry->id,
+ __entry->lun, show_opcode_name(__entry->opcode),
+ __parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
+ __print_hex(__get_dynamic_array(cmnd), __entry->cmd_len))
+);
+
+TRACE_EVENT(scsi_dispatch_cmd_error,
+
+ TP_PROTO(struct scsi_cmnd *cmd, int rtn),
+
+ TP_ARGS(cmd, rtn),
+
+ TP_STRUCT__entry(
+ __field( unsigned int, host_no )
+ __field( unsigned int, channel )
+ __field( unsigned int, id )
+ __field( unsigned int, lun )
+ __field( int, rtn )
+ __field( unsigned int, opcode )
+ __field( unsigned int, cmd_len )
+ __dynamic_array(unsigned char, cmnd, cmd->cmd_len)
+ ),
+
+ TP_fast_assign(
+ __entry->host_no = cmd->device->host->host_no;
+ __entry->channel = cmd->device->channel;
+ __entry->id = cmd->device->id;
+ __entry->lun = cmd->device->lun;
+ __entry->rtn = rtn;
+ __entry->opcode = cmd->cmnd[0];
+ __entry->cmd_len = cmd->cmd_len;
+ memcpy(__get_dynamic_array(cmnd), cmd->cmnd, cmd->cmd_len);
+ ),
+
+ TP_printk("host_no=%u channel=%u id=%u lun=%u cmnd=(%s %s raw=%s)"
+ " rtn=%d",
+ __entry->host_no, __entry->channel, __entry->id,
+ __entry->lun, show_opcode_name(__entry->opcode),
+ __parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
+ __print_hex(__get_dynamic_array(cmnd), __entry->cmd_len),
+ __entry->rtn)
+);
+
+DECLARE_EVENT_CLASS(scsi_cmd_done_timeout_template,
+
+ TP_PROTO(struct scsi_cmnd *cmd),
+
+ TP_ARGS(cmd),
+
+ TP_STRUCT__entry(
+ __field( unsigned int, host_no )
+ __field( unsigned int, channel )
+ __field( unsigned int, id )
+ __field( unsigned int, lun )
+ __field( int, result )
+ __field( unsigned int, opcode )
+ __field( unsigned int, cmd_len )
+ __dynamic_array(unsigned char, cmnd, cmd->cmd_len)
+ ),
+
+ TP_fast_assign(
+ __entry->host_no = cmd->device->host->host_no;
+ __entry->channel = cmd->device->channel;
+ __entry->id = cmd->device->id;
+ __entry->lun = cmd->device->lun;
+ __entry->result = cmd->result;
+ __entry->opcode = cmd->cmnd[0];
+ __entry->cmd_len = cmd->cmd_len;
+ memcpy(__get_dynamic_array(cmnd), cmd->cmnd, cmd->cmd_len);
+ ),
+
+ TP_printk("host_no=%u channel=%u id=%u lun=%u cmnd=(%s %s raw=%s) "
+ "result=(driver=%s host=%s message=%s status=%s)",
+ __entry->host_no, __entry->channel, __entry->id,
+ __entry->lun, show_opcode_name(__entry->opcode),
+ __parse_cdb(__get_dynamic_array(cmnd), __entry->cmd_len),
+ __print_hex(__get_dynamic_array(cmnd), __entry->cmd_len),
+ show_driverbyte_name(((__entry->result) >> 24) & 0xff),
+ show_hostbyte_name(((__entry->result) >> 16) & 0xff),
+ show_msgbyte_name(((__entry->result) >> 8) & 0xff),
+ show_statusbyte_name(__entry->result & 0xff))
+);
+
+DEFINE_EVENT(scsi_cmd_done_timeout_template, scsi_dispatch_cmd_done,
+ TP_PROTO(struct scsi_cmnd *cmd),
+ TP_ARGS(cmd));
+
+DEFINE_EVENT(scsi_cmd_done_timeout_template, scsi_dispatch_cmd_timeout,
+ TP_PROTO(struct scsi_cmnd *cmd),
+ TP_ARGS(cmd));
+
+TRACE_EVENT(scsi_eh_wakeup,
+
+ TP_PROTO(struct Scsi_Host *shost),
+
+ TP_ARGS(shost),
+
+ TP_STRUCT__entry(
+ __field( unsigned int, host_no )
+ ),
+
+ TP_fast_assign(
+ __entry->host_no = shost->host_no;
+ ),
+
+ TP_printk("host_no=%u", __entry->host_no)
+);
+
+#endif /* _TRACE_SCSI_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff -puN kernel/trace/trace_output.c~scsi_trace kernel/trace/trace_output.c
--- linux-2.6.33-rc6-trace/kernel/trace/trace_output.c~scsi_trace 2010-02-01 11:56:35.000000000 +0900
+++ linux-2.6.33-rc6-trace-kei/kernel/trace/trace_output.c 2010-02-01 11:56:35.000000000 +0900
@@ -209,6 +209,7 @@ int trace_seq_putc(struct trace_seq *s,

return 1;
}
+EXPORT_SYMBOL(trace_seq_putc);

int trace_seq_putmem(struct trace_seq *s, const void *mem, size_t len)
{

_


2010-02-02 23:13:16

by Martin K. Petersen

[permalink] [raw]
Subject: Re: [PATCH 2/2 v2] scsi: add scsi trace core function and put trace points

>>>>> "Kei" == Kei Tokunaga <[email protected]> writes:

I'm traveling so I won't have time to look at this closely until next
week. However, this caught my eye:

+static const char *
+scsi_trace_varlen(struct trace_seq *p, unsigned char *cdb, int len)
+{
+ switch (SERVICE_ACTION(cdb)) {
+ case READ_32:
+ case WRITE_32:
+ /* if protection is enabled */
+ if (((cdb[10] >> 5) & 0x7) == 1)
+ return scsi_trace_rw32(p, cdb, len);
+ /* fall through */
+ default:
+ return scsi_trace_misc(p, cdb, len);
+ }
+}

It is not a requirement that a 32-byte READ/WRITE request must have
PROTECT set. So that if statement is bogus.

--
Martin K. Petersen Oracle Linux Engineering

2010-02-03 05:56:06

by Kei Tokunaga

[permalink] [raw]
Subject: Re: [PATCH 2/2 v2] scsi: add scsi trace core function and put trace points

Martin K. Petersen wrote:
>>>>>> "Kei" == Kei Tokunaga <[email protected]> writes:
>
> I'm traveling so I won't have time to look at this closely until next
> week. However, this caught my eye:
>
> +static const char *
> +scsi_trace_varlen(struct trace_seq *p, unsigned char *cdb, int len)
> +{
> + switch (SERVICE_ACTION(cdb)) {
> + case READ_32:
> + case WRITE_32:
> + /* if protection is enabled */
> + if (((cdb[10] >> 5) & 0x7) == 1)
> + return scsi_trace_rw32(p, cdb, len);
> + /* fall through */
> + default:
> + return scsi_trace_misc(p, cdb, len);
> + }
> +}
>
> It is not a requirement that a 32-byte READ/WRITE request must have
> PROTECT set. So that if statement is bogus.

Yes. I agree that the if statement is not necessary here. I'll
fix it. Thanks for having your time for the review.

Kei