Skip to contentSkip to conversation

scsi: ftrace based scsi tracing feature

PATCH Superseded Kei Tokunaga 1 participant 3 messages Feb 15, 2010

Subsystems (3)

v3 of 4 Superseded Latest is v4 →

lore
Share & tools
lore
#0 lore raw

v3 cover scsi: ftrace based scsi tracing feature

Hi,

This is v3 patch series of SCSI trace. Since there has been no more new feedback on v2 for about a week, I've decided to post this.

Changelog from v2:

- fixed variable length command handling (removed the assumption that READ/WRITE(32) is only called if protection is enabled.)

Here are the links to the discussions on v2:

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

    http://marc.info/?l=linux-scsi&m=126500018231317&w=2
  [PATCH 1/2 v2] scsi: add __print_hex() to ftrace
    http://marc.info/?l=linux-scsi&m=126500074718183&w=2
  [PATCH 2/2 v2] scsi: add scsi trace core function and put trace
points
    http://marc.info/?l=linux-scsi&m=126500087718320&w=2

This patchset applies to 2.6.33-rc8.

Thanks,
Kei

#1 lore raw

PATCH v3 1/2 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

---

 linux-2.6.33-rc8-trace-kei/include/linux/ftrace_event.h |    3 +++
 linux-2.6.33-rc8-trace-kei/include/trace/ftrace.h       |    3 +++
 linux-2.6.33-rc8-trace-kei/kernel/trace/trace_output.c  |   15 +++++++++++++++
 3 files changed, 21 insertions(+)
include/linux/ftrace_event.h renamed from include/linux/ftrace_event.h~ftrace_print_hex +3 -0
diff -puN include/linux/ftrace_event.h~ftrace_print_hex include/linux/ftrace_event.h
@@ -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:
include/trace/ftrace.h renamed from include/trace/ftrace.h~ftrace_print_hex +3 -0
diff -puN include/trace/ftrace.h~ftrace_print_hex include/trace/ftrace.h
@@ -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						\
kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~ftrace_print_hex +15 -0
diff -puN kernel/trace/trace_output.c~ftrace_print_hex kernel/trace/trace_output.c
@@ -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)
 {

_

#2 lore raw

PATCH v3 2/2 scsi: add scsi trace core functions and put trace points

In reply to Kei Tokunaga

Changelog from v2:

- fixed variable length command handling (removed the assumption that READ/WRITE(32) is only called if protection is enabled.)

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)

---

 linux-2.6.33-rc8-trace-kei/drivers/scsi/Makefile       |    1 
 linux-2.6.33-rc8-trace-kei/drivers/scsi/scsi.c         |    6 
 linux-2.6.33-rc8-trace-kei/drivers/scsi/scsi_error.c   |    4 
 linux-2.6.33-rc8-trace-kei/drivers/scsi/scsi_trace.c   |  186 +++++++++
 linux-2.6.33-rc8-trace-kei/include/trace/events/scsi.h |  328 +++++++++++++++++
 linux-2.6.33-rc8-trace-kei/kernel/trace/trace_output.c |    1 
 6 files changed, 526 insertions(+)
drivers/scsi/Makefile renamed from drivers/scsi/Makefile~scsi_trace +1 -0
diff -puN drivers/scsi/Makefile~scsi_trace drivers/scsi/Makefile
@@ -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
 
drivers/scsi/scsi.c renamed from drivers/scsi/scsi.c~scsi_trace +6 -0
diff -puN drivers/scsi/scsi.c~scsi_trace drivers/scsi/scsi.c
@@ -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);
 }
 
drivers/scsi/scsi_error.c renamed from drivers/scsi/scsi_error.c~scsi_trace +4 -0
diff -puN drivers/scsi/scsi_error.c~scsi_trace drivers/scsi/scsi_error.c
@@ -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)
drivers/scsi/scsi_trace.c new file +186 -0

186 lines not on this page · raw message

include/trace/events/scsi.h new file +328 -0

328 lines not on this page · raw message

kernel/trace/trace_output.c renamed from kernel/trace/trace_output.c~scsi_trace +1 -0
diff -puN kernel/trace/trace_output.c~scsi_trace kernel/trace/trace_output.c
@@ -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)
 {

_