[PATCH 2/2] scsi: add scsi trace core function and put trace points

[Kei Tokunaga <tokunaga.keiich@jp.fujitsu.com>]

In this first attempt, trace points are put in these timings:

  - 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 exmaple:

  # 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 <xiaoguangrong@cn.fujitsu.com>
Signed-off-by: Tomohiro Kusumi <kusumi.tomohiro@jp.fujitsu.com>
Signed-off-by: Kei Tokunaga <tokunaga.keiich@jp.fujitsu.com>
---

 linux-2.6.33-rc4-trace-kei/drivers/scsi/scsi.c         |    6 
 linux-2.6.33-rc4-trace-kei/drivers/scsi/scsi_error.c   |    4 
 linux-2.6.33-rc4-trace-kei/include/trace/events/scsi.h |  328 +++++++++++++++++
 linux-2.6.33-rc4-trace-kei/kernel/trace/Makefile       |    3 
 linux-2.6.33-rc4-trace-kei/kernel/trace/scsitrace.c    |  168 ++++++++
 5 files changed, 509 insertions(+)

diff -puN kernel/trace/Makefile~scsi_trace kernel/trace/Makefile
--- linux-2.6.33-rc4-trace/kernel/trace/Makefile~scsi_trace	2010-01-18 16:23:16.000000000 +0900
+++ linux-2.6.33-rc4-trace-kei/kernel/trace/Makefile	2010-01-18 16:23:16.000000000 +0900
@@ -48,6 +48,9 @@ obj-$(CONFIG_BLK_DEV_IO_TRACE) += blktra
 ifeq ($(CONFIG_BLOCK),y)
 obj-$(CONFIG_EVENT_TRACING) += blktrace.o
 endif
+ifneq ($(CONFIG_SCSI),)
+obj-$(CONFIG_EVENT_TRACING) += scsitrace.o
+endif
 obj-$(CONFIG_EVENT_TRACING) += trace_events.o
 obj-$(CONFIG_EVENT_TRACING) += trace_export.o
 obj-$(CONFIG_FTRACE_SYSCALLS) += trace_syscalls.o
diff -puN /dev/null include/trace/events/scsi.h
--- /dev/null	2010-01-18 18:41:26.612813384 +0900
+++ linux-2.6.33-rc4-trace-kei/include/trace/events/scsi.h	2010-01-19 19:53:11.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 /dev/null kernel/trace/scsitrace.c
--- /dev/null	2010-01-18 18:41:26.612813384 +0900
+++ linux-2.6.33-rc4-trace-kei/kernel/trace/scsitrace.c	2010-01-19 18:28:40.000000000 +0900
@@ -0,0 +1,168 @@
+/*
+ * Copyright (C) 2010 FUJITSU LIMITED
+ * Copyright (C) 2010 Tomohiro Kusumi <kusumi.tomohiro@jp.fujitsu.com>
+ *
+ * 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>
+
+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, "lba=%llu txlen=%llu",
+			 (unsigned long long)lba, (unsigned long long)txlen);
+	trace_seq_putc(p, 0);
+
+	return ret;
+}
+
+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 READ_32:
+	case WRITE_32:
+		return scsi_trace_rw32(p, cdb, len);
+	default:
+		return scsi_trace_misc(p, cdb, len);
+	}
+}
+EXPORT_SYMBOL(scsi_trace_parse_cdb);
diff -puN drivers/scsi/scsi.c~scsi_trace drivers/scsi/scsi.c
--- linux-2.6.33-rc4-trace/drivers/scsi/scsi.c~scsi_trace	2010-01-18 16:23:16.000000000 +0900
+++ linux-2.6.33-rc4-trace-kei/drivers/scsi/scsi.c	2010-01-18 16:23:16.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-rc4-trace/drivers/scsi/scsi_error.c~scsi_trace	2010-01-18 16:23:16.000000000 +0900
+++ linux-2.6.33-rc4-trace-kei/drivers/scsi/scsi_error.c	2010-01-18 16:23:16.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)

_